Re: Open relay? Nonlocal recips but not originating: in my maillog

[Levente Birta]

On 29/09/2017 09:40, Levente Birta wrote:

On 29/09/2017 00:07, Patrick Ben Koetter wrote:

* Levente Birta <blevi.li...@gmail.com>:

I plan to downgrade to amavisd 2.10 to make some tests, but seems the
problem coming from version 2.11

Wait! Did you run amavis in more verbose debug mode to see how it reaches
decisions?

Any advise?
Thanks
Levi

Here is my amavisd.conf (amavisd-new 2.11) and after the log which is generated with log_level => 5 in the ORIGINATING policy bank.

Thanks in advance,
Levi


amavisd.conf:

use strict;

$max_servers = 2;            # num of pre-forked children (2..30 is common), -m $daemon_user  = 'amavis';    # (no default;  customary: vscan or amavis), -u $daemon_group = 'amavis';    # (no default;  customary: vscan or amavis), -g

$mydomain = 'localdomain.com';   # a convenient default for other settings

$MYHOME = '/var/spool/amavisd';   # a convenient default for other settings, -H

$TEMPBASE = "$MYHOME/tmp";   # working directory, needs to exist, -T

$ENV{TMPDIR} = $TEMPBASE;    # environment variable TMPDIR, used by SA, etc.

$QUARANTINEDIR = "$MYHOME/quarantine";      # -Q

$quarantine_subdir_levels = 1;  # add level of subdirs to disperse quarantine

$release_format = 'resend';     # 'attach', 'plain', 'resend'
$report_format  = 'arf';        # 'attach', 'plain', 'resend', 'arf'

$db_home   = "$MYHOME/db";        # dir for bdb nanny/cache/snmp databases, -D

$lock_file = "/var/run/amavisd/amavisd.lock";  # -L
$pid_file  = "/var/run/amavisd/amavisd.pid";   # -P

$sa_debug = 0;  #0; #'TxRep';
$log_level = 2;              # verbosity 0..5, -d
$log_recip_templ = undef;    # disable by-recipient level-0 log entries
$do_syslog = 1;              # log via syslogd (preferred)
$syslog_facility = 'mail';   # Syslog facility as a string
            # e.g.: mail, daemon, user, local0, ... local7

$enable_db = 1;              # enable use of BerkeleyDB/libdb (SNMP and nanny)

$nanny_details_level = 2;    # nanny verbosity: 1: traditional, 2: detailed
$enable_dkim_verification = 0;  # enable DKIM signatures verification

$enable_dkim_signing = 0;    # load DKIM signing code, keys defined by dkim_key

@local_domains_maps = ( [".$mydomain"] );  # list of all local domains

@mynetworks = qw( 127.0.0.0/8 );

$unix_socketname = "$MYHOME/amavisd.sock";  # amavisd-release or amavis-milter                # option(s) -p overrides $inet_socket_port and $unix_socketname

$inet_socket_bind = '127.0.0.1';

$interface_policy{'SOCK'} = 'AM.PDP-SOCK'; # only applies with $unix_socketname

$policy_bank{'AM.PDP-SOCK'} = {
   protocol => 'AM.PDP',

  auth_required_release => 0,  # do not require secret_id for amavisd-release

};

$sa_tag_level_deflt  = -999;  # add spam info headers if at, or above that level

$sa_tag2_level_deflt = 4.0;  # add 'spam detected' headers at that level

$sa_kill_level_deflt = 4.6;  # triggers spam evasive actions (e.g. blocks mail)

$sa_dsn_cutoff_level = 10;   # spam level beyond which a DSN is not sent

$sa_crediblefrom_dsn_cutoff_level = 12; # likewise, but for a likely valid From $sa_quarantine_cutoff_level = 999; # spam level beyond which quarantine is off $penpals_bonus_score = 8;    # (no effect without a @storage_sql_dsn database) $penpals_threshold_high = $sa_kill_level_deflt;  # don't waste time on hi spam $bounce_killer_score = 100;  # spam score points to add for joe-jobbed bounces

$sa_mail_body_size_limit = 400*1024; # don't waste time on SA if mail is larger $sa_local_tests_only = 0;    # only tests which do not require internet access?

$virus_admin               = 'ad...@localdomain.com'; # notifications recip.

$spam_admin = 'ad...@localdomain.com';
$banned_admin = 'ad...@localdomain.com';

$mailfrom_notify_admin     = 'amav...@localdomain.com';   # notifications sender $mailfrom_notify_recip     = 'amav...@localdomain.com';   # notifications sender $mailfrom_notify_spamadmin = 'amav...@localdomain.com';   # notifications sender $mailfrom_to_quarantine = 'amav...@localdomain.com'; # null return path; uses original sender if undef

@addr_extension_virus_maps      = ('virus');
@addr_extension_banned_maps     = ('banned');
@addr_extension_spam_maps       = ('spam');
@addr_extension_bad_header_maps = ('badh');

$path = '/usr/local/sbin:/usr/local/bin:/usr/sbin:/sbin:/usr/bin:/bin';

$MAXLEVELS = 14;
$MAXFILES = 3000;

$MIN_EXPANSION_QUOTA =      100*1024;  # bytes  (default undef, not enforced) $MAX_EXPANSION_QUOTA = 500*1024*1024;  # bytes  (default undef, not enforced)

$sa_spam_subject_tag = '***Spam*** ';
$defang_virus  = 1;  # MIME-wrap passed infected mail
$defang_banned = 1;  # MIME-wrap passed mail containing banned name
$defang_by_ccat{CC_BADH.",3"} = 1;  # NUL or CR character in header

$defang_by_ccat{CC_BADH.",5"} = 1;  # header line longer than 998 characters

$defang_by_ccat{CC_BADH.",6"} = 1;  # header field syntax error

