Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_ip_acl (public_nets) arr.obj: key="172.25.12.1" matches "!172.16.0.0/12", result=0
Dec 31 14:18:27 mail amavis[7142]: (07142-01) trace: ESMTP://[127.0.0.1]:45420 < ESMTPSA://[172.25.12.1]:52752
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Original mail size: 83768; quota set to: 41884000 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql begin, nontransaction
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Dec 31 14:18:27 mail amavis[7142]: (07142-01) save_info_preliminary VQrFXZ3q7qhB, sender id: 22, testuser@localtest.com, exists
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql begin, nontransaction
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Dec 31 14:18:27 mail amavis[7142]: (07142-01) orcpt_encode rfc822, extuser@extdomain.com, smtputf8
Dec 31 14:18:27 mail amavis[7142]: (07142-01) save_info_preliminary VQrFXZ3q7qhB, recip id: 23, extuser@extdomain.com (ORCPT rfc822;extuser@extdomain.com), exists
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql begin transaction
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql: preparing and executing (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) sql commit
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Checking: VQrFXZ3q7qhB MYNETS/MYUSERS [172.25.12.1] <testuser@localtest.com> -> <extuser@extdomain.com>
Dec 31 14:18:27 mail amavis[7142]: (07142-01) 2822.From: <testuser@localtest.com>
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(local), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="1"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [local_domains] => true, "extuser@extdomain.com" matches, result="1", matching_key="(constant:1)"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(bypass_virus_checks), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [bypass_virus_checks] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(bypass_banned_checks), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [bypass_banned_checks] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(bypass_spam_checks), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [bypass_spam_checks] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(id), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [users.id] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(policy_id), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [users.policy_id] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Extracting mime components from a string
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Issued a new file name: p001
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Issued a new file name: p002
Dec 31 14:18:27 mail amavis[7142]: (07142-01) mime_decode_preamble: 1 lines
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Issued a new pseudo part: p003
Dec 31 14:18:27 mail amavis[7142]: (07142-01) p003 1 Content-Type: multipart/mixed
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Charging 23 bytes to remaining quota 41884000 (out of 41884000, (0%)) - by mime_decode
Dec 31 14:18:27 mail amavis[7142]: (07142-01) p001 1/1 Content-Type: text/plain, size: 23 B, name:
Dec 31 14:18:27 mail amavis[7142]: (07142-01) reparenting p001 from p000 to p003
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Charging 60325 bytes to remaining quota 41883977 (out of 41884000, (0%)) - by mime_decode
Dec 31 14:18:27 mail amavis[7142]: (07142-01) p002 1/2 Content-Type: application/pdf, size: 60325 B, name: Solution_Server_1A.pdf
Dec 31 14:18:27 mail amavis[7142]: (07142-01) reparenting p002 from p000 to p003
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline mime_decode - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer mime_decode: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline mime_decode-1 - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Dec 31 14:18:27 mail amavis[7142]: (07142-01) running file(1) on 2 files, arglist size 23
Dec 31 14:18:27 mail amavis[7142]: (07142-01) run_command: [7172] /usr/bin/file p001 p002 </dev/null 2>&1
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: target fd1 closing, to become (65) &=19
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: target fd1 dup2 from fd19 (65) &=19
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: source fd19 closed
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Dec 31 14:18:27 mail amavis[7172]: (07142-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Dec 31 14:18:27 mail amavis[7142]: (07142-01) result line from file(1): p001: ASCII text\n
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [map_full_type_to_short_type] => true, "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) File-type of p001: ASCII text; (asc)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) result line from file(1): p002: PDF document, version 1.5\n
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_re("PDF document, version 1.5") matches key "(?^:^PDF document\\b)", result="pdf"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [map_full_type_to_short_type] => true, "PDF document, version 1.5" matches, result="pdf", matching_key="(?^:^PDF document\\b)"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) File-type of p002: PDF document, version 1.5; (pdf)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) decompose_part: p001 - atomic
Dec 31 14:18:27 mail amavis[7142]: (07142-01) decompose_part: p002 - atomic
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline parts_decode - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer parts_decode: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(bypass_header_checks), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [bypass_header_checks] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) check_header: 0, OK
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(bypass_header_checks), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [bypass_header_checks] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Checking for banned types and filenames
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_sql_field(banned_rulenames), "extuser@extdomain.com" no matching records
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="DEFAULT"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [banned_filename], 1 matches for "extuser@extdomain.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) collect banned table[0]: extuser@extdomain.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x23c3a70)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) starting banned checks - traversing message structure tree
Dec 31 14:18:27 mail amavis[7142]: (07142-01) check_for_banned (p003,p001) multipart/mixed | text/plain,.asc
Dec 31 14:18:27 mail amavis[7142]: (07142-01) doing banned check for extuser@extdomain.com on multipart/mixed | text/plain,.asc
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_re(["multipart/mixed","text/plain",".asc"]), no matches
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [check_bann:extuser@extdomain.com] => undef, ["multipart/mixed","text/plain",".asc"] does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p001\tL=1/1\tM=text/plain\tT=asc" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) p.path extuser@extdomain.com: "P=p003,L=1,M=multipart/mixed | P=p001,L=1/1,M=text/plain,T=asc"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) check_for_banned (p003,p002) multipart/mixed | application/pdf,.pdf,Solution_Server_1A.pdf
Dec 31 14:18:27 mail amavis[7142]: (07142-01) doing banned check for extuser@extdomain.com on multipart/mixed | application/pdf,.pdf,Solution_Server_1A.pdf
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_re(["multipart/mixed","application/pdf",".pdf","Solution_Server_1A.pdf"]), no matches
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [check_bann:extuser@extdomain.com] => undef, ["multipart/mixed","application/pdf",".pdf","Solution_Server_1A.pdf"] does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p002\tL=1/2\tM=application/pdf\tT=pdf\tN=Solution_Server_1A.pdf" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) p.path extuser@extdomain.com: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/pdf,T=pdf,N=Solution_Server_1A.pdf"
Dec 31 14:18:27 mail amavis[7142]: (07142-01) banned check: any=0, all=N (1)
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup_re("MAIL"), no matches
Dec 31 14:18:27 mail amavis[7142]: (07142-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Dec 31 14:18:27 mail amavis[7142]: (07142-01) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts
Dec 31 14:18:27 mail amavis[7142]: (07142-01) invoking av-scanner ClamAV-clamd
Dec 31 14:18:27 mail amavis[7142]: (07142-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl
Dec 31 14:18:27 mail amavis[7142]: (07142-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts\n
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 479.9 s
Dec 31 14:18:27 mail amavis[7142]: (07142-01) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Dec 31 14:18:27 mail amavis[7142]: (07142-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Dec 31 14:18:27 mail amavis[7142]: (07142-01) connected to /var/run/clamav/clamd.ctl successfully
Dec 31 14:18:28 mail amavis[7142]: (07142-01) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts\n to socket /var/run/clamav/clamd.ctl
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: sending 73 chars
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 479.9 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts: OK\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop read: got eof
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts: OK\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) run_av (ClamAV-clamd): CLEAN
Dec 31 14:18:28 mail amavis[7142]: (07142-01) run_av (ClamAV-clamd) result: clean
Dec 31 14:18:28 mail amavis[7142]: (07142-01) wbl: checking sender <testuser@localtest.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) wbl: (SQL) recip <extuser@extdomain.com>, 0 matches
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [blacklist_recip<extuser@extdomain.com>] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [blacklist_sender<testuser@localtest.com>,blacklist_sender] => undef, "testuser@localtest.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [whitelist_recip<extuser@extdomain.com>] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [whitelist_sender<testuser@localtest.com>,whitelist_sender] => undef, "testuser@localtest.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) query_keys: extuser@extdomain.com, extuser@, extdomain.com, .extdomain.com, .org, .
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_hash(extuser@extdomain.com) matches keys: "."=>ARRAY(0x23e1fa8)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [score_recip<extuser@extdomain.com>,score_sender], 1 matches for "extuser@extdomain.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x23f29e8),{}]
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_re("testuser@localtest.com"), no matches
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [score_sender<testuser@localtest.com>] => undef, "testuser@localtest.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) SpamControl: calling spam scanner SpamAssassin
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 479.9 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(sa_userconf), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [sa_userconf] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(sa_username), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [sa_username] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) SA user config: "", username: "amavis", 0, (0)extuser@extdomain.com
Dec 31 14:18:28 mail amavis[7142]: (07142-01) calling SA parse (0), SA vers 3.4.0, 3.004000, data as STRING_REF, recips_ind [0], user: "amavis"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) CALLING SA check (0)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) DONE SA check (0)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline spam_scan_sa - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer spam_scan_sa: timer 288, was 476, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) spam_scan: score=-1 autolearn=ham autolearn_force=no tests=[ALL_TRUSTED=-1] recips=0
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline spam_scan - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer spam_scan: timer 288, was 288, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_tag_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="2"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_tag_level] => true, "extuser@extdomain.com" matches, result="2", matching_key="(constant:2)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_tag2_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="6.31"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_tag2_level] => true, "extuser@extdomain.com" matches, result="6.31", matching_key="(constant:6.31)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_tag3_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_tag3_level] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_kill_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="6.31"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_kill_level] => true, "extuser@extdomain.com" matches, result="6.31", matching_key="(constant:6.31)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(message_size_limit), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [message_size_limit] => undef, "extuser@extdomain.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) final_destiny (ccat=0) is PASS, recip extuser@extdomain.com
Dec 31 14:18:28 mail amavis[7142]: (07142-01) final_destiny PASS, recip extuser@extdomain.com
Dec 31 14:18:28 mail amavis[7142]: (07142-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Dec 31 14:18:28 mail amavis[7142]: (07142-01) do_notify_and_quarantine: not quarantining, q_method off
Dec 31 14:18:28 mail amavis[7142]: (07142-01) skip admin notification, no administrators
Dec 31 14:18:28 mail amavis[7142]: (07142-01) do_notify_and_quarantine - done
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(forward_method), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [forward_method] => true, "extuser@extdomain.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) delivery method is 1, recips: extuser@extdomain.com
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_tag_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="2"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_tag_level] => true, "extuser@extdomain.com" matches, result="2", matching_key="(constant:2)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_sql_field(spam_tag2_level), "extuser@extdomain.com" no matching records
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup: (scalar) matches, result="6.31"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_tag2_level] => true, "extuser@extdomain.com" matches, result="6.31", matching_key="(constant:6.31)"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) headers CLUSTERING: NEW CLUSTER <extuser@extdomain.com>: score=-1, tag=0, tag2=0, local=1, bl=, s=, mangle=
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at mailserver
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header: X-Virus-Scanned: Debian amavisd-new at mailserver\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Dec 31 14:18:28 mail amavis[7142]: (07142-01) fwd: scanner provided a header field X-Spam-Level, but we preferred our own
Dec 31 14:18:28 mail amavis[7142]: (07142-01) fwd: scanner provided a header field X-Spam-Status, but we preferred our own
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header encoded (all-ASCII): Received: from mail.mahendrasgroup.org ([127.0.0.1])\n by mail.mahendrasgroup.org (mail.mahendrasgroup.org [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id VQrFXZ3q7qhB\n for <extuser@extdomain.com>;\n Thu, 31 Dec 2015 14:18:27 +0530 (IST)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header: Received: from mail.mahendrasgroup.org ([127.0.0.1])\n\tby mail.mahendrasgroup.org (mail.mahendrasgroup.org [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id VQrFXZ3q7qhB for <extuser@extdomain.com>;\n\tThu, 31 Dec 2015 14:18:27 +0530 (IST)\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) headers CLUSTERING: done all 1 recips in one go
Dec 31 14:18:28 mail amavis[7142]: (07142-01) dkim: candidate originators: From:<testuser@localtest.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) query_keys: testuser@localtest.com, testuser@, localtest.com, .localtest.com, .com, .
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup_hash(testuser@localtest.com) matches keys: "localtest.com"=>HASH(0x24b0130), "."=>HASH(0x24affc8)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [dkim_signature_options_bysender], 2 matches for "testuser@localtest.com", results: "localtest.com"=>{d=>"mahendrasgroup.org",ttl=>"864000",a=>"rsa-sha256"}, "."=>{a=>"rsa-sha256",c=>"relaxed/simple",ttl=>"2592000"}
Dec 31 14:18:28 mail amavis[7142]: (07142-01) dkim: signature options for testuser@localtest.com(From): a=rsa-sha256; c=relaxed/simple; ttl=864000; d=mahendrasgroup.org
Dec 31 14:18:28 mail amavis[7142]: (07142-01) dkim: signing (3rd-party), From: <testuser@localtest.com> (From:<testuser@localtest.com>), KEY.key_ind=>0, a=>rsa-sha256, c=>relaxed/simple, d=>mahendrasgroup.org, s=>dkim, ttl=>864000, x=>1452415708
Dec 31 14:18:28 mail amavis[7142]: (07142-01) write_header: 1, Amavis::Out::SMTP=HASH(0x7e659e0)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header encoded (all-ASCII): DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=\n\tmahendrasgroup.org; h=content-type:content-type:mime-version\n\t:user-agent:date:date:message-id:subject:subject:from:from:to;\n\t s=dkim; t=1451551707; x=1452415708; bh=GcvVHRglqftu3xK0lQwBxBZV\n\tpluLmIIteFPYD0bZnps=; b=Rhxs2KoOWyrYK1zCEV86KeQPvek2Lth6iVlihr5s\n\tO0vijSqFkPzs8a3F7PiZCli6HPtU2TNbjQbo5wbxg6HdIEW6enP+4nNe3IoMqlgo\n\t4Wy+65L+Tjx44AnLxRtC5QusDgkDnfzt6wGcGu/WlnLU7JwMrERpHAfBtKeMQoEL\n\tPXfYDXaHudkepIUU3opV0f0QnDOWw12bCq+X4I9pmK8v9vCR9Q5FTegDgS1LkWWZ\n\ti3Ad+aY4mwR1kqOD4HR0SZT0xAOSIOP3flK/08QGE3Vpe72cZ4K2zZoqtt+EkroF\n\tjdXpaS1XSYFDGkNvUokgU72ES/8GWlD51s7gYOV1XATRkw==
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=\n\tmahendrasgroup.org; h=content-type:content-type:mime-version\n\t:user-agent:date:date:message-id:subject:subject:from:from:to;\n\t s=dkim; t=1451551707; x=1452415708; bh=GcvVHRglqftu3xK0lQwBxBZV\n\tpluLmIIteFPYD0bZnps=; b=Rhxs2KoOWyrYK1zCEV86KeQPvek2Lth6iVlihr5s\n\tO0vijSqFkPzs8a3F7PiZCli6HPtU2TNbjQbo5wbxg6HdIEW6enP+4nNe3IoMqlgo\n\t4Wy+65L+Tjx44AnLxRtC5QusDgkDnfzt6wGcGu/WlnLU7JwMrERpHAfBtKeMQoEL\n\tPXfYDXaHudkepIUU3opV0f0QnDOWw12bCq+X4I9pmK8v9vCR9Q5FTegDgS1LkWWZ\n\ti3Ad+aY4mwR1kqOD4HR0SZT0xAOSIOP3flK/08QGE3Vpe72cZ4K2zZoqtt+EkroF\n\tjdXpaS1XSYFDGkNvUokgU72ES/8GWlD51s7gYOV1XATRkw==\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header encoded (all-ASCII): Authentication-Results: mail.mahendrasgroup.org (amavisd-new);\n dkim=pass\n reason="pass (just generated, assumed good)"\n header.d=mahendrasgroup.org
Dec 31 14:18:28 mail amavis[7142]: (07142-01) header: Authentication-Results: mail.mahendrasgroup.org (amavisd-new); dkim=pass\n\treason="pass (just generated, assumed good)"\n\theader.d=mahendrasgroup.org\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) about to connect to smtp:[127.0.0.1]:10025, VQrFXZ3q7qhB FWD from <testuser@localtest.com> -> <extuser@extdomain.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline fwd_init - deadline in 479.7 s, set to 480.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp session: setting up a new session
Dec 31 14:18:28 mail amavis[7142]: (07142-01) establish_or_refresh, state: down
Dec 31 14:18:28 mail amavis[7142]: (07142-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Dec 31 14:18:28 mail amavis[7142]: (07142-01) connected to [127.0.0.1]:10025 successfully
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Dec 31 14:18:28 mail postfix/smtpd[7175]: connect from mail.mahendrasgroup.org[127.0.0.1]
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop read 56 chars< 220 mail.mahendrasgroup.org ESMTP Postfix (Debian/GNU)\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp greeting: 220 mail.mahendrasgroup.org ESMTP Postfix (Debian/GNU), dt: 9.0 ms
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp cmd> EHLO mail.mahendrasgroup.org
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: sending 30 chars
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop sent 30> EHLO mail.mahendrasgroup.org\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop read 121 chars< 250-mail.mahendrasgroup.org\r\n250-PIPELINING\r\n250-SIZE 1048576\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp resp to EHLO: 250 mail.mahendrasgroup.org\nPIPELINING\nSIZE 1048576\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Dec 31 14:18:28 mail amavis[7142]: (07142-01) tls active=0, capable=, sec_level=0
Dec 31 14:18:28 mail amavis[7142]: (07142-01) Remote host presents itself as: mail.mahendrasgroup.org, handles DSN, PIPELINING, 8BITMIME
Dec 31 14:18:28 mail amavis[7142]: (07142-01) AUTH not needed, user='', MTA offers ''
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp cmd> MAIL FROM:<testuser@localtest.com> BODY=7BIT
Dec 31 14:18:28 mail amavis[7142]: (07142-01) orcpt_encode rfc822, extuser@extdomain.com, encode_for_smtp
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp cmd> RCPT TO:<extuser@extdomain.com> ORCPT=rfc822;extuser@extdomain.com
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp cmd> DATA
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: sending 133 chars
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop sent 133> MAIL FROM:<testuser@localtest.com> BODY=7BIT\r\nRCPT TO:<extuser@extdomain.com> ORCPT=rfc822;extuser@extdomain.com\r\nDATA\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Dec 31 14:18:28 mail postfix/smtpd[7175]: 36D4081FD8: client=mail.mahendrasgroup.org[127.0.0.1]
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail amavis[7142]: (07142-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
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp resp to RCPT (pip) (<extuser@extdomain.com>): 250 2.1.5 Ok
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x663e8b0)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=1, wr=1, timeout=180
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: sending 51537 chars
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop sent 51537> Authentication-Results: mail.mahendrasgroup.org (amavisd-new); dkim=pass\r\n\treason="pass (just generated, assumed good)"\r\n\theader.d=mahendrasgroup.org\r\nDKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simp [...]
Dec 31 14:18:28 mail postfix/cleanup[7164]: 36D4081FD8: message-id=<5684EB22.60905@localtest.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp connection_cache disabled, sending QUIT
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp cmd> QUIT
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.981
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: sending 33328 chars
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop sent 33328> 1oPfo9eIBeFIP0AaUycT056iG6hgzTW+B6p\r\nNnqazlIS9aVSo1F9d66RF9LT7Pk1ayp9JL8/JpyaQz8N49iZu2pVfCclo5U8epTa0n602NkI\r\nwPtmYRFO1Mqjd7RJ5iSjq/ED1+tvGcX0FDvFIX0jvUtnuINOjXcZS4xVxmpqSec0S8Meo5sx\r\nE7XGUiHNpdsxggp [...]
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.981
Dec 31 14:18:28 mail postfix/smtpd[7175]: disconnect from mail.mahendrasgroup.org[127.0.0.1]
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop: receiving
Dec 31 14:18:28 mail postfix/qmgr[1609]: 36D4081FD8: from=<testuser@localtest.com>, size=85070, nrcpt=1 (queue active)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rw_loop read 51 chars< 250 2.0.0 Ok: queued as 36D4081FD8\r\n221 2.0.0 Bye\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) smtp resp to data-dot (<extuser@extdomain.com>): 250 2.0.0 Ok: queued as 36D4081FD8, dt: 24.3 ms
Dec 31 14:18:28 mail amavis[7142]: (07142-01) Amavis::Out::SMTP::Session close, disconnecting
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline fwd-end-chkpnt - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) VQrFXZ3q7qhB FWD from <testuser@localtest.com> -> <extuser@extdomain.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 36D4081FD8
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline forwarding - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer forwarding: timer 288, was 288, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) DSN: sender is credible (orig), SA: -1.000, <testuser@localtest.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "testuser@localtest.com" does not match
Dec 31 14:18:28 mail amavis[7142]: (07142-01) dsn: from MTA 250 NonBlocking:Clean <testuser@localtest.com> -> <extuser@extdomain.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 36D4081FD8"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <testuser@localtest.com> -> <extuser@extdomain.com>
Dec 31 14:18:28 mail amavis[7142]: (07142-01) delivery_status_notification: notif 0 bytes, suppressed: no
Dec 31 14:18:28 mail amavis[7142]: (07142-01) one_response_for_all, per_recip_capable: N, suppressed: N
Dec 31 14:18:28 mail amavis[7142]: (07142-01) one_response_for_all <testuser@localtest.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 36D4081FD8'
Dec 31 14:18:28 mail amavis[7142]: (07142-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 36D4081FD8
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline delivery-notification - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInternal,RelayedUntaggedOriginating}
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline snmp-counters - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) orcpt_encode rfc822, extuser@extdomain.com, smtputf8
Dec 31 14:18:28 mail amavis[7142]: (07142-01) Passed CLEAN {RelayedInternal}, MYNETS/MYUSERS LOCAL [172.25.12.1]:52752 <testuser@localtest.com> -> <extuser@extdomain.com>, Queue-ID: C850D81C1C, Message-ID: <5684EB22.60905@localtest.com>, mail_id: VQrFXZ3q7qhB, Hits: -1, size: 83768, queued_as: 36D4081FD8, dkim_new=dkim:mahendrasgroup.org, 397 ms
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline main_log_entry - deadline in 479.7 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.7 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) sql begin transaction
Dec 31 14:18:28 mail amavis[7142]: (07142-01) sql: preparing and executing (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) save_info_final VQrFXZ3q7qhB, orig=Y, chks=VSHB, cont.ty=C, q.type= , q.to=, dsn=N, score=-1, Message-ID: <5684EB22.60905@localtest.com>, From: '"Test.User" <testuser@localtest.com>', Subject: 'Attachement test - 4'
Dec 31 14:18:28 mail amavis[7142]: (07142-01) sql: preparing and executing (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
Dec 31 14:18:28 mail amavis[7142]: (07142-01) sql commit
Dec 31 14:18:28 mail amavis[7142]: (07142-01) TIMING-SA total 135 ms - parse: 4.2 (3.1%), extract_message_metadata: 7 (4.8%), get_uri_detail_list: 0.25 (0.2%), tests_pri_-1000: 5.0 (3.7%), tests_pri_-950: 1.71 (1.3%), tests_pri_-900: 1.32 (1.0%), tests_pri_-400: 0.98 (0.7%), tests_pri_0: 43 (31.9%), check_spf: 0.40 (0.3%), check_dkim_adsp: 5 (4.0%), check_pyzor: 0.20 (0.1%), tests_pri_500: 3.6 (2.7%), learn: 50 (36.9%), b_learn: 47 (35.2%), b_count_change: 4.9 (3.6%), get_report: 0.36 (0.3%)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) updating snmp variables in BDB
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline check done - deadline in 479.6 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer check done: timer 288, was 288, deadline in 479.6 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 36D4081FD8"
Dec 31 14:18:28 mail amavis[7142]: (07142-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 36D4081FD8
Dec 31 14:18:28 mail amavis[7142]: (07142-01) switch_to_client_time 480 s, smtp response sent
Dec 31 14:18:28 mail postfix/smtp[7169]: C850D81C1C: to=<extuser@extdomain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.49, delays=0.05/0.01/0.01/0.41, 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 36D4081FD8)
Dec 31 14:18:28 mail amavis[7142]: (07142-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29
Dec 31 14:18:28 mail amavis[7142]: (07142-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20151231T141827-07142-iiGrcg29/parts, excl=1
Dec 31 14:18:28 mail postfix/qmgr[1609]: C850D81C1C: removed
Dec 31 14:18:28 mail amavis[7142]: (07142-01) size: 83768, TIMING [total 423 ms] - sql-prepare: 4.1 (1%)1, SMTP greeting: 2.4 (1%)2, SMTP EHLO: 1.4 (0%)2, SMTP pre-MAIL: 6 (1%)3, mkdir tempdir: 1.3 (0%)4, create email.txt: 0.3 (0%)4, sql-connect: 8 (2%)6, lookup_sql: 1.0 (0%)6, lookup_sql: 3.6 (1%)7, SMTP pre-DATA-flush: 3.1 (1%)7, SMTP DATA: 17 (4%)11, check_init: 0.6 (0%)11, digest_hdr: 2.2 (1%)12, digest_body_dkim: 1.1 (0%)12, collect_info: 2.1 (0%)13, gen_mail_id: 34 (8%)21, mkdir parts: 2.5 (1%)21, mime_decode: 16 (4%)25, get-file-type2: 19 (4%)30, parts_decode: 0.5 (0%)30, check_header: 1.2 (0%)30, AV-scan-1: 41 (10%)40, spam-wb-list: 1.9 (0%)40, SA msg read: 0.9 (0%)41, SA parse: 6 (1%)42, SA check: 129 (30%)72, decide_mail_destiny: 5 (1%)74, notif-quar: 0.4 (0%)74, write-header: 12 (3%)77, fwd-data-dkim: 16 (4%)80, fwd-connect: 16 (4%)84, fwd-mail-pip: 6 (1%)85, fwd-rcpt-pip: 0.2 (0%)86, fwd-data-chkpnt: 0.1 (0%)86, write-header: 0.5 (0%)86, fwd-data-contents: 1.2 (0%)86, fwd-end-chkpnt: 2...
Dec 31 14:18:28 mail amavis[7142]: (07142-01) ...5 (6%)92, prepare-dsn: 1.4 (0%)92, report: 2.0 (0%)93, main_log_entry: 5 (1%)94, sql-update: 20 (5%)99, update_snmp: 2.9 (1%)100, SMTP pre-response: 0.5 (0%)100, SMTP response: 0.3 (0%)100, unlink-2-files: 0.3 (0%)100, rundown: 0.8 (0%)100
Dec 31 14:18:28 mail amavis[7142]: (07142-01) idle_proc, 6: was busy, 394.3 ms, total idle 0.001 s, busy 0.422 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.422 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) ESMTP< QUIT\r\n
Dec 31 14:18:28 mail amavis[7142]: (07142-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Dec 31 14:18:28 mail amavis[7142]: (07142-01) switch_to_client_time 480 s, smtp response sent
Dec 31 14:18:28 mail amavis[7142]: (07142-01) SMTP session over, timer stopped
Dec 31 14:18:28 mail amavis[7142]: (07142-01) exiting process_request
Dec 31 14:18:28 mail amavis[7142]: (07142-01) idle_proc, bye: was busy, 2.3 ms, total idle 0.001 s, busy 0.425 s
Dec 31 14:18:28 mail amavis[7142]: (07142-01) load: 100 %, total idle 0.001 s, busy 0.425 s
Dec 31 14:18:37 mail postfix/smtp[7176]: 36D4081FD8: to=<extuser@extdomain.com>, relay=mail.extdomain.com[xx.xx.x.xx]:25, delay=9.7, delays=0.03/0.01/2/7.7, dsn=2.0.0, status=sent (250 OK)
Dec 31 14:18:38 mail postfix/qmgr[1609]: 36D4081FD8: removed