gistfile1.txt

root@alpha:~# cat amavis_debug.log 
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP< MAIL FROM:<user@example.com> SIZE=14541\r\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_mail_begin_task: task_count=3
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_ip_acl arr.obj: key="208.65.145.68", no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [debug_sender] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP> 250 2.1.0 Sender <user@example.com> OK
May 21 12:17:17 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, smtp response sent
May 21 12:17:17 alpha amavis[1201]: (01201-03) idle_proc, 6: was busy, 1.5 ms, total idle 11.419 s, busy 2.600 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) idle_proc, 5: was idle, 0.1 ms, total idle 11.419 s, busy 2.600 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP< RCPT TO:<admin@domain.org> ORCPT=rfc822;admin@domain.org\r\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup => undef, "admin@domain.org", no lookup tables
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_acl(admin@domain.org), no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [local_domains] => undef, "admin@domain.org" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) query_keys: admin@domain.org, @domain.org, @.domain.org, @.org, @.
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql sel_policy "admin@domain.org", query args: [admin@domain.org,12], [@domain.org,12], [@.domain.org,12], [@.org,12], [@.,12]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql select: SELECT *,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql begin, nontransaction
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql: executing clause: SELECT *,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql(admin@domain.org) matches, result=(id=>"2", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"10", policy_id=>"5", email=>"admin@domain.org", fullname=>"admin@domain.org", local=>"Y", id=>"2", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", policy_name=>"Normal", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", spam_modifies_subj=>"Y", virus_quarantine_to=>"", spam_quarantine_to=>"", banned_quarantine_to=>"", bad_header_quarantine_to=>"", clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"1", spam_tag2_level=>"4.5", spam_kill_level=>"50", spam_dsn_cutoff_level=>"0", spam_quarantine_cutoff_level=>"0", addr_extension_virus=>"", addr_extension_spam=>"", addr_exte...
May 21 12:17:17 alpha amavis[1201]: (01201-03) ...nsion_banned=>"", addr_extension_bad_header=>"", warnvirusrecip=>"N", warnbannedrecip=>"N", warnbadhrecip=>"N", newvirus_admin=>"", virus_admin=>"", banned_admin=>"", bad_header_admin=>"", spam_admin=>"", spam_subject_tag=>"", spam_subject_tag2=>"***SPAM***", message_size_limit=>"20000000", banned_rulenames=>"", policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1", policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"2")
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql(admin@domain.org) matches, result=(id=>"1", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"5", policy_id=>"5", email=>"@domain.org", fullname=>"@domain.org", local=>"Y", id=>"1", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", policy_name=>"Normal", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", spam_modifies_subj=>"Y", virus_quarantine_to=>"", spam_quarantine_to=>"", banned_quarantine_to=>"", bad_header_quarantine_to=>"", clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"1", spam_tag2_level=>"4.5", spam_kill_level=>"50", spam_dsn_cutoff_level=>"0", spam_quarantine_cutoff_level=>"0", addr_extension_virus=>"", addr_extension_spam=>"", addr_extension_banne...
May 21 12:17:17 alpha amavis[1201]: (01201-03) ...d=>"", addr_extension_bad_header=>"", warnvirusrecip=>"N", warnbannedrecip=>"N", warnbadhrecip=>"N", newvirus_admin=>"", virus_admin=>"", banned_admin=>"", bad_header_admin=>"", spam_admin=>"", spam_subject_tag=>"", spam_subject_tag2=>"***SPAM***", message_size_limit=>"20000000", banned_rulenames=>"", policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1", policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"1")
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(message_size_limit) rec=0, "admin@domain.org" result: "20000000"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [message_size_limit] => true,  "admin@domain.org" matches, result="20000000", matching_key="id=>"2", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"10", policy_id=>"5", email=>"admin@domain.org", fullname=>"admin@domain.org", local=>"Y", id=>"2", sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", policy_name=>"Normal", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", spam_modifies_subj=>"Y", virus_quarantine_to=>"", spam_quarantine_to=>"", banned_quarantine_to=>"", bad_header_quarantine_to=>"", clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"1", spam_tag2_level=>"4.5", spam_kill_level=>"50", spam_dsn_cutoff_level=>"0", spam_quarantine_cutoff_level=>"0", addr_ex...
May 21 12:17:17 alpha amavis[1201]: (01201-03) ...tension_virus=>"", addr_extension_spam=>"", addr_extension_banned=>"", addr_extension_bad_header=>"", warnvirusrecip=>"N", warnbannedrecip=>"N", warnbadhrecip=>"N", newvirus_admin=>"", virus_admin=>"", banned_admin=>"", bad_header_admin=>"", spam_admin=>"", spam_subject_tag=>"", spam_subject_tag2=>"***SPAM***", message_size_limit=>"20000000", banned_rulenames=>"", policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1", policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"2""
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP> 250 2.1.5 Recipient <admin@domain.org> OK
May 21 12:17:17 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, smtp response sent
May 21 12:17:17 alpha amavis[1201]: (01201-03) idle_proc, 6: was busy, 3.7 ms, total idle 11.419 s, busy 2.604 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) idle_proc, 5: was idle, 0.1 ms, total idle 11.420 s, busy 2.604 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP< DATA\r\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP::10024 /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L: <user@example.com> -> <admin@domain.org> SIZE=14541 Received: from alpha.domain.org ([127.0.0.1]) by localhost (alpha.domain.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <admin@domain.org>; Wed, 21 May 2014 12:17:17 -0400 (EDT)
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP> 354 End data with <CR><LF>.<CR><LF>
May 21 12:17:17 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, smtp response sent
May 21 12:17:17 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, receiving data
May 21 12:17:17 alpha amavis[1201]: (01201-03) enforcing size limit 20000000 during DATA
May 21 12:17:17 alpha amavis[1201]: (01201-03) smtp copy: read 14516 bytes into buffer, new size: 14516
May 21 12:17:17 alpha amavis[1201]: (01201-03) smtp copy: 6 bytes still buffered at end
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) ESMTP< .<CR><LF>
May 21 12:17:17 alpha amavis[1201]: (01201-03) Actual message size 14507 B less than the declared 14541 B
May 21 12:17:17 alpha amavis[1201]: (01201-03) smtp connection cache, dt: 11.4, state: 1
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_body_digest: reading header section
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_body_digest: reading mail body
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
May 21 12:17:17 alpha amavis[1201]: (01201-03) body hash: 176c9156018d337b1e409dde40973810
May 21 12:17:17 alpha amavis[1201]: (01201-03) Original mail size: 14507; quota set to: 7253500 bytes
May 21 12:17:17 alpha amavis[1201]: (01201-03) Checking: Z7q6sIQtQSQW [208.65.145.68] <user@example.com> -> <admin@domain.org>
May 21 12:17:17 alpha amavis[1201]: (01201-03) 2822.From: <user@example.com>
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(local) rec=0, "admin@domain.org" result: "Y"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [local_domains] => true,  "admin@domain.org" matches, result="Y", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(bypass_virus_checks) rec=0, "admin@domain.org" result: "0"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [bypass_virus_checks] => false, "admin@domain.org" matches, result="0", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(bypass_banned_checks) rec=0, "admin@domain.org" result: "0"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [bypass_banned_checks] => false, "admin@domain.org" matches, result="0", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(bypass_spam_checks) rec=0, "admin@domain.org" result: "0"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [bypass_spam_checks] => false, "admin@domain.org" matches, result="0", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(id) rec=0, "admin@domain.org" result: "2"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(id) rec=1, "admin@domain.org" result: "1"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [users.id], 2 matches for "admin@domain.org", results: "/cached/"=>"2", "/cached/"=>"1"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(policy_id) rec=0, "admin@domain.org" result: "5"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [users.policy_id] => true,  "admin@domain.org" matches, result="5", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) Extracting mime components
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new file name: p001
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new file name: p002
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new file name: p003
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new file name: p004
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new pseudo part: p005
May 21 12:17:17 alpha amavis[1201]: (01201-03) p005 1 Content-Type: multipart/related
May 21 12:17:17 alpha amavis[1201]: (01201-03) Issued a new pseudo part: p006
May 21 12:17:17 alpha amavis[1201]: (01201-03) p006 1/1 Content-Type: multipart/alternative
May 21 12:17:17 alpha amavis[1201]: (01201-03) Charging 613 bytes to remaining quota 7253500 (out of 7253500, (0%)) - by mime_decode
May 21 12:17:17 alpha amavis[1201]: (01201-03) p001 1/1/1 Content-Type: text/plain, size: 613 B, name: 
May 21 12:17:17 alpha amavis[1201]: (01201-03) reparenting p001 from p000 to p006
May 21 12:17:17 alpha amavis[1201]: (01201-03) Charging 5332 bytes to remaining quota 7252887 (out of 7253500, (0%)) - by mime_decode
May 21 12:17:17 alpha amavis[1201]: (01201-03) p002 1/1/2 Content-Type: text/html, size: 5332 B, name: 
May 21 12:17:17 alpha amavis[1201]: (01201-03) reparenting p002 from p000 to p006
May 21 12:17:17 alpha amavis[1201]: (01201-03) Charging 388 bytes to remaining quota 7247555 (out of 7253500, (0%)) - by mime_decode
May 21 12:17:17 alpha amavis[1201]: (01201-03) p003 1/2 Content-Type: image/jpeg, size: 388 B, name: image001.jpg
May 21 12:17:17 alpha amavis[1201]: (01201-03) reparenting p003 from p000 to p005
May 21 12:17:17 alpha amavis[1201]: (01201-03) Charging 3007 bytes to remaining quota 7247167 (out of 7253500, (0%)) - by mime_decode
May 21 12:17:17 alpha amavis[1201]: (01201-03) p004 1/3 Content-Type: image/png, size: 3007 B, name: image002.png
May 21 12:17:17 alpha amavis[1201]: (01201-03) reparenting p004 from p000 to p005
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline mime_decode - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer mime_decode: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline mime_decode-1 - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer mime_decode-1: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) decode_parts: level=1, #parts=6 : p001, p002, p003, p004, p005, ...
May 21 12:17:17 alpha amavis[1201]: (01201-03) running file(1) on 4 files, arglist size 33
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_command: [1338] /usr/bin/file p001 p002 p003 p004 </dev/null 2>&1
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: target fd0 closing, to become < /dev/null
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: target fd1 closing, to become > &=17
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: target fd1 dup2 from fd17 > &=17
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: source fd17 closed
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: target fd2 closing, to become > &1
May 21 12:17:17 alpha amavis[1338]: (01201-03) open_on_specific_fd: target fd2 dup2 from fd1 > &1
May 21 12:17:17 alpha amavis[1201]: (01201-03) result line from file(1): p001: ASCII text, with very long lines\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("ASCII text, with very long lines") matches key "(?^i:^(ASCII|text)\b)", result="asc"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [map_full_type_to_short_type] => true,  "ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
May 21 12:17:17 alpha amavis[1201]: (01201-03) File-type of p001: ASCII text, with very long lines; (asc)
May 21 12:17:17 alpha amavis[1201]: (01201-03) result line from file(1): p002: HTML document, ASCII text, with very long lines\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("HTML document, ASCII text, with very long lines") matches key "(?^i:\btext\b)", result="asc"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [map_full_type_to_short_type] => true,  "HTML document, ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:\\btext\\b)"
May 21 12:17:17 alpha amavis[1201]: (01201-03) File-type of p002: HTML document, ASCII text, with very long lines; (asc)
May 21 12:17:17 alpha amavis[1201]: (01201-03) result line from file(1): p003: JPEG image data, JFIF standard 1.01\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("JPEG image data, JFIF standard 1.01") matches key "(?^:^JPEG image data\b)", result=["image","jpg"]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [map_full_type_to_short_type] => true,  "JPEG image data, JFIF standard 1.01" matches, result=["image","jpg"], matching_key="(?^:^JPEG image data\\b)"
May 21 12:17:17 alpha amavis[1201]: (01201-03) File-type of p003: JPEG image data, JFIF standard 1.01; (image, jpg)
May 21 12:17:17 alpha amavis[1201]: (01201-03) result line from file(1): p004: PNG image data, 101 x 28, 8-bit/color RGBA, non-interlaced\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("PNG image data, 101 x 28, 8-bit/color RGBA, non-interlaced") matches key "(?^:^PNG image data\b)", result=["image","png"]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [map_full_type_to_short_type] => true,  "PNG image data, 101 x 28, 8-bit/color RGBA, non-interlaced" matches, result=["image","png"], matching_key="(?^:^PNG image data\\b)"
May 21 12:17:17 alpha amavis[1201]: (01201-03) File-type of p004: PNG image data, 101 x 28, 8-bit/color RGBA, non-interlaced; (image, png)
May 21 12:17:17 alpha amavis[1201]: (01201-03) decompose_part: p001 - atomic
May 21 12:17:17 alpha amavis[1201]: (01201-03) decompose_part: p002 - atomic
May 21 12:17:17 alpha amavis[1201]: (01201-03) decompose_part: p003 - atomic
May 21 12:17:17 alpha amavis[1201]: (01201-03) decompose_part: p004 - atomic
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline parts_decode - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer parts_decode: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(bypass_header_checks) rec=0, "admin@domain.org" result: "0"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [bypass_header_checks] => false, "admin@domain.org" matches, result="0", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_header: 0, OK
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(bypass_header_checks) rec=0, "admin@domain.org" result: "0"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [bypass_header_checks] => false, "admin@domain.org" matches, result="0", matching_key="/cached/"
May 21 12:17:17 alpha amavis[1201]: (01201-03) Checking for banned types and filenames
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(banned_rulenames) rec=0, "admin@domain.org" result: ""
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(banned_rulenames) rec=1, "admin@domain.org" result: ""
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup: (scalar) matches, result="DEFAULT"
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [banned_filename], 3 matches for "admin@domain.org", results: "/cached/"=>"", "/cached/"=>"", "(constant:DEFAULT)"=>"DEFAULT"
May 21 12:17:17 alpha amavis[1201]: (01201-03) collect banned table[0]: admin@domain.org, tables: 
May 21 12:17:17 alpha amavis[1201]: (01201-03) collect banned table[1]: admin@domain.org, tables: 
May 21 12:17:17 alpha amavis[1201]: (01201-03) collect banned table[2]: admin@domain.org, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x2b326a0)
May 21 12:17:17 alpha amavis[1201]: (01201-03) starting banned checks - traversing message structure tree
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_for_banned (p005,p003) multipart/related | image/jpeg,.image,.jpg,image001.jpg
May 21 12:17:17 alpha amavis[1201]: (01201-03) doing banned check for admin@domain.org on multipart/related | image/jpeg,.image,.jpg,image001.jpg
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re(["multipart/related","image/jpeg",".image",".jpg","image001.jpg"]), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [check_bann:admin@domain.org] => undef, ["multipart/related","image/jpeg",".image",".jpg","image001.jpg"] does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [banned_namepath_re] => undef, "P=p005\tL=1\tM=multipart/related\nP=p003\tL=1/2\tM=image/jpeg\tT=image\tT=jpg\tN=image001.jpg" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) p.path admin@domain.org: "P=p005,L=1,M=multipart/related | P=p003,L=1/2,M=image/jpeg,T=image,T=jpg,N=image001.jpg"
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_for_banned (p005,p004) multipart/related | image/png,.image,.png,image002.png
May 21 12:17:17 alpha amavis[1201]: (01201-03) doing banned check for admin@domain.org on multipart/related | image/png,.image,.png,image002.png
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re(["multipart/related","image/png",".image",".png","image002.png"]), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [check_bann:admin@domain.org] => undef, ["multipart/related","image/png",".image",".png","image002.png"] does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [banned_namepath_re] => undef, "P=p005\tL=1\tM=multipart/related\nP=p004\tL=1/3\tM=image/png\tT=image\tT=png\tN=image002.png" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) p.path admin@domain.org: "P=p005,L=1,M=multipart/related | P=p004,L=1/3,M=image/png,T=image,T=png,N=image002.png"
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_for_banned (p005,p006,p001) multipart/related | multipart/alternative | text/plain,.asc
May 21 12:17:17 alpha amavis[1201]: (01201-03) doing banned check for admin@domain.org on multipart/related | multipart/alternative | text/plain,.asc
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re(["multipart/related","multipart/alternative","text/plain",".asc"]), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [check_bann:admin@domain.org] => undef, ["multipart/related","multipart/alternative","text/plain",".asc"] does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [banned_namepath_re] => undef, "P=p005\tL=1\tM=multipart/related\nP=p006\tL=1/1\tM=multipart/alternative\nP=p001\tL=1/1/1\tM=text/plain\tT=asc" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) p.path admin@domain.org: "P=p005,L=1,M=multipart/related | P=p006,L=1/1,M=multipart/alternative | P=p001,L=1/1/1,M=text/plain,T=asc"
May 21 12:17:17 alpha amavis[1201]: (01201-03) check_for_banned (p005,p006,p002) multipart/related | multipart/alternative | text/html,.asc
May 21 12:17:17 alpha amavis[1201]: (01201-03) doing banned check for admin@domain.org on multipart/related | multipart/alternative | text/html,.asc
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re(["multipart/related","multipart/alternative","text/html",".asc"]), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [check_bann:admin@domain.org] => undef, ["multipart/related","multipart/alternative","text/html",".asc"] does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [banned_namepath_re] => undef, "P=p005\tL=1\tM=multipart/related\nP=p006\tL=1/1\tM=multipart/alternative\nP=p002\tL=1/1/2\tM=text/html\tT=asc" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) p.path admin@domain.org: "P=p005,L=1,M=multipart/related | P=p006,L=1/1,M=multipart/alternative | P=p002,L=1/1/2,M=text/html,T=asc"
May 21 12:17:17 alpha amavis[1201]: (01201-03) banned check: any=0, all=N (1)
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("MAIL"), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [keep_decoded_original] => undef, "MAIL" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) Calling virus scanners, 4 files to scan in /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts
May 21 12:17:17 alpha amavis[1201]: (01201-03) invoking av-scanner ClamAV-clamd
May 21 12:17:17 alpha amavis[1201]: (01201-03) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_av (ClamAV-clamd): query template(1,3): CONTSCAN {}\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline run_av_pre - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer run_av_pre: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline run_av_scan - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer run_av_scan: timer 336, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) ClamAV-clamd: Connecting to socket  /var/run/clamav/clamd.ctl
May 21 12:17:17 alpha amavis[1201]: (01201-03) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout 10
May 21 12:17:17 alpha amavis[1201]: (01201-03) connected to /var/run/clamav/clamd.ctl successfully
May 21 12:17:17 alpha amavis[1201]: (01201-03) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts\n to socket /var/run/clamav/clamd.ctl
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: needline=0, flush=1, wr=1, timeout=10
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: sending
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 480.0 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: needline=0, flush=0, wr=0, timeout=335.999
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: receiving
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts: OK\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: needline=0, flush=0, wr=0, timeout=335.999
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop: receiving
May 21 12:17:17 alpha amavis[1201]: (01201-03) rw_loop read: got eof
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.9 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline run_av_3 - deadline in 479.9 s, set to 336.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer run_av_3: timer 336, was 336, deadline in 479.9 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts: OK\n
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_av (ClamAV-clamd): CLEAN
May 21 12:17:17 alpha amavis[1201]: (01201-03) run_av (ClamAV-clamd) result: clean
May 21 12:17:17 alpha amavis[1201]: (01201-03) wbl: checking sender <user@example.com>
May 21 12:17:17 alpha amavis[1201]: (01201-03) wbl: (SQL) recip <admin@domain.org>, 2 matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_acl(user@example.com), no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [local_domains] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) query_keys: user@example.com, @example.com, @.example.com, @.com, @.
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql sel_wblist "user@example.com", query args: "2", [user@example.com,12], [@example.com,12], [@.example.com,12], [@.com,12], [@.,12]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql begin, nontransaction
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql: preparing and executing: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql, "user@example.com" no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(wb), "user@example.com" no matching records
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) wbl: (SQL) recip <admin@domain.org>, rid=2, got: ""
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_acl(user@example.com), no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [local_domains] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) query_keys: user@example.com, @example.com, @.example.com, @.com, @.
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql sel_wblist "user@example.com", query args: "1", [user@example.com,12], [@example.com,12], [@.example.com,12], [@.com,12], [@.,12]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql begin, nontransaction
May 21 12:17:17 alpha amavis[1201]: (01201-03) sql: executing clause: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql, "user@example.com" no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(wb), "user@example.com" no matching records
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) wbl: (SQL) recip <admin@domain.org>, rid=1, got: ""
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [blacklist_recip<admin@domain.org>] => undef, "admin@domain.org" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [blacklist_sender<user@example.com>,blacklist_sender] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [whitelist_recip<admin@domain.org>] => undef, "admin@domain.org" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_acl(user@example.com), no match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [whitelist_sender<user@example.com>,whitelist_sender] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) query_keys: admin@domain.org, admin@, domain.org, .domain.org, .org, .
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_hash(admin@domain.org) matches keys: "."=>ARRAY(0x2f4bd68)
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [score_recip<admin@domain.org>,score_sender], 1 matches for "admin@domain.org", results: "."=>[Amavis::Lookup::RE=ARRAY(0x2f4bed0),{}]
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_re("user@example.com"), no matches
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [score_sender<user@example.com>] => undef, "user@example.com" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) SpamControl: calling spam scanner SpamAssassin
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) prolong_timer spam_scan_sa_pre: timer 476, was 336, deadline in 479.9 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(sa_userconf) rec=0, "admin@domain.org" result: undef
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(sa_userconf) rec=1, "admin@domain.org" result: undef
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field, no such fields: sa_userconf
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [sa_userconf] => undef, "admin@domain.org" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(sa_username) rec=0, "admin@domain.org" result: undef
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field(sa_username) rec=1, "admin@domain.org" result: undef
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup_sql_field, no such fields: sa_username
May 21 12:17:17 alpha amavis[1201]: (01201-03) lookup [sa_username] => undef, "admin@domain.org" does not match
May 21 12:17:17 alpha amavis[1201]: (01201-03) SA user config: "", username: "amavis", 0
May 21 12:17:17 alpha amavis[1201]: (01201-03) calling SA parse (0), SA vers 3.4.0, 3.004000, data as GLOB, recips_ind [0], user: "amavis"
May 21 12:17:17 alpha amavis[1201]: (01201-03) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
May 21 12:17:17 alpha amavis[1201]: (01201-03) CALLING SA check (0)
May 21 12:17:18 alpha amavis[1201]: (01201-03) DONE SA check (0)
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline spam_scan_sa - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer spam_scan_sa: timer 336, was 475, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) spam_scan: score=-1.919 autolearn=ham autolearn_force=no tests=[BAYES_00=-1.9,HTML_MESSAGE=0.001,RCVD_IN_MSPIKE_H3=-0.01,RCVD_IN_MSPIKE_WL=-0.01] recips=0
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline spam_scan - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer spam_scan: timer 336, was 336, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag_level) rec=0, "admin@domain.org" result: "1"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_tag_level] => true,  "admin@domain.org" matches, result="1", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag2_level) rec=0, "admin@domain.org" result: "4.5"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_tag2_level] => true,  "admin@domain.org" matches, result="4.5", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag3_level) rec=0, "admin@domain.org" result: undef
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag3_level) rec=1, "admin@domain.org" result: undef
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field, no such fields: spam_tag3_level
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_tag3_level] => undef, "admin@domain.org" does not match
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_kill_level) rec=0, "admin@domain.org" result: "50"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_kill_level] => true,  "admin@domain.org" matches, result="50", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(message_size_limit) rec=0, "admin@domain.org" result: "20000000"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [message_size_limit] => true,  "admin@domain.org" matches, result="20000000", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) final_destiny (ccat=0) is PASS, recip admin@domain.org
May 21 12:17:18 alpha amavis[1201]: (01201-03) final_destiny PASS, recip admin@domain.org
May 21 12:17:18 alpha amavis[1201]: (01201-03) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May 21 12:17:18 alpha amavis[1201]: (01201-03) do_notify_and_quarantine: not quarantining, q_method off
May 21 12:17:18 alpha amavis[1201]: (01201-03) skip admin notification, no administrators
May 21 12:17:18 alpha amavis[1201]: (01201-03) do_notify_and_quarantine - done
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(forward_method) rec=0, "admin@domain.org" result: undef
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(forward_method) rec=1, "admin@domain.org" result: undef
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field, no such fields: forward_method
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [forward_method] => true,  "admin@domain.org" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
May 21 12:17:18 alpha amavis[1201]: (01201-03) delivery method is smtp:[127.0.0.1]:10025, recips: admin@domain.org
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag_level) rec=0, "admin@domain.org" result: "1"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_tag_level] => true,  "admin@domain.org" matches, result="1", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_sql_field(spam_tag2_level) rec=0, "admin@domain.org" result: "4.5"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_tag2_level] => true,  "admin@domain.org" matches, result="4.5", matching_key="/cached/"
May 21 12:17:18 alpha amavis[1201]: (01201-03) headers CLUSTERING: NEW CLUSTER <admin@domain.org>: score=-1.919, tag=0, tag2=0, local=1, bl=, s=, mangle=
May 21 12:17:18 alpha amavis[1201]: (01201-03) header: X-Virus-Scanned: Debian amavisd-new at alpha.domain.org\n
May 21 12:17:18 alpha amavis[1201]: (01201-03) fwd: scanner provided X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
May 21 12:17:18 alpha amavis[1201]: (01201-03) fwd: scanner provided X-Spam-Level, but we preferred our own
May 21 12:17:18 alpha amavis[1201]: (01201-03) fwd: scanner provided X-Spam-Status, but we preferred our own
May 21 12:17:18 alpha amavis[1201]: (01201-03) header: Received: from alpha.domain.org ([127.0.0.1])\n\tby localhost (alpha.domain.org [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id Z7q6sIQtQSQW for <admin@domain.org>;\n\tWed, 21 May 2014 12:17:17 -0400 (EDT)\n
May 21 12:17:18 alpha amavis[1201]: (01201-03) headers CLUSTERING: done all 1 recips in one go
May 21 12:17:18 alpha amavis[1201]: (01201-03) about to connect to smtp:[127.0.0.1]:10025, FWD from <user@example.com> -> <admin@domain.org>
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline fwd_init - deadline in 478.8 s, set to 479.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp session reuse (smtp:[127.0.0.1]:10025), 2 transactions so far
May 21 12:17:18 alpha amavis[1201]: (01201-03) establish_or_refresh, state: ehlo
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp session most likely still valid (short idle 12.7 s)
May 21 12:17:18 alpha amavis[1201]: (01201-03) Remote host presents itself as: alpha.domain.org, handles DSN, handles PIPELINING
May 21 12:17:18 alpha amavis[1201]: (01201-03) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp cmd> MAIL FROM:<user@example.com> BODY=7BIT
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp cmd> RCPT TO:<admin@domain.org> ORCPT=rfc822;admin@domain.org
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp cmd> DATA
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: needline=0, flush=1, wr=1, timeout=120
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: sending
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop sent 104> MAIL FROM:<user@example.com> BODY=7BIT\r\nRCPT TO:<admin@domain.org> ORCPT=rfc822;admin@domain.org\r\nDATA\r\n
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: needline=1, flush=0, wr=0, timeout=300
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: receiving
May 21 12:17:18 alpha amavis[1201]: (01201-03) 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
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp resp to MAIL (pip): 250 2.1.0 Ok
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp resp to RCPT (pip) (<admin@domain.org>): 250 2.1.5 Ok
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
May 21 12:17:18 alpha amavis[1201]: (01201-03) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x740bf78)
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: needline=1, flush=0, wr=1, timeout=478.992
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: sending
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop sent 14775> X-Virus-Scanned: Debian amavisd-new at alpha.domain.org\r\nReceived: from alpha.domain.org ([127.0.0.1])\r\n\tby localhost (alpha.domain.org [127.0.0.1]) (amavisd-new, port 10024)\r\n\twith ESMTP id Z7q6sIQtQSQW [...]
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: needline=1, flush=0, wr=0, timeout=478.992
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop: receiving
May 21 12:17:18 alpha amavis[1201]: (01201-03) rw_loop read 37 chars< 250 2.0.0 Ok: queued as CAB67660123\r\n
May 21 12:17:18 alpha amavis[1201]: (01201-03) smtp resp to data-dot (<admin@domain.org>): 250 2.0.0 Ok: queued as CAB67660123
May 21 12:17:18 alpha amavis[1201]: (01201-03) Amavis::Out::SMTP::Session close, keeping connection
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline fwd-end-chkpnt - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) FWD from <user@example.com> -> <admin@domain.org>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as CAB67660123
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline forwarding - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer forwarding: timer 336, was 336, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) DSN: sender NOT credible, SA: -1.919, <user@example.com>
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup: (scalar) matches, result="100"
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup [spam_dsn_cutoff_level_bysender] => true,  "user@example.com" matches, result="100", matching_key="(constant:100)"
May 21 12:17:18 alpha amavis[1201]: (01201-03) dsn: from MTA 250 NonBlocking:Clean <user@example.com> -> <admin@domain.org>: 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 CAB67660123"
May 21 12:17:18 alpha amavis[1201]: (01201-03) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <user@example.com> -> <admin@domain.org>
May 21 12:17:18 alpha amavis[1201]: (01201-03) one_response_for_all <user@example.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 CAB67660123'
May 21 12:17:18 alpha amavis[1201]: (01201-03) 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 CAB67660123
May 21 12:17:18 alpha amavis[1201]: (01201-03) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline delivery-notification - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer delivery-notification: timer 336, was 336, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) fish_out_ip_from_received: 10.250.250.206
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_ip_acl (publicnetworks) arr.obj: key="10.250.250.206" matches "!10.0.0.0/8", result=0
May 21 12:17:18 alpha amavis[1201]: (01201-03) fish_out_ip_from_received: 198.207.145.29
May 21 12:17:18 alpha amavis[1201]: (01201-03) lookup_ip_acl (publicnetworks) arr.obj: key="198.207.145.29" matches "::FFFF:0:0/96", result=1
May 21 12:17:18 alpha amavis[1201]: (01201-03) parse_ip_address_from_received: 198.207.145.29
May 21 12:17:18 alpha amavis[1201]: (01201-03) Passed CLEAN {RelayedInbound}, [208.65.145.68]:36890 [198.207.145.29] <user@example.com> -> <admin@domain.org>, Queue-ID: CF569660122, Message-ID: <D8B85499F2179242B235C7C725DDB0EF1A739C3DC3@GDTSRV-EXCH1.generaldatatech.com>, mail_id: Z7q6sIQtQSQW, Hits: -1.919, size: 14507, queued_as: CAB67660123, 1283 ms
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline main_log_entry - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer main_log_entry: timer 336, was 336, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) TIMING-SA total 1152 ms - parse: 1.89 (0.2%), extract_message_metadata: 23 (2.0%), get_uri_detail_list: 2.5 (0.2%), tests_pri_-1000: 8 (0.7%), tests_pri_-950: 1.04 (0.1%), tests_pri_-900: 1.20 (0.1%), tests_pri_-400: 17 (1.5%), check_bayes: 16 (1.4%), b_tokenize: 6 (0.5%), b_tok_get_all: 4.3 (0.4%), b_comp_prob: 3.6 (0.3%), b_tok_touch_all: 0.27 (0.0%), b_finish: 0.58 (0.1%), tests_pri_0: 220 (19.1%), check_dkim_adsp: 144 (12.5%), check_spf: 16 (1.3%), poll_dns_idle: 839 (72.8%), check_pyzor: 0.16 (0.0%), tests_pri_500: 839 (72.8%), learn: 27 (2.3%), b_learn: 24 (2.1%), b_count_change: 12 (1.0%), get_report: 0.42 (0.0%)
May 21 12:17:18 alpha amavis[1201]: (01201-03) updating snmp variables
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline check done - deadline in 478.8 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer check done: timer 336, was 336, deadline in 478.8 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as CAB67660123"
May 21 12:17:18 alpha amavis[1201]: (01201-03) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as CAB67660123
May 21 12:17:18 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1201]: (01201-03) TempDir::strip: /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L
May 21 12:17:18 alpha amavis[1201]: (01201-03) rmdir_recursively: /var/lib/amavis/tmp/amavis-20140521T121703-01201-4yS_YE9L/parts, excl=1
May 21 12:17:18 alpha amavis[1201]: (01201-03) size: 14507, TIMING [total 1288 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 2 (0%)0, lookup_sql: 4 (0%)1, SMTP pre-DATA-flush: 2 (0%)1, SMTP DATA: 33 (3%)3, check_init: 1 (0%)3, digest_hdr: 2 (0%)4, digest_body_dkim: 1 (0%)4, mime_decode: 18 (1%)5, get-file-type4: 17 (1%)6, parts_decode: 0 (0%)6, check_header: 1 (0%)6, AV-scan-1: 12 (1%)7, lookup_sql: 2 (0%)8, lookup_sql: 1 (0%)8, spam-wb-list: 2 (0%)8, SA parse: 4 (0%)8, SA check: 1149 (89%)97, decide_mail_destiny: 5 (0%)98, notif-quar: 0 (0%)98, fwd-connect: 4 (0%)98, fwd-mail-pip: 6 (0%)98, fwd-rcpt-pip: 0 (0%)98, fwd-data-chkpnt: 0 (0%)98, write-header: 1 (0%)99, fwd-data-contents: 0 (0%)99, fwd-end-chkpnt: 6 (1%)99, prepare-dsn: 1 (0%)99, main_log_entry: 6 (0%)100, update_snmp: 3 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 1 (0%)100, unlink-4-files: 0 (0%)100, rundown: 0 (0%)100
May 21 12:17:18 alpha amavis[1201]: (01201-03) idle_proc, 6: was busy, 1278.3 ms, total idle 11.420 s, busy 3.882 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) idle_proc, 5: was idle, 0.2 ms, total idle 11.420 s, busy 3.882 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) ESMTP< QUIT\r\n
May 21 12:17:18 alpha amavis[1201]: (01201-03) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
May 21 12:17:18 alpha amavis[1201]: (01201-03) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1201]: (01201-03) SMTP session over, timer stopped
May 21 12:17:18 alpha amavis[1201]: (01201-03) exiting process_request
May 21 12:17:18 alpha amavis[1201]: (01201-03) idle_proc, bye: was busy, 1.8 ms, total idle 11.420 s, busy 3.884 s
May 21 12:17:18 alpha amavis[1201]: (01201-03) load: 25 %, total idle 11.420 s, busy 3.884 s
May 21 12:17:18 alpha amavis[1200]: (01200-03) Net::Server: 2014/05/21-12:17:18 CONNECT TCP Peer: "[127.0.0.1]:33272" Local: "[127.0.0.1]:10024"
May 21 12:17:18 alpha amavis[1200]: () idle_proc, hi : was idle, 4940.6 ms, total idle 7.076 s, busy 8.249 s
May 21 12:17:18 alpha amavis[1200]: () loaded base policy bank
May 21 12:17:18 alpha amavis[1200]: () lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
May 21 12:17:18 alpha amavis[1200]: () process_request: fileno sock=12, STDIN=0, STDOUT=1
May 21 12:17:18 alpha amavis[1200]: () get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1200]: () prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
May 21 12:17:18 alpha amavis[1200]: () process_request: suggested_protocol="" on a TCP socket
May 21 12:17:18 alpha amavis[1200]: (01200-04) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May 21 12:17:18 alpha amavis[1200]: (01200-04) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 4: was busy, 2.1 ms, total idle 7.076 s, busy 8.251 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) smtp readline: read 22 bytes into buffer, new size: 22
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 5: was idle, 0.4 ms, total idle 7.076 s, busy 8.251 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) SMTP< EHLO alpha.domain.org\r\n
May 21 12:17:18 alpha amavis[1200]: (01200-04) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-[127.0.0.1]
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-VRFY
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-PIPELINING
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-SIZE
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-ENHANCEDSTATUSCODES
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-8BITMIME
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250-DSN
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
May 21 12:17:18 alpha amavis[1200]: (01200-04) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 6: was busy, 1.6 ms, total idle 7.076 s, busy 8.253 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) smtp readline: read 138 bytes into buffer, new size: 138
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 5: was idle, 0.3 ms, total idle 7.077 s, busy 8.253 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP< XFORWARD SOURCE=LOCAL\r\n
May 21 12:17:18 alpha amavis[1200]: (01200-04) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250 2.5.0 Ok XFORWARD
May 21 12:17:18 alpha amavis[1200]: (01200-04) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 6: was busy, 0.6 ms, total idle 7.077 s, busy 8.253 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 5: was idle, 0.1 ms, total idle 7.077 s, busy 8.253 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP< MAIL FROM:<user@example.com> SIZE=15228\r\n
May 21 12:17:18 alpha amavis[1200]: (01200-04) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) check_mail_begin_task: task_count=4
May 21 12:17:18 alpha amavis[1200]: (01200-04) lookup_ip_acl arr.obj: key="0.0.0.0", no match
May 21 12:17:18 alpha amavis[1200]: (01200-04) lookup [debug_sender] => undef, "user@example.com" does not match
May 21 12:17:18 alpha amavis[1200]: (01200-04) ESMTP> 250 2.1.0 Sender <user@example.com> OK
May 21 12:17:18 alpha amavis[1200]: (01200-04) switch_to_client_time 480 s, smtp response sent
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 6: was busy, 1.4 ms, total idle 7.077 s, busy 8.255 s
May 21 12:17:18 alpha amavis[1200]: (01200-04) idle_proc, 5: was idle, 0.1 ms, total idle 7.077 s, busy 8.255 s