$myhostname = 'host.localdomain.com';  # must be a fully-qualified domain name!

$notify_method  = 'smtp:[127.0.0.1]:10025';
$forward_method = 'smtp:[127.0.0.1]:10025';  # set to undef with milter!

$final_virus_destiny      = D_DISCARD;
$final_banned_destiny     = D_BOUNCE;
$final_spam_destiny       = D_DISCARD;  #!!!  D_DISCARD / D_REJECT
$final_bad_header_destiny = D_BOUNCE;

$X_HEADER_LINE = "by $myproduct_name using ClamAV & SpamAssassin @ wsrv";

@keep_decoded_original_maps = (new_RE(
   qr'^MAIL$',                # let virus scanner see full original message
   qr'^MAIL-UNDECIPHERABLE$', # same as ^MAIL$ if mail is undecipherable
   qr'^(ASCII(?! cpio)|text|uuencoded|xxencoded|binhex)'i,
));

$banned_filename_re = new_RE(

  qr'^\.(exe-ms|dll)$',                   # banned file(1) types, rudimentary   [ qr'^\.(rpm|cpio|tar)$'       => 0 ],  # allow any in Unix-type archives   qr'.\.(pif|scr)$'i,                     # banned extensions - rudimentary

   qr'^application/x-msdownload$'i,        # block these MIME types
   qr'^application/x-msdos-program$'i,
   qr'^application/hta$'i,
   # block certain double extensions in filenames

qr'^(?!cid:).*\.[^./]*[A-Za-z][^./]*\.\s*(exe|vbs|pif|scr|bat|cmd|com|cpl|dll)[.\s]*$'i,  qr'.\.(exe|vbs|pif|scr|cpl|bat|cmd|com)$'i, # banned extension - basic+cmd

  qr'.\.(ade|adp|app|bas|bat|chm|cmd|com|cpl|crt|emf|exe|fxp|grp|hlp|hta|
         inf|ini|ins|isp|js|jse|lib|lnk|mda|mdb|mde|mdt|mdw|mdz|msc|msi|

msp|mst|ocx|ops|pcd|pif|prg|reg|scr|sct|shb|shs|sys|vb|vbe|vbs|vxd|

         wmf|wsc|wsf|wsh)$'ix,                # banned extensions - long
  qr'.\.(asd|asf|asx|url|vcs|wmd|wmz)$'i,     # consider also

 qr'.\.(ani|cur|ico)$'i,                 # banned cursors and icons filename  qr'^\.ani$',                            # banned animated cursor file(1) type  qr'.\.(mim|b64|bhx|hqx|xxe|uu|uue)$'i,  # banned extension - WinZip vulnerab.

);

@score_sender_maps = ({ # a by-recipient hash lookup table,

                        # results from all matching recipient tables are summed

   ## site-wide opinions about senders (the '.' matches any recipient)
   '.' => [  # the _first_ matching sender determines the score boost

   new_RE(  # regexp-type lookup table, just happens to be all soft-blacklist     [qr'^(bulkmail|offers|cheapbenefits|earnmoney|foryou)@'i         => 5.0],     [qr'^(greatcasino|investments|lose_weight_today|market\.alert)@'i=> 5.0],     [qr'^(money2you|MyGreenCard|new\.tld\.registry|opt-out|opt-in)@'i=> 5.0],     [qr'^(optin|saveonlsmoking2002k|specialoffer|specialoffers)@'i   => 5.0],     [qr'^(stockalert|stopsnoring|wantsome|workathome|yesitsfree)@'i  => 5.0],     [qr'^(your_friend|greatoffers)@'i                                => 5.0],     [qr'^(inkjetplanet|marketopt|MakeMoney)\d*@'i                    => 5.0],

    ),

    { # a hash-type lookup table (associative array)
      'nob...@cert.org'                        => -3.0,
      'cert-advis...@us-cert.gov'              => -3.0,
      'owner-al...@iss.net'                    => -3.0,
      'slash...@slashdot.org'                  => -3.0,
      'securityfocus.com'                      => -3.0,
      'ntbugt...@listserv.ntbugtraq.com'       => -3.0,
      'security-ale...@linuxsecurity.com'      => -3.0,
      'mailman-announce-ad...@python.org'      => -3.0,
      'amavis-user-ad...@lists.sourceforge.net'=> -3.0,
      'amavis-user-boun...@lists.sourceforge.net' => -3.0,
      'spamassassin.apache.org'                => -3.0,
      'notification-ret...@lists.sophos.com'   => -3.0,
      'owner-postfix-us...@postfix.org'        => -3.0,
      'owner-postfix-annou...@postfix.org'     => -3.0,
      'owner-sendmail-annou...@lists.sendmail.org'   => -3.0,
      'sendmail-announce-requ...@lists.sendmail.org' => -3.0,
      'donotre...@sendmail.org'                => -3.0,
      'ca+envel...@sendmail.org'               => -3.0,
      'nore...@freshmeat.net'                  => -3.0,
      'owner-techn...@postel.acm.org'          => -3.0,
      'ietf-123-ow...@loki.ietf.org'           => -3.0,
      'cvs-commits-list-ad...@gnome.org'       => -3.0,
      'rt-users-ad...@lists.fsck.com'          => -3.0,
      'clp-requ...@comp.nus.edu.sg'            => -3.0,
      'surveys-err...@lists.nua.ie'            => -3.0,
      'emailn...@genomeweb.com'                => -5.0,
      'yahoo-dev-n...@yahoo-inc.com'           => -3.0,
      'returns.groups.yahoo.com'               => -3.0,
      'clustern...@linuxnetworx.com'           => -3.0,
      lc('lvs-users-ad...@linuxvirtualserver.org')    => -3.0,
      lc('owner-textbreakingn...@cnnimail12.cnn.com') => -5.0,

      # soft-blacklisting (positive score)
      'sen...@example.net'                     =>  3.0,
      '.example.net'                           =>  1.0,

    },
   ],  # end of site-wide tables
});


