need help finding origin of timeout
Patrick Proniewski
patrick.proniewski at univ-lyon2.fr
Tue Jul 15 14:09:52 CEST 2014
Hello list,
I'm using Amavisd-new for years with success on MX servers @work, but few days ago I've noticed few timeouts during email reception. I'm using Postfix 2.10.0 and amavisd-new-2.8.0_2 on FreeBSD, in before queue content filtering.
The timeout occurs only for two different sender-recipient couple. I've activated amavisd-new debuging for both sender, to get some data, but I can't find the culprit. Any help would be greatly appreciated.
(I'm subscribed to digest, feel free to Cc me)
Postfix side of the error:
Jul 15 13:20:26 host postfix/smtpd[60906]: connect from sender.domain.tld[xxx.yyy.130.2]
Jul 15 13:20:26 host postfix/smtpd[60906]: NOQUEUE: client=sender.domain.tld[xxx.yyy.130.2]
Jul 15 13:22:57 host postfix/smtpd[60906]: warning: timeout talking to proxy 127.0.0.1:10024
Jul 15 13:22:57 host postfix/smtpd[60906]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<sender at domain.tld> to=<user.1 at at-work.tld> proto=ESMTP helo=<sender.domain.tld>
Jul 15 13:24:33 host postfix/smtpd[60906]: disconnect from sender.domain.tld[xxx.yyy.130.2]
Amavisd-new debug logs:
Jul 15 13:20:26 host amavis[58256]: (58256-16) DEBUG_ONESHOT: TURNED ON
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP< MAIL From:<sender at domain.tld> SIZE=1444466\r\n
Jul 15 13:20:26 host amavis[58256]: (58256-16) mesage size set to a declared size 1444466
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP> 250 2.1.0 Sender <sender at domain.tld> OK
Jul 15 13:20:26 host amavis[58256]: (58256-16) switch_to_client_time 480 s, smtp response sent
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 6: was busy, 2.0 ms, total idle 1440.899 s, busy 26.897 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) smtp readline: read 37 bytes, new size: 37
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 5: was idle, 0.4 ms, total idle 1440.899 s, busy 26.897 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP< RCPT To:<user.1 at at-work.tld>\r\n
Jul 15 13:20:26 host amavis[58256]: (58256-16) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) lookup => undef, "user.1 at at-work.tld", no lookup tables
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP> 250 2.1.5 Recipient <user.1 at at-work.tld> OK
Jul 15 13:20:26 host amavis[58256]: (58256-16) switch_to_client_time 480 s, smtp response sent
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 6: was busy, 1.3 ms, total idle 1440.899 s, busy 26.898 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) smtp readline: read 39 bytes, new size: 39
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 5: was idle, 1.2 ms, total idle 1440.901 s, busy 26.898 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP< RCPT To:<user.2 at at-work.tld>\r\n
Jul 15 13:20:26 host amavis[58256]: (58256-16) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) lookup => undef, "user.2 at at-work.tld", no lookup tables
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP> 250 2.1.5 Recipient <user.2 at at-work.tld> OK
Jul 15 13:20:26 host amavis[58256]: (58256-16) switch_to_client_time 480 s, smtp response sent
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 6: was busy, 1.5 ms, total idle 1440.901 s, busy 26.900 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) smtp readline: read 6 bytes, new size: 6
Jul 15 13:20:26 host amavis[58256]: (58256-16) idle_proc, 5: was idle, 0.4 ms, total idle 1440.901 s, busy 26.900 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP< DATA\r\n
Jul 15 13:20:26 host amavis[58256]: (58256-16) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP:[127.0.0.1]:10024 /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5: <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld> SIZE=1444466 Received: from amavis.at.at-work.tld ([127.0.0.1]) by host.at-work.tld (host.at-work.tld [127.0.0.1]) (amavisd-new, port 10024) with ESMTP; Tue, 15 Jul 2014 13:20:26 +0200 (CEST)
Jul 15 13:20:26 host amavis[58256]: (58256-16) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jul 15 13:20:26 host amavis[58256]: (58256-16) switch_to_client_time 480 s, smtp response sent
Jul 15 13:20:26 host amavis[58256]: (58256-16) switch_to_client_time 480 s, receiving data
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 57344 bytes into buffer, new size: 57344
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 57344 bytes into buffer, new size: 57344
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28673
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 14336 bytes into buffer, new size: 14336
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 28672 bytes into buffer, new size: 28672
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: read 2222 bytes into buffer, new size: 2222
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp copy: 0 bytes still buffered at end
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) ESMTP< .<CR><LF>
Jul 15 13:20:27 host amavis[58256]: (58256-16) Actual message size 1464491 B greater than the declared 1444466 B
Jul 15 13:20:27 host amavis[58256]: (58256-16) smtp connection cache, dt: 80.9, state: 0
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_body_digest: reading header section from a file
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_body_digest: sending h/b separator to DKIM
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_body_digest: reading mail body from a file
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_body_digest: message size 1464491, header+sep 1560, body 1462931
Jul 15 13:20:27 host amavis[58256]: (58256-16) body type (ESMTP BODY): unlabeled, but 8-bit body (h=0, b=1)
Jul 15 13:20:27 host amavis[58256]: (58256-16) body hash: 55119bc8be3eb63bfa8a07113c2b46bb
Jul 15 13:20:27 host amavis[58256]: (58256-16) Original mail size: 1464491; quota set to: 314572800 bytes
Jul 15 13:20:27 host amavis[58256]: (58256-16) Checking: 3P40W7CF-BJA [xxx.yyy.130.2] <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld>
Jul 15 13:20:27 host amavis[58256]: (58256-16) 2822.From: <sender at domain.tld>
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(user.1 at at-work.tld) matches key "at-work.tld", result=1
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [local_domains] => true, "user.1 at at-work.tld" matches, result="1", matching_key="at-work.tld"
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_virus_checks] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_banned_checks] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_spam_checks] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(user.2 at at-work.tld) matches key "at-work.tld", result=1
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [local_domains] => true, "user.2 at at-work.tld" matches, result="1", matching_key="at-work.tld"
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_virus_checks] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_banned_checks] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_spam_checks] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) decoding bypassed
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_header_checks] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_header_checks] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) check_header: 0, OK
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_header_checks] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [bypass_header_checks] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) Checking for banned types and filenames
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="DEFAULT"
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [banned_filename], 1 matches for "user.1 at at-work.tld", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 15 13:20:27 host amavis[58256]: (58256-16) collect banned table[0]: user.1 at at-work.tld, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x804961e58)
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="DEFAULT"
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [banned_filename], 1 matches for "user.2 at at-work.tld", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 15 13:20:27 host amavis[58256]: (58256-16) collect banned table[0]: user.2 at at-work.tld, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x804961e58)
Jul 15 13:20:27 host amavis[58256]: (58256-16) starting banned checks - traversing message structure tree
Jul 15 13:20:27 host amavis[58256]: (58256-16) banned check: any=0, all=N (2)
Jul 15 13:20:27 host amavis[58256]: (58256-16) Issued a new file name: p001
Jul 15 13:20:27 host amavis[58256]: (58256-16) presenting full original message to scanners as /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts/p001, MIME not decoded
Jul 15 13:20:27 host amavis[58256]: (58256-16) Calling virus scanners, 1 files to scan in /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts
Jul 15 13:20:27 host amavis[58256]: (58256-16) invoking av-scanner ClamAV-clamd
Jul 15 13:20:27 host amavis[58256]: (58256-16) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.sock
Jul 15 13:20:27 host amavis[58256]: (58256-16) run_av (ClamAV-clamd): query template(1,0): CONTSCAN {}\n
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline run_av_pre - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer run_av_pre: timer 336, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline run_av_scan - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer run_av_scan: timer 336, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts\n
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.sock
Jul 15 13:20:27 host amavis[58256]: (58256-16) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.sock, timeout 10
Jul 15 13:20:27 host amavis[58256]: (58256-16) connected to /var/run/clamav/clamd.sock successfully
Jul 15 13:20:27 host amavis[58256]: (58256-16) ClamAV-clamd: Sending CONTSCAN /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts\n to socket /var/run/clamav/clamd.sock
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: sending 69 chars
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop sent 69> CONTSCAN /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts\n
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 480.0 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=0, wr=0, timeout=335.998
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop read 64 chars< /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts: OK\n
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=0, wr=0, timeout=335.998
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:20:27 host amavis[58256]: (58256-16) rw_loop read: got eof
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline ask_daemon_internal - deadline in 479.8 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.8 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline run_av_3 - deadline in 479.8 s, set to 336.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer run_av_3: timer 336, was 336, deadline in 479.8 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) run_av (ClamAV-clamd) result: /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5/parts: OK\n
Jul 15 13:20:27 host amavis[58256]: (58256-16) run_av (ClamAV-clamd): CLEAN
Jul 15 13:20:27 host amavis[58256]: (58256-16) run_av (ClamAV-clamd) result: clean
Jul 15 13:20:27 host amavis[58256]: (58256-16) wbl: checking sender <sender at domain.tld>
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [blacklist_recip<user.1 at at-work.tld>] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [blacklist_sender<sender at domain.tld>,blacklist_sender] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [whitelist_recip<user.1 at at-work.tld>] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(sender at domain.tld), no match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(sender at domain.tld), no match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [whitelist_sender<sender at domain.tld>,whitelist_sender] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) query_keys: user.1 at at-work.tld, user.1@, at-work.tld, .at-work.tld, .fr, .
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_hash(user.1 at at-work.tld) matches keys: "."=>ARRAY(0x804937d68)
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [score_recip<user.1 at at-work.tld>,score_sender], 1 matches for "user.1 at at-work.tld", results: "."=>[Amavis::Lookup::RE=ARRAY(0x8049376a8),{.dolist.net=>"2",SD84.btc-net.bg=>"2",www-data at chichou.com=>"2",amavis-user-admin at lists.sourceforge.net=>"-3",postmaster at at-work.tld=>"5",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",linguist at LINGUISTLIST.ORG=>"-5",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",linguist at linguistist.org=>"-5",cert-advisory at us-cert.gov=>"-3", at nouvelle-vision.com=>"5",returns.groups.yahoo.com=>"-3",ac...
Jul 15 13:20:27 host amavis[58256]: (58256-16) ...counts at oecd-ilibrary.org=>"-5",owner-postfix-users at postfix.org=>"-3",bounce at geodiffusion.net=>"2",owner-freebsd-questions at freebsd.org=>"-5",.example.net=>"1",securityfocus.com=>"-3",notification at crisisgroup.org=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",emv2.net=>"2",sendmail-announce-request at lists.sendmail.org=>"-3",surveys-errors at lists.nua.ie=>"-3",noreply at photoshop.com=>"-5",spamassassin.apache.org=>"-3",.constantcontact.com=>"3",chris at lesirius.com=>"5.15",.routage-emailing.com=>"5",lvs-users-admin at linuxvirtualserver.org=>"-3",emv1.net=>"2", at tnp-villeurbanne.com=>"-4",reno at radioscoop.com=>"5",sender at example.net=>"3",emailserver at pop3.amadeus.net=>"-3",owner-sendmail-announce at lists.sendmail.org=>"-3",dbworld-bounces at cs.wisc.edu=>"-5", at mom.fr=>"-3",marciapsidivulga at terra.com.br=>"-5",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",administrator at at-work.tld=>"5",CheckMyTrip at e...
Jul 15 13:20:27 host amavis[58256]: (58256-16) ...-travel.com=>"-1",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_re("sender at domain.tld"), no matches
Jul 15 13:20:27 host amavis[58256]: (58256-16) query_keys: sender at domain.tld, sender@, domain.tld, .domain.tld, .fr, .
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_hash(sender at domain.tld), no matches
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [score_sender<sender at domain.tld>] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [blacklist_recip<user.2 at at-work.tld>] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [blacklist_sender<sender at domain.tld>,blacklist_sender] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [whitelist_recip<user.2 at at-work.tld>] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(sender at domain.tld), no match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_acl(sender at domain.tld), no match
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [whitelist_sender<sender at domain.tld>,whitelist_sender] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) query_keys: user.2 at at-work.tld, user.2@, at-work.tld, .at-work.tld, .fr, .
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_hash(user.2 at at-work.tld) matches keys: "."=>ARRAY(0x804937d68)
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [score_recip<user.2 at at-work.tld>,score_sender], 1 matches for "user.2 at at-work.tld", results: "."=>[Amavis::Lookup::RE=ARRAY(0x8049376a8),{.dolist.net=>"2",SD84.btc-net.bg=>"2",www-data at chichou.com=>"2",amavis-user-admin at lists.sourceforge.net=>"-3",postmaster at at-work.tld=>"5",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",linguist at LINGUISTLIST.ORG=>"-5",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",linguist at linguistist.org=>"-5",cert-advisory at us-cert.gov=>"-3", at nouvelle-vision.com=>"5",returns.groups.yahoo.com=>"-3...
Jul 15 13:20:27 host amavis[58256]: (58256-16) ...",accounts at oecd-ilibrary.org=>"-5",owner-postfix-users at postfix.org=>"-3",bounce at geodiffusion.net=>"2",owner-freebsd-questions at freebsd.org=>"-5",.example.net=>"1",securityfocus.com=>"-3",notification at crisisgroup.org=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",emv2.net=>"2",sendmail-announce-request at lists.sendmail.org=>"-3",surveys-errors at lists.nua.ie=>"-3",noreply at photoshop.com=>"-5",spamassassin.apache.org=>"-3",.constantcontact.com=>"3",chris at lesirius.com=>"5.15",.routage-emailing.com=>"5",lvs-users-admin at linuxvirtualserver.org=>"-3",emv1.net=>"2", at tnp-villeurbanne.com=>"-4",reno at radioscoop.com=>"5",sender at example.net=>"3",emailserver at pop3.amadeus.net=>"-3",owner-sendmail-announce at lists.sendmail.org=>"-3",dbworld-bounces at cs.wisc.edu=>"-5", at mom.fr=>"-3",marciapsidivulga at terra.com.br=>"-5",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",administrator at at-work.tld=>"5",CheckMyTr...
Jul 15 13:20:27 host amavis[58256]: (58256-16) ...ip at e-travel.com=>"-1",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_re("sender at domain.tld"), no matches
Jul 15 13:20:27 host amavis[58256]: (58256-16) query_keys: sender at domain.tld, sender@, domain.tld, .domain.tld, .fr, .
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup_hash(sender at domain.tld), no matches
Jul 15 13:20:27 host amavis[58256]: (58256-16) lookup [score_sender<sender at domain.tld>] => undef, "sender at domain.tld" does not match
Jul 15 13:20:27 host amavis[58256]: (58256-16) SpamControl: calling spam scanner SpamAssassin
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline spam_scan_sa_pre - deadline in 479.8 s, set to 476.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) prolong_timer spam_scan_sa_pre: timer 476, was 336, deadline in 479.8 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) truncating a message passed to SA at 615961 bytes, orig 1464491
Jul 15 13:20:27 host amavis[58256]: (58256-16) SA user config: "", username: "vscan", 0,1
Jul 15 13:20:27 host amavis[58256]: (58256-16) calling SA parse (0), SA vers 3.3.2, 3.003002, data as GLOB, recips_ind [0,1], user: "vscan"
Jul 15 13:20:27 host amavis[58256]: (58256-16) get_deadline SA check - deadline in 479.8 s, set to 475.000 s
Jul 15 13:20:27 host amavis[58256]: (58256-16) CALLING SA check (0)
Jul 15 13:22:57 host postfix/smtpd[60906]: warning: timeout talking to proxy 127.0.0.1:10024
Jul 15 13:23:20 host amavis[58256]: (58256-16) DONE SA check (0)
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline spam_scan_sa - deadline in 306.5 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer spam_scan_sa: timer 215, was 303, deadline in 306.5 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) spam_scan: score=-3.858 autolearn=unavailable tests=[BAYES_00=-1.9,CRM114_CHECK=-1.9605,HTML_MESSAGE=0.001,LOTS_OF_MONEY=0.001,NORMAL_HTTP_TO_IP=0.001,RP_MATCHES_RCVD=-0.001,WEIRD_QUOTING=0.001] recips=0,1
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline spam_scan - deadline in 306.5 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer spam_scan: timer 215, was 215, deadline in 306.5 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="-5"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag_level] => true, "user.1 at at-work.tld" matches, result="-5", matching_key="(constant:-5)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="3"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag2_level] => true, "user.1 at at-work.tld" matches, result="3", matching_key="(constant:3)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag3_level] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="6"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_kill_level] => true, "user.1 at at-work.tld" matches, result="6", matching_key="(constant:6)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny (ccat=1) is PASS, recip user.1 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny (ccat=0) is PASS, recip user.1 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny PASS, recip user.1 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="-5"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag_level] => true, "user.2 at at-work.tld" matches, result="-5", matching_key="(constant:-5)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="3"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag2_level] => true, "user.2 at at-work.tld" matches, result="3", matching_key="(constant:3)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag3_level] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="6"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_kill_level] => true, "user.2 at at-work.tld" matches, result="6", matching_key="(constant:6)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny (ccat=1) is PASS, recip user.2 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny (ccat=0) is PASS, recip user.2 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) final_destiny PASS, recip user.2 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jul 15 13:23:20 host amavis[58256]: (58256-16) do_notify_and_quarantine: not quarantining, q_method off
Jul 15 13:23:20 host amavis[58256]: (58256-16) do_notify_and_quarantine: not quarantining, q_method off
Jul 15 13:23:20 host amavis[58256]: (58256-16) skip admin notification, no administrators
Jul 15 13:23:20 host amavis[58256]: (58256-16) do_notify_and_quarantine - done
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [forward_method] => true, "user.1 at at-work.tld" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [forward_method] => true, "user.2 at at-work.tld" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) delivery method is 1, recips: user.1 at at-work.tld, user.2 at at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="1"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [remove_existing_spam_headers] => true, "user.1 at at-work.tld" matches, result="1", matching_key="(constant:1)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="-5"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag_level] => true, "user.1 at at-work.tld" matches, result="-5", matching_key="(constant:-5)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="3"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag2_level] => true, "user.1 at at-work.tld" matches, result="3", matching_key="(constant:3)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_subject_tag] => undef, "user.1 at at-work.tld" does not match
Jul 15 13:23:20 host amavis[58256]: (58256-16) headers CLUSTERING: NEW CLUSTER <user.1 at at-work.tld>: score=-3.858, tag=1, tag2=0, local=1, bl=, s=, mangle=
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-Virus-Scanned: amavisd-new at at-work.tld\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-Spam-Flag: NO\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-Spam-Score: -3.858\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-Spam-Level:\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-Spam-Status: No, score=-3.858 tagged_above=-5 required=3\n\ttests=[BAYES_00=-1.9, CRM114_CHECK=-1.9605, HTML_MESSAGE=0.001,\n\tLOTS_OF_MONEY=0.001, NORMAL_HTTP_TO_IP=0.001, RP_MATCHES_RCVD=-0.001,\n\tWEIRD_QUOTING=0.001] autolearn=unavailable\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) fwd: scanner provided X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Jul 15 13:23:20 host amavis[58256]: (58256-16) fwd: scanner provided X-Spam-Level, but we preferred our own
Jul 15 13:23:20 host amavis[58256]: (58256-16) fwd: scanner provided X-Spam-Status, but we preferred our own
Jul 15 13:23:20 host amavis[58256]: (58256-16) fwd: scanner provided X-Spam-CRM114-Status, inhibited by %allowed_added_header_fields
Jul 15 13:23:20 host amavis[58256]: (58256-16) fwd: scanner provided X-CRM114-Status, inserting
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: X-CRM114-Status: GOOD ( 39.21 )\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) header: Received: from amavis.at.at-work.tld ([127.0.0.1])\n\tby host.at-work.tld (host.at-work.tld [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id 3P40W7CF-BJA; Tue, 15 Jul 2014 13:20:26 +0200 (CEST)\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="1"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [remove_existing_spam_headers] => true, "user.2 at at-work.tld" matches, result="1", matching_key="(constant:1)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="-5"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag_level] => true, "user.2 at at-work.tld" matches, result="-5", matching_key="(constant:-5)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="3"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_tag2_level] => true, "user.2 at at-work.tld" matches, result="3", matching_key="(constant:3)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_subject_tag] => undef, "user.2 at at-work.tld" does not match
Jul 15 13:23:20 host amavis[58256]: (58256-16) headers CLUSTERING: <user.2 at at-work.tld> joining cluster
Jul 15 13:23:20 host amavis[58256]: (58256-16) headers CLUSTERING: done all 2 recips in one go
Jul 15 13:23:20 host amavis[58256]: (58256-16) spam-tag, <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld>, No, score=-3.858 tagged_above=-5 required=3 tests=[BAYES_00=-1.9, CRM114_CHECK=-1.9605, HTML_MESSAGE=0.001, LOTS_OF_MONEY=0.001, NORMAL_HTTP_TO_IP=0.001, RP_MATCHES_RCVD=-0.001, WEIRD_QUOTING=0.001] autolearn=unavailable
Jul 15 13:23:20 host amavis[58256]: (58256-16) dkim: not signing mail which is not originating from our site
Jul 15 13:23:20 host amavis[58256]: (58256-16) about to connect to smtp:[127.0.0.1]:10025, FWD from <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline fwd_init - deadline in 306.5 s, set to 307.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp session: setting up a new session
Jul 15 13:23:20 host amavis[58256]: (58256-16) establish_or_refresh, state: down
Jul 15 13:23:20 host amavis[58256]: (58256-16) new socket using IO::Socket::INET to [127.0.0.1]:10025, timeout 35
Jul 15 13:23:20 host amavis[58256]: (58256-16) connected to [127.0.0.1]:10025 successfully
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop read 30 chars< 220 host.at-work.tld ESMTP\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp greeting: 220 host.at-work.tld ESMTP, dt: 1.7 ms
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> EHLO host.at-work.tld
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 25 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 25> EHLO host.at-work.tld\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop read 180 chars< 250-host.at-work.tld\r\n250-PIPELINING\r\n250-SIZE 20480000\r\n250-VRFY\r\n250-ETRN\r\n250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to EHLO: 250 host.at-work.tld\nPIPELINING\nSIZE 20480000\nVRFY\nETRN\nXFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Jul 15 13:23:20 host amavis[58256]: (58256-16) tls active=0, capable=, sec_level=0
Jul 15 13:23:20 host amavis[58256]: (58256-16) Remote host presents itself as: host.at-work.tld, handles DSN, handles PIPELINING
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> XFORWARD ADDR=xxx.yyy.130.2 NAME=sender.domain.tld PORT=57611 PROTO=ESMTP HELO=sender.domain.tld SOURCE=REMOTE
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 122 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 122> XFORWARD ADDR=xxx.yyy.130.2 NAME=sender.domain.tld PORT=57611 PROTO=ESMTP HELO=sender.domain.tld SOURCE=REMOTE\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop read 14 chars< 250 2.0.0 Ok\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to XFORWARD: 250 2.0.0 Ok
Jul 15 13:23:20 host amavis[58256]: (58256-16) AUTH not needed, user='', MTA offers ''
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> MAIL FROM:<sender at domain.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> RCPT TO:<user.1 at at-work.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> RCPT TO:<user.2 at at-work.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> DATA
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 116 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 116> MAIL FROM:<sender at domain.tld>\r\nRCPT TO:<user.1 at at-work.tld>\r\nRCPT TO:<user.2 at at-work.tld>\r\nDATA\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop read 79 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to RCPT (pip) (<user.1 at at-work.tld>): 250 2.1.5 Ok
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to RCPT (pip) (<user.2 at at-work.tld>): 250 2.1.5 Ok
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jul 15 13:23:20 host amavis[58256]: (58256-16) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x80afe3a38)
Jul 15 13:23:20 host amavis[58256]: (58256-16) deleted: X-Spam-Status: No
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 68621 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 68621> X-Virus-Scanned: amavisd-new at at-work.tld\r\nX-Spam-Flag: NO\r\nX-Spam-Score: -3.858\r\nX-Spam-Level:\r\nX-Spam-Status: No, score=-3.858 tagged_above=-5 required=3\r\n\ttests=[BAYES_00=-1.9, CRM114_CHECK=-1. [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> gDFAFdj36VCzYPXHvVgx9f0qjc8cgc44oAc0vykAdRimLW92jwl5I1a\r\nRIpA [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66433 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66433> 9Bn2rlYPBes2Nzoeq2L2Uep2UItrtDK3l3USgAHO3IOOOfPFTW2l61HqGi3Nx [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> +8cMTye9V\r\nLHwjpmm25t7U36W4jaOOE30xWJW6hAW+0jT1sbJJBbxszASSNI [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> 45qfLkCK85U+IuXN2LJdkjljRU0\r\nQNALLO6XXW4BhFInD38Oispuq0QFuPsk [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> MHGoaoa21xWG0tQdYtM19tBV9+UdDWy+CYdoKHkxbSHQQW+UY4qY9d\r\nKUWtS [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66433 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66433> n7WztY9bvN+Xs0WA76WOfCMoEuTCZIUpk3rMj7pJ/MzSw4fr0p5u4WSBY9Yrh [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> O+/k3onE\r\n0RJL4mg0RRgDChdPhPE/b7s1hWrWexp/sg1SKWYmdXgwLPxmaSz [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> Q0d6Zpg9wyrxI6vTJza1oFmOY1\r\nfqqjEuBTbA51xatiOHrfCX+9H9ixloJ9g [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> Pk2zQ7XJugtnnKVlDOsMonp+0z766hRM+scM+SdIyP9E\D9k1eWqT\r\nwsRU3L [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66433 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66433> TmfjRCLd+yXCeQ7Q49q0CBmaZeqsnJexKq6QW5IS3W/4pN7nDVjvkw0Iy6lSx [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> /jnn27/\r\nwD/++PaL2+9u39y+wp9+efvz23/fvsO/G6db+Ipd64P68jdsZjjj [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> e9mYK9VDHyIdg9lv9r/qtflmJ\r\n1XfYyokPBDc48MrffI0yPUL0eAMEjSPLVn [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> kJIjyFscvvT03JSTMrxUtXqyXJ7st1W5Xg9N7kD6d5A\rRC+QTFW\r\nPHBIOLg [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66433 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66433> qzLUqqo7cI44DTk2AXhXmKBzP3hvMq+B4XsMFDZdVLOhX4GtAEaL4TdtCBBev [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> Jqkls5\r\nLsmUK6WRluYAeO8knJo0L4dPA3xKkumkOfDMHzb7EOlbQOODy2X2t [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> jt3Kbp11x9p19+cdeuPjnfP2\r\nVZdvSLyuf/YZVVwJwIVOAW1HzUhM2JfGfD4 [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> dGX5o7co9mfQbh0S7rWJHO8e/qGHoSj0DciaGGgF90\r\7CMs5F\r\nkba1w/9l [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66433 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66433> dSe8dSe8dSe8dSe8dSe8dWfQW++Gt+74HG/t/wJv3fkF3AcrlCHCgjOZwy0E5 [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> +R/E5\r\nis9RfI7icxSfo/gcxecoPhfpamrP22rPUXuO3lZwNUrIdW5ij4hwV5 [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> bW5joeyW92uklBeq+AqCx1p\r\nDbpOhY61DrqqQsWt51DlnrwwNta67UL3rzrv [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 66434 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 66434> eRth9nTrpuyXGH5yQElSqacDhIIPOJl7MhKALtm+d\r\nyMiAw\r\nIG9iag0KP [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp connection_cache disabled, sending QUIT
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp cmd> QUIT
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=0, flush=1, wr=1, timeout=306.944
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: sending 1334 chars
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop sent 1334> DAxNjk2IDY1NTM1IGYNCjAwMDAwMDE2OTcgNjU1MzUgZg0AwMDA2MTgyMTEgM [...]
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: needline=1, flush=0, wr=0, timeout=306.944
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop: receiving
Jul 15 13:23:20 host amavis[58256]: (58256-16) rw_loop read 48 chars< 250 2.0.0 Ok: queued as E320316\r\n221 2.0.0 Bye\r\n
Jul 15 13:23:20 host amavis[58256]: (58256-16) smtp resp to data-dot (<user.1 at at-work.tld>, etc.): 250 2.0.0 Ok: queued as E320316, dt: 4.6 ms
Jul 15 13:23:20 host amavis[58256]: (58256-16) Amavis::Out::SMTP::Session close, disconnecting
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline fwd-end-chkpnt - deadline in 306.4 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer fwd-end-chkpnt: timer 215, was 0, deadline in 306.4 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) FWD from <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld>, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E320316
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline forwarding - deadline in 306.4 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer forwarding: timer 215, was 215, deadline in 306.4 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) DSN: sender NOT credible, SA: -3.858, <sender at domain.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup: (scalar) matches, result="8"
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup [spam_dsn_cutoff_level_bysender] => true, "sender at domain.tld" matches, result="8", matching_key="(constant:8)"
Jul 15 13:23:20 host amavis[58256]: (58256-16) dsn: from MTA 250 NonBlocking:CleanTag <sender at domain.tld> -> <user.1 at at-work.tld>: 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 E320316"
Jul 15 13:23:20 host amavis[58256]: (58256-16) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <sender at domain.tld> -> <user.1 at at-work.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) dsn: from MTA 250 NonBlocking:CleanTag <sender at domain.tld> -> <user.2 at at-work.tld>: 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 E320316"
Jul 15 13:23:20 host amavis[58256]: (58256-16) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <sender at domain.tld> -> <user.2 at at-work.tld>
Jul 15 13:23:20 host amavis[58256]: (58256-16) one_response_for_all <sender at domain.tld>: 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 E320316'
Jul 15 13:23:20 host amavis[58256]: (58256-16) 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 E320316
Jul 15 13:23:20 host amavis[58256]: (58256-16) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline delivery-notification - deadline in 306.4 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer delivery-notification: timer 215, was 215, deadline in 306.4 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) fish_out_ip_from_received: xxx.yyy.181.135
Jul 15 13:23:20 host amavis[58256]: (58256-16) lookup_ip_acl (publicnetworks) arr.obj: key="xxx.yyy.181.135" matches "::FFFF:0:0/96", result=1
Jul 15 13:23:20 host amavis[58256]: (58256-16) parse_ip_address_from_received: xxx.yyy.181.135
Jul 15 13:23:20 host amavis[58256]: (58256-16) Passed CLEAN {RelayedInbound}, [xxx.yyy.130.2]:57611 [xxx.yyy.181.135] <sender at domain.tld> -> <user.1 at at-work.tld>,<user.2 at at-work.tld>, Message-ID: <53C4F38E.1000901 at domain.tld>, mail_id: 3P40W7CF-BJA, Hits: -3.858, size: 1464491, queued_as: E320316, 174032 ms
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline main_log_entry - deadline in 306.4 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer main_log_entry: timer 215, was 215, deadline in 306.4 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) TIMING-SA total 173319 ms - parse: 27 (0.0%), extract_message_metadata: 578 (0.3%), get_uri_detail_list: 834 (0.5%), tests_pri_-1000: 18 (0.0%), tests_pri_-950: 3 (0.0%), tests_pri_-900: 3 (0.0%), tests_pri_-400: 9418 (5.4%), check_bayes: 9393 (5.4%), tests_pri_0: 162515 (93.8%), check_dkim_adsp: 5 (0.0%), check_razor2: 517 (0.3%), check_pyzor: 187 (0.1%), tests_pri_500: 13 (0.0%), tests_pri_899: 260 (0.2%), check_crm114: 256 (0.1%), learn: 456 (0.3%), get_report: 1.33 (0.0%)
Jul 15 13:23:20 host amavis[58256]: (58256-16) DEBUG_ONESHOT CAUSES EVIDENCE TO BE PRESERVED
Jul 15 13:23:20 host amavis[58256]: (58256-16) get_deadline check done - deadline in 306.4 s, set to 215.000 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) prolong_timer check done: timer 215, was 215, deadline in 306.4 s
Jul 15 13:23:20 host amavis[58256]: (58256-16) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E320316"
Jul 15 13:23:20 host amavis[58256]: (58256-16) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E320316
Jul 15 13:23:20 host amavis[58256]: (58256-16) switch_to_client_time 480 s, smtp response sent
Jul 15 13:23:20 host amavis[58256]: (58256-16) (!)PRESERVING EVIDENCE in /var/amavis/tmp/amavis-20140715T125559-58256-II3Gd7R5
Jul 15 13:23:20 host amavis[58256]: (58256-16) size: 1464491, TIMING [total 174040 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 8 (0%)0, SMTP DATA: 413 (0%)0, check_init: 1 (0%)0, digest_hdr: 3 (0%)0, digest_body_dkim: 15 (0%)0, check_header: 5 (0%)0, AV-scan-1: 158 (0%)0, spam-wb-list: 6 (0%)0, SA parse: 29 (0%)0, SA check: 173285 (100%)100, decide_mail_destiny: 22 (0%)100, notif-quar: 1 (0%)100, fwd-connect: 14 (0%)100, fwd-xforward: 2 (0%)100, fwd-mail-pip: 3 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100, fwd-data-contents: 45 (0%)100, fwd-end-chkpnt: 7 (0%)100, prepare-dsn: 3 (0%)100, main_log_entry: 12 (0%)100, SMTP pre-response: 2 (0%)100, SMTP response: 1 (0%)100, rundown: 2 (0%)100
Jul 15 13:23:21 host amavis[58256]: (58256-16) idle_proc, 6: was busy, 174031.1 ms, total idle 1440.901 s, busy 200.931 s
Jul 15 13:23:21 host amavis[58256]: (58256-16) smtp readline: error: Connection reset by peer
Jul 15 13:23:21 host amavis[58256]: (58256-16) SMTP session over, timer stopped
Jul 15 13:23:21 host amavis[58256]: (58256-16) idle_proc, 7: was idle, 0.9 ms, total idle 1440.902 s, busy 200.931 s
Jul 15 13:23:21 host amavis[58256]: (58256-16) ESMTP: notice: client broke the connection without a QUIT ()
Jul 15 13:23:21 host amavis[58256]: (58256-16) exiting process_request
Jul 15 13:23:21 host amavis[58256]: (58256-16) DEBUG_ONESHOT: TURNED OFF
Patrick PRONIEWSKI
--
Responsable pôle Opérations - DSI - Université Lumière Lyon 2
Responsable Sécurité des Systèmes d'Information
More information about the amavis-users
mailing list