Open relay? Nonlocal recips but not originating: in my maillog
Levente Birta
blevi.linux at gmail.com
Tue Oct 3 13:10:13 CEST 2017
On 29/09/2017 09:40, Levente Birta wrote:
>
>
> On 29/09/2017 00:07, Patrick Ben Koetter wrote:
>> * Levente Birta <blevi.linux at 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 = 'admin at localdomain.com'; # notifications
> recip.
> $spam_admin = 'admin at localdomain.com';
> $banned_admin = 'admin at localdomain.com';
>
> $mailfrom_notify_admin = 'amavisd at localdomain.com'; #
> notifications sender
> $mailfrom_notify_recip = 'amavisd at localdomain.com'; #
> notifications sender
> $mailfrom_notify_spamadmin = 'amavisd at localdomain.com'; #
> notifications sender
> $mailfrom_to_quarantine = 'amavisd at 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)
> 'nobody at cert.org' => -3.0,
> 'cert-advisory at us-cert.gov' => -3.0,
> 'owner-alert at iss.net' => -3.0,
> 'slashdot at slashdot.org' => -3.0,
> 'securityfocus.com' => -3.0,
> 'ntbugtraq at listserv.ntbugtraq.com' => -3.0,
> 'security-alerts at linuxsecurity.com' => -3.0,
> 'mailman-announce-admin at python.org' => -3.0,
> 'amavis-user-admin at lists.sourceforge.net'=> -3.0,
> 'amavis-user-bounces at lists.sourceforge.net' => -3.0,
> 'spamassassin.apache.org' => -3.0,
> 'notification-return at lists.sophos.com' => -3.0,
> 'owner-postfix-users at postfix.org' => -3.0,
> 'owner-postfix-announce at postfix.org' => -3.0,
> 'owner-sendmail-announce at lists.sendmail.org' => -3.0,
> 'sendmail-announce-request at lists.sendmail.org' => -3.0,
> 'donotreply at sendmail.org' => -3.0,
> 'ca+envelope at sendmail.org' => -3.0,
> 'noreply at freshmeat.net' => -3.0,
> 'owner-technews at postel.acm.org' => -3.0,
> 'ietf-123-owner at loki.ietf.org' => -3.0,
> 'cvs-commits-list-admin at gnome.org' => -3.0,
> 'rt-users-admin at lists.fsck.com' => -3.0,
> 'clp-request at comp.nus.edu.sg' => -3.0,
> 'surveys-errors at lists.nua.ie' => -3.0,
> 'emailnews at genomeweb.com' => -5.0,
> 'yahoo-dev-null at yahoo-inc.com' => -3.0,
> 'returns.groups.yahoo.com' => -3.0,
> 'clusternews at linuxnetworx.com' => -3.0,
> lc('lvs-users-admin at LinuxVirtualServer.org') => -3.0,
> lc('owner-textbreakingnews at CNNIMAIL12.CNN.COM') => -5.0,
>
> # soft-blacklisting (positive score)
> 'sender at 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=sender at localdomain.com
> Sep 29 09:13:29 localhost postfix/cleanup[47168]: 3y3Lpd5Qtgz52wQSv:
> message-id=<0789fa21-18f8-f756-3d08-93dca692ed64 at 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=<sender at 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:<sender at 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, "sender at localdomain.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP>
> 250 2.1.0 Sender <sender at 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:<recipient at gmail.com> ORCPT=rfc822;recipient at 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, "recipient at gmail.com", no lookup tables
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_acl(recipient at gmail.com), no match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [local_domains] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> query_keys: recipient at gmail.com, @gmail.com, @.gmail.com, @.com, @.
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql sel_policy "recipient at gmail.com", query args:
> [recipient at 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, "recipient at gmail.com" no match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(message_size_limit), "recipient at gmail.com" no matching
> records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [message_size_limit] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) LMTP>
> 250 2.1.5 Recipient <recipient at 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:
> <sender at localdomain.com> -> <recipient at 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
> <recipient at 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]
> <sender at localdomain.com> -> <recipient at gmail.com>
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> 2822.From: <sender at localdomain.com>
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(local), "recipient at gmail.com" no matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_acl(recipient at gmail.com), no match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [local_domains] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(bypass_virus_checks), "recipient at gmail.com" no matching
> records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [bypass_virus_checks] => undef, "recipient at 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, "recipient at 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), "recipient at gmail.com" no matching
> records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [bypass_spam_checks] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(id), "recipient at gmail.com" no matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [users.id] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(policy_id), "recipient at gmail.com" no matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [users.policy_id] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) Open
> relay? Nonlocal recips but not originating: recipient at 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), "recipient at gmail.com" no
> matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [bypass_header_checks] => undef, "recipient at 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), "recipient at gmail.com" no
> matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [bypass_header_checks] => undef, "recipient at 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 <sender at localdomain.com>
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) wbl:
> (SQL) recip <recipient at gmail.com>, 0 matches
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [blacklist_recip<recipient at gmail.com>] => undef, "recipient at gmail.com"
> does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [blacklist_sender<sender at localdomain.com>,blacklist_sender] => undef,
> "sender at localdomain.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [whitelist_recip<recipient at gmail.com>] => undef, "recipient at gmail.com"
> does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [whitelist_sender<sender at localdomain.com>,whitelist_sender] => undef,
> "sender at localdomain.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> query_keys: recipient at gmail.com, recipient@, gmail.com, .gmail.com, .com, .
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_hash(recipient at gmail.com) matches keys: "."=>ARRAY(0x229c980)
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [score_recip<recipient at gmail.com>,score_sender], 1 matches for
> "recipient at gmail.com", results:
> "."=>[Amavis::Lookup::RE=ARRAY(0x229bf60),{amavis-user-admin at lists.sourceforge.net=>"-3",owner-postfix-announce at postfix.org=>"-3",ntbugtraq at listserv.ntbugtraq.com=>"-3",donotreply at sendmail.org=>"-3",slashdot at slashdot.org=>"-3",clp-request at comp.nus.edu.sg=>"-3",nobody at cert.org=>"-3",security-alerts at linuxsecurity.com=>"-3",cvs-commits-list-admin at gnome.org=>"-3",amavis-user-bounces at lists.sourceforge.net=>"-3",notification-return at lists.sophos.com=>"-3",mailman-announce-admin at python.org=>"-3",emailnews at genomeweb.com=>"-5",owner-textbreakingnews at cnnimail12.cnn.com=>"-5",ca+envelope at sendmail.org=>"-3",cert-advisory at us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-users at postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",sendmail-announce-request at lists.sendmail.org=>"-3",surveys-e...
>
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> ...rrors at lists.nua.ie=>"-3",spamassassin.apache.org=>"-3",lvs-users-admin at linuxvirtualserver.org=>"-3",sender at example.net=>"3",owner-sendmail-announce at lists.sendmail.org=>"-3",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
>
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_re("sender at localdomain.com"), no matches
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> query_keys: sender at localdomain.com, sender@, localdomain.com,
> .localdomain.com, .com, .
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_hash(sender at localdomain.com), no matches
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [score_sender<sender at localdomain.com>] => undef,
> "sender at 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), "recipient at gmail.com" no matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [sa_userconf] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(sa_username), "recipient at gmail.com" no matching records
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) lookup
> [sa_username] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:30 localhost amavis/authenticated[47891]: (47891-01) SA
> user config: "", username: "amavis", 0, (0)recipient at 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), "recipient at 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, "recipient at 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), "recipient at 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, "recipient at 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), "recipient at gmail.com" no matching
> records
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup
> [spam_tag3_level] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(spam_kill_level), "recipient at 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, "recipient at 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), "recipient at gmail.com" no matching
> records
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) lookup
> [message_size_limit] => undef, "recipient at gmail.com" does not match
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> final_destiny (ccat=0) is PASS, recip recipient at gmail.com
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> final_destiny PASS, recip recipient at 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), "recipient at 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, "recipient at 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: recipient at gmail.com
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> lookup_sql_field(spam_tag_level), "recipient at 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, "recipient at 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), "recipient at 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, "recipient at gmail.com" matches, result="4",
> matching_key="(constant:4)"
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> headers CLUSTERING: NEW CLUSTER <recipient at 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
> <sender at localdomain.com> -> <recipient at 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:<sender at localdomain.com> BODY=7BIT
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01)
> orcpt_encode rfc822, recipient at gmail.com, encode_for_smtp
> Sep 29 09:13:31 localhost amavis/authenticated[47891]: (47891-01) smtp
> cmd> RCPT TO:<recipient at gmail.com> ORCPT=rfc822;recipient at 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:<sender at localdomain.com> BODY=7BIT\r\nRCPT
> TO:<recipient at gmail.com> ORCPT=rfc822;recipient at 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) (<recipient at 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-93dca692ed64 at 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=<sender at 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 (<recipient at 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 <sender at localdomain.com> -> <recipient at 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, <sender at 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, "sender at 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 <sender at localdomain.com> ->
> <recipient at 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:
> <sender at localdomain.com> -> <recipient at 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 <sender at 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, recipient at 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]
> <sender at localdomain.com> -> <recipient at gmail.com>, Queue-ID:
> 3y3Lpd5Qtgz52wQSv, Message-ID:
> <0789fa21-18f8-f756-3d08-93dca692ed64 at 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 <recipient at 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=<recipient at 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=<recipient at 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
>
>
>
>
>
>
>
>
>
>
>
More information about the amavis-users
mailing list