@decoders = (
   ['mail', \&do_mime_decode],
   ['F',    \&do_uncompress, ['unfreeze', 'freeze -d', 'melt', 'fcat'] ],
   ['Z',    \&do_uncompress, ['uncompress', 'gzip -d', 'zcat'] ],
   ['gz',   \&do_uncompress, 'gzip -d'],
   ['gz',   \&do_gunzip],
   ['bz2',  \&do_uncompress, 'bzip2 -d'],
   ['xz',   \&do_uncompress,
            ['xzdec', 'xz -dc', 'unxz -c', 'xzcat'] ],
   ['lzma', \&do_uncompress,
            ['lzmadec', 'xz -dc --format=lzma',
             'lzma -dc', 'unlzma -c', 'lzcat', 'lzmadec'] ],
   ['lrz',  \&do_uncompress,
            ['lrzip -q -k -d -o -', 'lrzcat -q -k'] ],
   ['lzo',  \&do_uncompress, 'lzop -d'],
   ['lz4',  \&do_uncompress, ['lz4c -d'] ],
   ['rpm',  \&do_uncompress, ['rpm2cpio.pl', 'rpm2cpio'] ],
   [['cpio','tar'], \&do_pax_cpio, ['pax', 'gcpio', 'cpio'] ],
            # ['/usr/local/heirloom/usr/5bin/pax', 'pax', 'gcpio', 'cpio']
   ['deb',  \&do_ar, 'ar'],
   ['rar',  \&do_unrar, ['unrar', 'rar'] ],
   ['arj',  \&do_unarj, ['unarj', 'arj'] ],
   ['arc',  \&do_arc,   ['nomarch', 'arc'] ],
   ['zoo',  \&do_zoo,   ['zoo', 'unzoo'] ],
   ['cab',  \&do_cabextract, 'cabextract'],
   ['tnef', \&do_tnef],
   [['zip','kmz'], \&do_7zip,  ['7za', '7z'] ],
   [['zip','kmz'], \&do_unzip],
   ['7z',   \&do_7zip,  ['7zr', '7za', '7z'] ],
   [[qw(gz bz2 Z tar)],
            \&do_7zip,  ['7za', '7z'] ],
   [[qw(xz lzma jar cpio arj rar swf lha iso cab deb rpm)],
            \&do_7zip,  '7z' ],
   ['exe',  \&do_executable, ['unrar','rar'], 'lha', ['unarj','arj'] ],
);


@av_scanners = (

   ### http://www.clamav.net/
   ['ClamAV-clamd',
     \&ask_daemon, ["CONTSCAN {}\n", "/var/run/clamd.amavisd/clamd.sock"],
     qr/\bOK$/m, qr/\bFOUND$/m,
     qr/^.*?: (?!Infected Archive)(.*) FOUND$/m ],

  # NOTE: run clamd under the same user as amavisd - or run it under its own   #   uid such as clamav, add user clamav to the amavis group, and then add

   #   AllowSupplementaryGroups to clamd.conf;

  # NOTE: match socket name (LocalSocket) in clamav.conf to the socket name in   #   this entry; when running chrooted one may prefer a socket under $MYHOME.

);


@av_scanners_backup = (

   ### http://www.clamav.net/   - backs up clamd or Mail::ClamAV
   ['ClamAV-clamscan', 'clamscan',
     "--stdout --no-summary -r --tempdir=$TEMPBASE {}",
     [0], qr/:.*\sFOUND$/m, qr/^.*?: (?!Infected Archive)(.*) FOUND$/m ],
);

@bypass_virus_checks_maps = (

   \%bypass_virus_checks, \@bypass_virus_checks_acl, \$bypass_virus_checks_re);

@bypass_spam_checks_maps = (

   \%bypass_spam_checks, \@bypass_spam_checks_acl, \$bypass_spam_checks_re);

@lookup_sql_dsn =

   ( ['DBI:mysql:database=db;mysql_socket=/var/lib/mysql/mysql.sock;port=3306', 'user', 'pass'] );

$sql_select_policy =
    'SELECT *,spamfilter_users.id'.

   ' FROM spamfilter_users LEFT JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id'.    ' WHERE spamfilter_users.email IN (%k) ORDER BY spamfilter_users.priority DESC';

$sql_select_white_black_list = 'SELECT wb FROM spamfilter_wblist'.

    ' WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (%k)) AND (spamfilter_wblist.active="y")' .

     ' ORDER BY spamfilter_wblist.priority DESC';

$originating = 0;

$inet_socket_port = [10024,10026];   # listen on this local TCP port(s)

$interface_policy{'10026'} = 'ORIGINATING';

$policy_bank{'ORIGINATING'} = {  # mail supposedly originating from our users

   originating => 1,  # declare that mail was submitted by our smtp client
   #log_level => 5,
   allow_disclaimers => 1,  # enables disclaimer insertion if available
   # notify administrator of locally originating malware
   virus_admin_maps => ["admin\@localdomain.com"],
   spam_admin_maps  => ["admin\@localdomain.com"],
   warnbadhsender   => 1,
   # forward to a smtpd service providing DKIM signing service
   forward_method => 'smtp:[127.0.0.1]:10025',
   # force MTA conversion to 7-bit (e.g. before DKIM signing)
   smtpd_discard_ehlo_keywords => ['8BITMIME'],

  bypass_banned_checks_maps => [1],  # allow sending any file names and types   terminate_dsn_on_notify_success => 0,  # don't remove NOTIFY=SUCCESS option

   syslog_ident => 'amavis/authenticated',
};


$final_virus_destiny      = D_DISCARD;
$final_banned_destiny     = D_DISCARD;
$final_spam_destiny       = D_DISCARD;  #!!!  D_DISCARD / D_REJECT
$final_bad_header_destiny = D_PASS;
$bad_header_quarantine_to = undef;


$banned_files_quarantine_method = 'local:banned-%m';
$spam_quarantine_method         = 'local:spam-%m';
$bad_header_quarantine_method   = 'local:badh-%m';
$virus_quarantine_method         = 'local:virus-%m';

$spam_quarantine_to = 'spam-quarantine';
$banned_quarantine_to = 'banned-quarantine';
$bad_header_quarantine_to= 'bad-header-quarantine';
$virus_quarantine_to = 'virus-quarantine';

$allowed_added_header_fields{lc('Received')} = 0;


@virus_name_to_spam_score_maps =
     (new_RE(  # the order matters!
         [ qr`^Structured\.(SSN|CreditCardNumber)\b`            => 0.1 ],
         [ qr`^(Heuristics\.)?Phishing\.`                       => 0.1 ],
         [ qr`’^(Email|HTML)\.Phishing\.(?!.*Sanesecurity)`      => 0.1 ],

        [ qr`^Sanesecurity\.(Malware|Badmacro|Foxhole|Rogue|Trojan)\.` => undef ],# keep as infected

         [ qr`^Sanesecurity\.Blurl\.`                           => 1.5 ],
         [ qr`^Sanesecurity\.`                                  => 0.1 ],
         [ qr`^Sanesecurity.TestSig_`                           => 0   ],
         [ qr`^Email\.Spam\.Bounce(\.[^., ]*)*\.Sanesecurity\.` => 0   ],

        [ qr`^BofhlandMW\.`                                    => undef ],# keep as infected         [ qr`^Bofhland\.Malware\.`                             => undef ],# keep as infected

         [ qr`^Bofhland\.`                                      => 0.1 ],

        [ qr`^winnow.malware\.`                                => undef ],# keep as infected

         [ qr`^winnow\_`                                        => 0.1 ],
         [ qr`^PhishTank\.Phishing\.`                           => 0.1 ],

        [ qr`^Porcupine\.Malware\.`                            => undef ],# keep as infected

         [ qr`^Porcupine\.`                                     => 0.1 ],
         [ qr`^Email\.Spammail\b`                               => 0.1 ],
         [ qr`^Safebrowsing\.`                                  => 0.1 ],
         [ qr`^winnow\.(phish|spam)\.`                          => 0.1 ],
         [ qr`^ScamNailer\.`                                    => 0.1 ],
         [ qr`SecuriteInfo\.com\.Spam\-720`                     => 1.5 ],
   ));


1;  # insure a defined return value



MAILLOG:

Sep 29 09:13:29 localhost postfix/submission/smtpd[47434]: connect from unknown[ss.ss.ss.ss] Sep 29 09:13:29 localhost postfix/submission/smtpd[47434]: Anonymous TLS connection established from unknown[ss.ss.ss.ss]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits) Sep 29 09:13:29 localhost postfix/submission/smtpd[47434]: 3y3Lpd5Qtgz52wQSv: client=unknown[ss.ss.ss.ss], sasl_method=PLAIN, sasl_username=sen...@localdomain.com Sep 29 09:13:29 localhost postfix/cleanup[47168]: 3y3Lpd5Qtgz52wQSv: message-id=<0789fa21-18f8-f756-3d08-93dca692e...@localdomain.com> Sep 29 09:13:29 localhost opendkim[15137]: 3y3Lpd5Qtgz52wQSv: DKIM-Signature field added (s=20170927, d=localdomain.com) Sep 29 09:13:30 localhost postfix/qmgr[43061]: 3y3Lpd5Qtgz52wQSv: from=<sen...@localdomain.com>, size=670, nrcpt=1 (queue active) Sep 29 09:13:30 localhost amavis/authenticated[47891]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1 Sep 29 09:13:30 localhost amavis/authenticated[47891]: process_request: fileno sock=16, STDIN=0, STDOUT=1 Sep 29 09:13:30 localhost amavis/authenticated[47891]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: process_request: suggested_protocol="" on a TCP socket Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 4: was busy, 3.3 ms, total idle 0.000 s, busy 0.003 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) smtp readline: read 30 bytes, new size: 30 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.003 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) SMTP< LHLO host.localdomain.com\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP LHLO) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP LHLO): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-[127.0.0.1] Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-VRFY Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-PIPELINING Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-SIZE Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-ENHANCEDSTATUSCODES Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250-DSN Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 0.7 ms, total idle 0.000 s, busy 0.004 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) smtp readline: read 227 bytes, new size: 227 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.004 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< XFORWARD ADDR=ss.ss.ss.ss PORT=14585\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 2.5.0 Ok XFORWARD Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 0.4 ms, total idle 0.000 s, busy 0.004 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.004 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< XFORWARD PROTO=ESMTP HELO=[192.168.1.64] IDENT=3y3Lpd5Qtgz52wQSv SOURCE=REMOTE\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 2.5.0 Ok XFORWARD Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 0.3 ms, total idle 0.000 s, busy 0.005 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.005 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< MAIL FROM:<sen...@localdomain.com>\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) check_mail_begin_task: task_count=1 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) TempDir::prepare_dir: created directory /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) TempDir::prepare_file: creating file /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/email.txt Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) TempDir::prepare_file: layers: unix,perlio Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="ss.ss.ss.ss", no match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [debug_sender] => undef, "sen...@localdomain.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 2.1.0 Sender <sen...@localdomain.com> OK Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 1.9 ms, total idle 0.000 s, busy 0.006 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.0 ms, total idle 0.000 s, busy 0.006 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< RCPT TO:<recipi...@gmail.com> ORCPT=rfc822;recipi...@gmail.com\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup => undef, "recipi...@gmail.com", no lookup tables Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_acl(recipi...@gmail.com), no match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [local_domains] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) query_keys: recipi...@gmail.com, @gmail.com, @.gmail.com, @.com, @. Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql sel_policy "recipi...@gmail.com", query args: [recipi...@gmail.com,12], [@gmail.com,12], [@.gmail.com,12], [@.com,12], [@.,12] Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql select: SELECT *,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority DESC Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) sql begin, nontransaction Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Connecting to SQL database server Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) connect_to_sql: trying 'DBI:mysql:database=dbispconfig;mysql_socket=/var/lib/mysql/mysql.sock;port=3306' Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) connect_to_sql: 'DBI:mysql:database=dbispconfig;mysql_socket=/var/lib/mysql/mysql.sock;port=3306' succeeded Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) sql: preparing and executing (5 args): SELECT *,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority DESC Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql, "recipi...@gmail.com" no match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(message_size_limit), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [message_size_limit] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 2.1.5 Recipient <recipi...@gmail.com> OK Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 4.3 ms, total idle 0.000 s, busy 0.011 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.011 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< DATA\r\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP :10026 /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj: <sen...@localdomain.com> -> <recipi...@gmail.com> Received: from host.localdomain.com ([127.0.0.1]) by localhost (host.localdomain.com [127.0.0.1]) (amavisd-new, port 10026) with LMTP for <recipi...@gmail.com>; Fri, 29 Sep 2017 09:13:30 +0300 (EEST) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP> 354 End data with <CR><LF>.<CR><LF> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, receiving data Sep 29 09:13:30 localhost postfix/submission/smtpd[47434]: disconnect from unknown[ss.ss.ss.ss] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) smtp copy: read 1530 bytes into buffer, new size: 1530 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) smtp copy: 6 bytes still buffered at end Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP< .<CR><LF> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) message size set to 1521 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_body_digest: reading header section from memory Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_body_digest: reading mail body from memory, 0 DKIM signatures Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_body_digest: message size 1521, header+sep 1519, body 2 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) body type (8bit-MIMEtransport): unlabeled, good (h=0, b=0) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) body hash: 68b329da9893e34099c7d8ad5cb9c940 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) ip_from_received: ss.ss.ss.ss Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_ip_acl (public_nets) arr.obj: key="ss.ss.ss.ss" matches "::ffff:0:0/96", result=1 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) trace: LMTP://[127.0.0.1]:46452 < ESMTPSA://[ss.ss.ss.ss]:14585 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Original mail size: 1521; quota set to: 760500 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Checking: K_6H-Jewi-oP ORIGINATING [ss.ss.ss.ss] <sen...@localdomain.com> -> <recipi...@gmail.com> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) 2822.From: <sen...@localdomain.com> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(local), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_acl(recipi...@gmail.com), no match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [local_domains] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(bypass_virus_checks), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [bypass_virus_checks] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="1" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup => true,  "recipi...@gmail.com" matches, result="1", matching_key="(constant:1)" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(bypass_spam_checks), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [bypass_spam_checks] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(id), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [users.id] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(policy_id), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [users.policy_id] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Open relay? Nonlocal recips but not originating: recipi...@gmail.com Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Extracting mime components from a string Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Issued a new file name: p001 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Charging 1 bytes to remaining quota 760500 (out of 760500, (0%)) - by mime_decode Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) p001 1 Content-Type: text/plain, 7bit, size: 1, SHA1 digest: adc83b19e793491b1c6ea0fd8b46cd9f32e592fc Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) inspect_dsn: parts: text/plain Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) inspect_dsn: not a bounce Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline dsn_parse - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer dsn_parse: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) decode_parts: level=1, #parts=1 : p001 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) running file(1) on 1 files, arglist size 18 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_command: [47910] /usr/bin/file p001 </dev/null 2>&1 Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: target fd0 closing, to become < /dev/null Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: target fd1 closing, to become (65) &=20 Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20 Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: source fd20 closed Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: target fd2 closing, to become (65) &1 Sep 29 09:13:30 localhost amavis/authenticated[47910]: (47891-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) result line from file(1): p001: very short file (no magic)\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_re("very short file (no magic)") matches key "(?^:^)", result="dat" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [map_full_type_to_short_type] => true,  "very short file (no magic)" matches, result="dat", matching_key="(?^:^)" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) File-type of p001: very short file (no magic); (dat) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) decompose_part: p001 - atomic Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(bypass_header_checks), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [bypass_header_checks] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) check_header: 0, OK Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(bypass_header_checks), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [bypass_header_checks] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Checking for banned types and filenames Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) skipping banned check: all recipients bypass banned checks Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) banned check: any=0, all=Y (1) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_re("MAIL") matches key "(?^:^MAIL$)", result="1" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [keep_decoded_original] => true,  "MAIL" matches, result="1", matching_key="(?^:^MAIL$)" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Issued a new file name: p002 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) presenting full original message to scanners as /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts/p002 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Calling virus scanners, 2 files to scan in /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) invoking av-scanner ClamAV-clamd Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamd.amavisd/clamd.sock Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline run_av_pre - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline run_av_scan - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer run_av_scan: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) ClamAV-clamd: Connecting to socket  /var/run/clamd.amavisd/clamd.sock Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) new socket by IO::Socket::UNIX to /var/run/clamd.amavisd/clamd.sock, timeout set to 10 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) connected to /var/run/clamd.amavisd/clamd.sock successfully Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) ClamAV-clamd: Sending CONTSCAN /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts\n to socket /var/run/clamd.amavisd/clamd.sock Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=1, wr=1, timeout=10 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: sending 76 chars Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop sent 76> CONTSCAN /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999 Sep 29 09:13:30 localhost clamd[2084]: /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts/p002: OK Sep 29 09:13:30 localhost clamd[2084]: /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts/p001: OK Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 71 chars< /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts: OK\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999 Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) rw_loop read: got eof Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline ask_daemon_internal - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline run_av_3 - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer run_av_3: timer 288, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_av (ClamAV-clamd) result: /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts: OK\n Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_av (ClamAV-clamd): CLEAN Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) run_av (ClamAV-clamd) result: clean Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) wbl: checking sender <sen...@localdomain.com> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) wbl: (SQL) recip <recipi...@gmail.com>, 0 matches Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [blacklist_recip<recipi...@gmail.com>] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [blacklist_sender<sen...@localdomain.com>,blacklist_sender] => undef, "sen...@localdomain.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [whitelist_recip<recipi...@gmail.com>] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [whitelist_sender<sen...@localdomain.com>,whitelist_sender] => undef, "sen...@localdomain.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) query_keys: recipi...@gmail.com, recipient@, gmail.com, .gmail.com, .com, . Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_hash(recipi...@gmail.com) matches keys: "."=>ARRAY(0x229c980) Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [score_recip<recipi...@gmail.com>,score_sender], 1 matches for "recipi...@gmail.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x229bf60),{amavis-user-ad...@lists.sourceforge.net=>"-3",owner-postfix-annou...@postfix.org=>"-3",ntbugt...@listserv.ntbugtraq.com=>"-3",donotre...@sendmail.org=>"-3",slash...@slashdot.org=>"-3",clp-requ...@comp.nus.edu.sg=>"-3",nob...@cert.org=>"-3",security-ale...@linuxsecurity.com=>"-3",cvs-commits-list-ad...@gnome.org=>"-3",amavis-user-boun...@lists.sourceforge.net=>"-3",notification-ret...@lists.sophos.com=>"-3",mailman-announce-ad...@python.org=>"-3",emailn...@genomeweb.com=>"-5",owner-textbreakingn...@cnnimail12.cnn.com=>"-5",ca+envel...@sendmail.org=>"-3",cert-advis...@us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-us...@postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-n...@yahoo-inc.com=>"-3",owner-al...@iss.net=>"-3",sendmail-announce-requ...@lists.sendmail.org=>"-3",surveys-e... Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) ...rr...@lists.nua.ie=>"-3",spamassassin.apache.org=>"-3",lvs-users-ad...@linuxvirtualserver.org=>"-3",sen...@example.net=>"3",owner-sendmail-annou...@lists.sendmail.org=>"-3",nore...@freshmeat.net=>"-3",ietf-123-ow...@loki.ietf.org=>"-3",clustern...@linuxnetworx.com=>"-3",owner-techn...@postel.acm.org=>"-3",rt-users-ad...@lists.fsck.com=>"-3"}] Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_re("sen...@localdomain.com"), no matches Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) query_keys: sen...@localdomain.com, sender@, localdomain.com, .localdomain.com, .com, . Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_hash(sen...@localdomain.com), no matches Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [score_sender<sen...@localdomain.com>] => undef, "sen...@localdomain.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) SpamControl: calling spam scanner SpamAssassin Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline spam_scan_sa_pre - deadline in 480.0 s, set to 476.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 480.0 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(sa_userconf), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [sa_userconf] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(sa_username), "recipi...@gmail.com" no matching records Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup [sa_username] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) SA user config: "", username: "amavis", 0, (0)recipi...@gmail.com Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) calling SA parse (0), SA vers 4.0.0-r1694545, 4.000000, data as STRING_REF, recips_ind [0], user: "amavis" Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) get_deadline SA check - deadline in 480.0 s, set to 475.000 s Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) mimepart digest: adc83b19e793491b1c6ea0fd8b46cd9f32e592fc:text/plain Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) CALLING SA check (0) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) DONE SA check (0) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline spam_scan_sa - deadline in 478.9 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer spam_scan_sa: timer 288, was 475, deadline in 478.9 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) spam_scan: score=-8.944 autolearn=ham autolearn_force=no tests=[ALL_TRUSTED=-1,BAYES_00=-1.9,DKIM_SIGNED=1,DKIM_VALID=-1.5,DKIM_VALID_AU=-1,TXREP=-4.544] recips=0 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline spam_scan - deadline in 478.9 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer spam_scan: timer 288, was 288, deadline in 478.9 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_tag_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="-999" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_tag_level] => true,  "recipi...@gmail.com" matches, result="-999", matching_key="(constant:-999)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_tag2_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="4" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_tag2_level] => true,  "recipi...@gmail.com" matches, result="4", matching_key="(constant:4)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_tag3_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_tag3_level] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_kill_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="4.6" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_kill_level] => true,  "recipi...@gmail.com" matches, result="4.6", matching_key="(constant:4.6)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(message_size_limit), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [message_size_limit] => undef, "recipi...@gmail.com" does not match Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) final_destiny (ccat=0) is PASS, recip recipi...@gmail.com Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) final_destiny PASS, recip recipi...@gmail.com Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth= Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) do_notify_and_quarantine: not quarantining, q_method off Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) skip admin notification, no administrators Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) do_notify_and_quarantine - done Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(forward_method), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [forward_method] => true,  "recipi...@gmail.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) delivery method is 1, recips: recipi...@gmail.com Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_tag_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="-999" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_tag_level] => true,  "recipi...@gmail.com" matches, result="-999", matching_key="(constant:-999)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup_sql_field(spam_tag2_level), "recipi...@gmail.com" no matching records Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="4" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_tag2_level] => true,  "recipi...@gmail.com" matches, result="4", matching_key="(constant:4)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) headers CLUSTERING: NEW CLUSTER <recipi...@gmail.com>: score=-8.944, tag=1, tag2=0, local=0, bl=, s=, mangle= Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) header encoded (all-ASCII): X-Virus-Scanned: by amavisd-new using ClamAV & SpamAssassin @ wsrv Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) header: X-Virus-Scanned: by amavisd-new using ClamAV & SpamAssassin @ wsrv\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) headers CLUSTERING: done all 1 recips in one go Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) about to connect to smtp:[127.0.0.1]:10025, K_6H-Jewi-oP FWD from <sen...@localdomain.com> -> <recipi...@gmail.com> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline fwd_init - deadline in 478.9 s, set to 479.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp session: setting up a new session Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) establish_or_refresh, state: down Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) connected to [127.0.0.1]:10025 successfully Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=0, timeout=35 Sep 29 09:13:31 localhost postfix/smtpd[47916]: connect from localhost[127.0.0.1] Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 43 chars< 220 host.localdomain.com ESMTP Postfix\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp greeting: 220 host.localdomain.com ESMTP Postfix, dt: 7.0 ms Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp cmd> EHLO localhost Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=1, wr=1, timeout=300 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: sending 16 chars Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop sent 16> EHLO localhost\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=0, timeout=300 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 310 chars< 250-host.localdomain.com\r\n250-PIPELINING\r\n250-SIZE\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH PLAIN LOGIN\r\n250-AUTH=PLAIN LOGIN\r\n250-XCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT LOGIN DESTADDR DESTPORT\r\n250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to EHLO: 250 host.localdomain.com\nPIPELINING\nSIZE\nVRFY\nETRN\nSTARTTLS\nAUTH PLAIN LOGIN\nAUTH=PLAIN LOGIN\nXCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT LOGIN DESTADDR DESTPORT\nXFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) tls active=0, capable=1, sec_level=0 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) Remote host presents itself as: host.localdomain.com, handles DSN, PIPELINING, 8BITMIME Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp cmd> XFORWARD ADDR=ss.ss.ss.ss PORT=14585 PROTO=ESMTP HELO=[192.168.1.64] SOURCE=REMOTE IDENT=3y3Lpd5Qtgz52wQSv Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=1, wr=1, timeout=300 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: sending 109 chars Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop sent 109> XFORWARD ADDR=ss.ss.ss.ss PORT=14585 PROTO=ESMTP HELO=[192.168.1.64] SOURCE=REMOTE IDENT=3y3Lpd5Qtgz52wQSv\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=0, timeout=300 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 14 chars< 250 2.0.0 Ok\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to XFORWARD: 250 2.0.0 Ok Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) AUTH not needed, user='', MTA offers 'PLAIN LOGIN' Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp cmd> MAIL FROM:<sen...@localdomain.com> BODY=7BIT Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) orcpt_encode rfc822, recipi...@gmail.com, encode_for_smtp Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp cmd> RCPT TO:<recipi...@gmail.com> ORCPT=rfc822;recipi...@gmail.com Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp cmd> DATA Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=0, flush=1, wr=1, timeout=120 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: sending 118 chars Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop sent 118> MAIL FROM:<sen...@localdomain.com> BODY=7BIT\r\nRCPT TO:<recipi...@gmail.com> ORCPT=rfc822;recipi...@gmail.com\r\nDATA\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=0, timeout=300 Sep 29 09:13:31 localhost postfix/smtpd[47916]: 3y3Lpg1Kcwz531TZS: client=localhost[127.0.0.1], orig_queue_id=3y3Lpd5Qtgz52wQSv, orig_client=unknown[ss.ss.ss.ss] Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to MAIL (pip): 250 2.1.0 Ok Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to RCPT (pip) (<recipi...@gmail.com>): 250 2.1.5 Ok Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x632de98) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=1, timeout=478.989 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: sending 1592 chars Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop sent 1592> X-Virus-Scanned: by amavisd-new using ClamAV & SpamAssassin @ wsrv\r\nReceived: from [192.168.1.64] (unknown [ss.ss.ss.ss])\r\n\tby host.localdomain.com (Postfix) with ESMTPSA id 3y3Lpd5Qtgz52wQSv\r\n\tfo [...] Sep 29 09:13:31 localhost postfix/cleanup[47583]: 3y3Lpg1Kcwz531TZS: message-id=<0789fa21-18f8-f756-3d08-93dca692e...@localdomain.com> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: needline=1, flush=0, wr=0, timeout=478.989 Sep 29 09:13:31 localhost postfix/qmgr[43061]: 3y3Lpg1Kcwz531TZS: from=<sen...@localdomain.com>, size=1814, nrcpt=1 (queue active) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop: receiving Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rw_loop read 43 chars< 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp resp to data-dot (<recipi...@gmail.com>): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS, dt: 41.7 ms Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) Amavis::Out::SMTP::Session close, keeping connection Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline fwd-end-chkpnt - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) K_6H-Jewi-oP FWD from <sen...@localdomain.com> -> <recipi...@gmail.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline forwarding - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer forwarding: timer 288, was 288, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) DSN: sender NOT credible, SA: -8.944, <sen...@localdomain.com> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup: (scalar) matches, result="10" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup [spam_dsn_cutoff_level_bysender] => true,  "sen...@localdomain.com" matches, result="10", matching_key="(constant:10)" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) dsn: from MTA 250 NonBlocking:CleanTag <sen...@localdomain.com> -> <recipi...@gmail.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <sen...@localdomain.com> -> <recipi...@gmail.com> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) delivery_status_notification: notif 0 bytes, suppressed: no Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) one_response_for_all, per_recip_capable: Y, suppressed: N Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) one_response_for_all <sen...@localdomain.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS' Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline delivery-notification - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer delivery-notification: timer 288, was 288, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedOpenRelay} Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline snmp-counters - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer snmp-counters: timer 288, was 288, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) orcpt_encode rfc822, recipi...@gmail.com, smtputf8 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) oldest_public_ip_addr_from_received: ss.ss.ss.ss Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) Passed CLEAN {RelayedOpenRelay}, ORIGINATING [ss.ss.ss.ss]:14585 [ss.ss.ss.ss] <sen...@localdomain.com> -> <recipi...@gmail.com>, Queue-ID: 3y3Lpd5Qtgz52wQSv, Message-ID: <0789fa21-18f8-f756-3d08-93dca692e...@localdomain.com>, mail_id: K_6H-Jewi-oP, Hits: -8.944, size: 1521, queued_as: 3y3Lpg1Kcwz531TZS, 1227 ms Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline main_log_entry - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer main_log_entry: timer 288, was 288, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) TIMING-SA total 1070 ms - parse: 0.80 (0.1%), extract_message_metadata: 2.00 (0.2%), get_uri_detail_list: 0.13 (0.0%), tests_pri_-1000: 2.7 (0.3%), tests_pri_-950: 0.87 (0.1%), tests_pri_-900: 0.65 (0.1%), tests_pri_-400: 7 (0.7%), check_bayes: 7 (0.6%), b_tokenize: 2.2 (0.2%), b_tok_get_all: 1.38 (0.1%), b_comp_prob: 1.36 (0.1%), b_tok_touch_all: 0.10 (0.0%), b_finish: 0.39 (0.0%), tests_pri_0: 767 (71.7%), check_spf: 0.24 (0.0%), check_dkim_signature: 5 (0.5%), check_razor2: 722 (67.5%), check_pyzor: 24 (2.2%), tests_pri_500: 1.87 (0.2%), tests_pri_1000: 88 (8.2%), total_txrep: 152 (14.2%), check_txrep_msg_id: 1.68 (0.2%), update_txrep_msg_id: 15 (1.4%), check_txrep_email_ip: 0.67 (0.1%), update_txrep_email_ip: 15 (1.4%), check_txrep_domain: 0.63 (0.1%), update_txrep_domain: 15 (1.4%), check_txrep_helo: 0.60 (0.1%), update_txrep_helo: 15 (1.4%), check_txrep_ip: 0.51 (0.0%), update_txrep_ip: 15 (1.4%), learn: 191 (17.8%), b_learn: 125 (11.7%), b_count... Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) ..._change: 3.7 (0.3%), get_report: 0.23 (0.0%) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) updating snmp variables in BDB Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline check done - deadline in 478.8 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer check done: timer 288, was 288, deadline in 478.8 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) LMTP response for <recipi...@gmail.com>: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS" Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) LMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:31 localhost amavis-inject/lmtp[47169]: 3y3Lpd5Qtgz52wQSv: to=<recipi...@gmail.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=1.5, delays=0.26/0/0/1.2, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3y3Lpg1Kcwz531TZS) Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) TempDir::strip: /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20170929T091330-47891-19JauTSj/parts, excl=1 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) size: 1521, TIMING [total 1230 ms] - sql-prepare: 2.1 (0%)0, SMTP greeting: 1.2 (0%)0, SMTP LHLO: 0.8 (0%)0, SMTP pre-MAIL: 1.0 (0%)0, mkdir tempdir: 0.8 (0%)0, create email.txt: 0.2 (0%)0, SMTP MAIL: 0.6 (0%)1, sql-connect: 3.7 (0%)1, lookup_sql: 0.6 (0%)1, SMTP pre-DATA-flush: 1.0 (0%)1, SMTP DATA: 33 (3%)4, check_init: 0.4 (0%)4, digest_hdr: 0.5 (0%)4, digest_body: 0.3 (0%)4, collect_info: 1.2 (0%)4, mkdir parts: 1.3 (0%)4, mime_decode: 29 (2%)6, get-file-type1: 6 (1%)7, parts_decode: 0.1 (0%)7, check_header: 0.6 (0%)7, AV-scan-1: 7 (1%)7, spam-wb-list: 1.3 (0%)8, SA msg read: 0.5 (0%)8, SA parse: 1.6 (0%)8, SA check: 1068 (87%)95, decide_mail_destiny: 3.7 (0%)95, notif-quar: 0.3 (0%)95, fwd-connect: 10 (1%)96, fwd-xforward: 0.6 (0%)96, fwd-mail-pip: 1.7 (0%)96, fwd-rcpt-pip: 0.2 (0%)96, fwd-data-chkpnt: 0.0 (0%)96, write-header: 0.4 (0%)96, fwd-data-contents: 0.0 (0%)96, fwd-end-chkpnt: 42 (3%)99, prepare-dsn: 1.0 (0%)99, report: 1.2 (0%)100, main_... Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) ...log_entry: 2.9 (0%)100, update_snmp: 1.2 (0%)100, SMTP pre-response: 0.2 (0%)100, SMTP response: 0.2 (0%)100, unlink-2-files: 0.2 (0%)100, rundown: 0.3 (0%)100 Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 6: was busy, 1218.6 ms, total idle 0.000 s, busy 1.229 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 1.229 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) LMTP< QUIT\r\n Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) LMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) switch_to_client_time 480 s, smtp response sent Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) SMTP session over, timer stopped Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) extra modules loaded: Mail/SpamAssassin/SQLBasedAddrList.pm Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) exiting process_request Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) idle_proc, bye: was busy, 1.7 ms, total idle 0.001 s, busy 1.231 s Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) load: 100 %, total idle 0.001 s, busy 1.231 s

Sep 29 09:13:31 localhost postfix/qmgr[43061]: 3y3Lpd5Qtgz52wQSv: removed

Sep 29 09:13:34 localhost postfix/smtp[47175]: Untrusted TLS connection established to gmail-smtp-in.l.google.com[108.177.98.27]:25: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits) Sep 29 09:13:37 localhost postfix/smtp[47175]: 3y3Lpg1Kcwz531TZS: to=<recipi...@gmail.com>, relay=gmail-smtp-in.l.google.com[108.177.98.27]:25, delay=5.9, delays=0.04/0/3.8/2.1, dsn=2.0.0, status=sent (250 2.0.0 OK 1506665616 y186si2739895pgb.520 - gsmtp)

Sep 29 09:13:37 localhost postfix/qmgr[43061]: 3y3Lpg1Kcwz531TZS: removed