Feb 3 07:02:23 hostname postfix/smtpd[15081]: connect from 68-67-82-237.wavecable.com[68.67.82.237] Feb 3 07:02:24 hostname postfix/smtpd[15081]: 97D3812334: client=68-67-82-237.wavecable.com[68.67.82.237] Feb 3 07:02:25 hostname postfix/cleanup[15087]: 97D3812334: message-id=<515464700269274-TQYLRXOUDZSTOIGAWSUW@dns279.iwa-online.net> Feb 3 07:02:25 hostname postfix/qmgr[5225]: 97D3812334: from=, size=671, nrcpt=1 (queue active) Feb 3 07:02:25 hostname amavis[11103]: (11103-17) Net::Server: 2015/02/03-07:02:25 CONNECT TCP Peer: "[127.0.0.1]:54413" Local: "[127.0.0.1]:10024" Feb 3 07:02:25 hostname amavis[11103]: () idle_proc, hi : was idle, 240636.6 ms, total idle 6961.500 s, busy 23.398 s Feb 3 07:02:25 hostname amavis[11103]: () loaded base policy bank Feb 3 07:02:25 hostname amavis[11103]: () lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1 Feb 3 07:02:25 hostname amavis[11103]: () process_request: fileno sock=12, STDIN=0, STDOUT=1 Feb 3 07:02:25 hostname amavis[11103]: () get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: () prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: () process_request: suggested_protocol="" on a TCP socket Feb 3 07:02:25 hostname amavis[11103]: (11103-18) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 4: was busy, 2.3 ms, total idle 6961.500 s, busy 23.400 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) smtp readline: read 27 bytes into buffer, new size: 27 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.3 ms, total idle 6961.500 s, busy 23.400 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) SMTP< EHLO hostname.domain.tld\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-[127.0.0.1] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-VRFY Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-PIPELINING Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-SIZE Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-ENHANCEDSTATUSCODES Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-8BITMIME Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250-DSN Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 1.8 ms, total idle 6961.500 s, busy 23.402 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) smtp readline: read 272 bytes into buffer, new size: 272 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.3 ms, total idle 6961.500 s, busy 23.402 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< XFORWARD NAME=68-67-82-237.wavecable.com ADDR=68.67.82.237 PORT=43721\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250 2.5.0 Ok XFORWARD Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 0.9 ms, total idle 6961.500 s, busy 23.403 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.1 ms, total idle 6961.501 s, busy 23.403 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< XFORWARD PROTO=SMTP HELO=68-67-82-237.wavecable.com IDENT=97D3812334 SOURCE=REMOTE\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250 2.5.0 Ok XFORWARD Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 0.8 ms, total idle 6961.501 s, busy 23.404 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.1 ms, total idle 6961.501 s, busy 23.404 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< MAIL FROM: SIZE=671\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) check_mail_begin_task: task_count=18 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_ip_acl arr.obj: key="68.67.82.237", no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [debug_sender] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250 2.1.0 Sender OK Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 2.1 ms, total idle 6961.501 s, busy 23.406 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.1 ms, total idle 6961.501 s, busy 23.406 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< RCPT TO: ORCPT=rfc822;mailbox@domain.tld\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup => undef, "mailbox@domain.tld", no lookup tables Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(mailbox@domain.tld), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: mailbox@domain.tld, @domain.tld, @.domain.tld, @.tld, @. Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql sel_policy "mailbox@domain.tld", query args: [mailbox@domain.tld,12], [@domain.tld,12], [@.domain.tld,12], [@.tld,12], [@.,12] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) 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 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql begin, nontransaction Feb 3 07:02:25 hostname amavis[11103]: (11103-18) 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 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql(mailbox@domain.tld) matches, result=(id=>"12", sys_userid=>"2", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"10", policy_id=>"9", email=>"mailbox@domain.tld", fullname=>"mailbox@domain.tld", local=>"Y", id=>"12", sys_userid=>"2", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", policy_name=>"Very Clean", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>-, bypass_banned_checks=>"N", bypass_header_checks=>"N", spam_modifies_subj=>"Y", virus_quarantine_to=>"quarantine@domain.tld", spam_quarantine_to=>"quarantine@domain.tld", banned_quarantine_to=>"quarantine@domain.tld", bad_header_quarantine_to=>"quarantine@domain.tld", clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"0.01", spam_tag2_level=>"0.1", spam_kill_level=>"4.5", spa... Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ...m_dsn_cutoff_level=>"0", spam_quarantine_cutoff_level=>"50", addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>"???SPAM???(_SCORE_)", spam_subject_tag2=>"***SPAM***(_SCORE_)", message_size_limit=>-, banned_rulenames=>-, policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1", policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"12") Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql(mailbox@domain.tld) matches, result=(id=>"20", sys_userid=>"2", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"5", policy_id=>"10", email=>"@domain.tld", fullname=>"@domain.tld", local=>"Y", id=>"20", sys_userid=>"2", sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r", policy_name=>"Normal (Marked)", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>-, bypass_banned_checks=>"N", bypass_header_checks=>"N", spam_modifies_subj=>"Y", virus_quarantine_to=>"quarantine@domain.tld", spam_quarantine_to=>"quarantine@domain.tld", banned_quarantine_to=>"quarantine@domain.tld", bad_header_quarantine_to=>"quarantine@domain.tld", clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"0.01", spam_tag2_level=>"4.5", spam_kill_level=>"50", spam_dsn_cutoff_level... Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ...=>"0", spam_quarantine_cutoff_level=>"0", addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>"???SPAM???(_SCORE_)", spam_subject_tag2=>"***SPAM***(_SCORE_)", message_size_limit=>-, banned_rulenames=>-, policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1", policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"20") Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(message_size_limit) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(message_size_limit) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [message_size_limit] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 250 2.1.5 Recipient OK Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 4.3 ms, total idle 6961.501 s, busy 23.410 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.1 ms, total idle 6961.501 s, busy 23.410 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< DATA\r\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP::10024 /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh: -> SIZE=671 Received: from hostname.domain.tld ([127.0.0.1]) by localhost (hostname.domain.tld [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for ; Tue, 3 Feb 2015 07:02:25 +1000 (AEST) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP> 354 End data with . Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:25 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, receiving data Feb 3 07:02:25 hostname amavis[11103]: (11103-18) smtp copy: read 680 bytes into buffer, new size: 680 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) smtp copy: 6 bytes still buffered at end Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ESMTP< . Feb 3 07:02:25 hostname amavis[11103]: (11103-18) smtp connection cache, dt: 240.6, state: 0 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_body_digest: reading header section Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_body_digest: reading mail body Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) body type (ESMTP BODY): unlabeled, good (h=0, b=0) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) body hash: 350912e415b5119687fd10ce37df9bb5 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Original mail size: 671; quota set to: 335500 bytes Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Checking: lZhqNh2_obyI [68.67.82.237] -> Feb 3 07:02:25 hostname amavis[11103]: (11103-18) 2822.From: , 2821.Mail_From: Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(local) rec=0, "mailbox@domain.tld" result: "Y" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => true, "mailbox@domain.tld" matches, result="Y", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_virus_checks) rec=0, "mailbox@domain.tld" result: "0" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [bypass_virus_checks] => false, "mailbox@domain.tld" matches, result="0", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_banned_checks) rec=0, "mailbox@domain.tld" result: "0" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [bypass_banned_checks] => false, "mailbox@domain.tld" matches, result="0", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_spam_checks) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_spam_checks) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [bypass_spam_checks] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(id) rec=0, "mailbox@domain.tld" result: "12" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(id) rec=1, "mailbox@domain.tld" result: "20" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [users.id], 2 matches for "mailbox@domain.tld", results: "/cached/"=>"12", "/cached/"=>"20" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(policy_id) rec=0, "mailbox@domain.tld" result: "9" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [users.policy_id] => true, "mailbox@domain.tld" matches, result="9", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Extracting mime components Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Issued a new file name: p001 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Charging 119 bytes to remaining quota 335500 (out of 335500, (0%)) - by mime_decode Feb 3 07:02:25 hostname amavis[11103]: (11103-18) p001 1 Content-Type: text/html, size: 119 B, name: Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline mime_decode - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer mime_decode: timer 336, was 336, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline mime_decode-1 - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer mime_decode-1: timer 336, was 336, deadline in 480.0 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) decode_parts: level=1, #parts=1 : p001 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) running file(1) on 1 files, arglist size 18 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_command: [15097] /usr/bin/file p001 &1 Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: target fd0 closing, to become < /dev/null Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: target fd1 closing, to become > &=16 Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: target fd1 dup2 from fd16 > &=16 Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: source fd16 closed Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: target fd2 closing, to become > &1 Feb 3 07:02:25 hostname amavis[15097]: (11103-18) open_on_specific_fd: target fd2 dup2 from fd1 > &1 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) result line from file(1): p001: ASCII text\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\b)", result="asc" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [map_full_type_to_short_type] => true, "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) File-type of p001: ASCII text; (asc) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) decompose_part: p001 - atomic Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline parts_decode - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer parts_decode: timer 336, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_header_checks) rec=0, "mailbox@domain.tld" result: "0" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [bypass_header_checks] => false, "mailbox@domain.tld" matches, result="0", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) check_header: 0, OK Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(bypass_header_checks) rec=0, "mailbox@domain.tld" result: "0" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [bypass_header_checks] => false, "mailbox@domain.tld" matches, result="0", matching_key="/cached/" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Checking for banned types and filenames Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(banned_rulenames) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(banned_rulenames) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup: (scalar) matches, result="DEFAULT" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [banned_filename], 1 matches for "mailbox@domain.tld", results: "(constant:DEFAULT)"=>"DEFAULT" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) collect banned table[0]: mailbox@domain.tld, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3803650) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) starting banned checks - traversing message structure tree Feb 3 07:02:25 hostname amavis[11103]: (11103-18) check_for_banned (p001) text/html,.asc Feb 3 07:02:25 hostname amavis[11103]: (11103-18) doing banned check for mailbox@domain.tld on text/html,.asc Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_re(["text/html",".asc"]), no matches Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [check_bann:mailbox@domain.tld] => undef, ["text/html",".asc"] does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [banned_namepath_re] => undef, "P=p001\tL=1\tM=text/html\tT=asc" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) p.path mailbox@domain.tld: "P=p001,L=1,M=text/html,T=asc" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) banned check: any=0, all=N (1) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_re("MAIL"), no matches Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [keep_decoded_original] => undef, "MAIL" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) Calling virus scanners, 1 files to scan in /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts Feb 3 07:02:25 hostname amavis[11103]: (11103-18) invoking av-scanner ClamAV-clamd Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_av (ClamAV-clamd): query template(1,0): CONTSCAN {}\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline run_av_pre - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer run_av_pre: timer 336, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline run_av_scan - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer run_av_scan: timer 336, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl Feb 3 07:02:25 hostname amavis[11103]: (11103-18) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout 10 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) connected to /var/run/clamav/clamd.ctl successfully Feb 3 07:02:25 hostname amavis[11103]: (11103-18) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts\n to socket /var/run/clamav/clamd.ctl Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=1, wr=1, timeout=10 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: sending Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=0, wr=0, timeout=335.994 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts: OK\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=0, wr=0, timeout=335.994 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:25 hostname amavis[11103]: (11103-18) rw_loop read: got eof Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline run_av_3 - deadline in 479.9 s, set to 336.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer run_av_3: timer 336, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts: OK\n Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_av (ClamAV-clamd): CLEAN Feb 3 07:02:25 hostname amavis[11103]: (11103-18) run_av (ClamAV-clamd) result: clean Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: checking sender , Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: (SQL) recip , 2 matches Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(wfvmf@katsma.com), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: wfvmf@katsma.com, @katsma.com, @.katsma.com, @.com, @. Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql sel_wblist "wfvmf@katsma.com", query args: "12", [wfvmf@katsma.com,12], [@katsma.com,12], [@.katsma.com,12], [@.com,12], [@.,12] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql begin, nontransaction Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql: executing clause: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql, "wfvmf@katsma.com" no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(wb), "wfvmf@katsma.com" no matching records Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: (SQL) recip , rid=12, got: "" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(wfvmf@katsma.com), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: wfvmf@katsma.com, @katsma.com, @.katsma.com, @.com, @. Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql sel_wblist "wfvmf@katsma.com", query args: "20", [wfvmf@katsma.com,12], [@katsma.com,12], [@.katsma.com,12], [@.com,12], [@.,12] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql begin, nontransaction Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql: executing clause: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql, "wfvmf@katsma.com" no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(wb), "wfvmf@katsma.com" no matching records Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: (SQL) recip , rid=20, got: "" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [blacklist_recip] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [blacklist_sender,blacklist_sender] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [whitelist_recip] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(wfvmf@katsma.com), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [whitelist_sender,whitelist_sender] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: mailbox@domain.tld, mailbox@, domain.tld, .domain.tld, .tld, . Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_hash(mailbox@domain.tld) matches keys: "."=>ARRAY(0x3c1cd18) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [score_recip,score_sender], 1 matches for "mailbox@domain.tld", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3c1ce80),{}] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_re("wfvmf@katsma.com"), no matches Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [score_sender] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(Marshall.Leman@iwa-online.net), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: Marshall.Leman@iwa-online.net, marshall.leman@iwa-online.net, @iwa-online.net, @.iwa-online.net, @.net, @. Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql sel_wblist "Marshall.Leman@iwa-online.net", query args: "12", [Marshall.Leman@iwa-online.net,12], [marshall.leman@iwa-online.net,12], [@iwa-online.net,12], [@.iwa-online.net,12], [@.net,12], [@.,12] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql begin, nontransaction Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql: executing clause: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql, "Marshall.Leman@iwa-online.net" no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(wb), "Marshall.Leman@iwa-online.net" no matching records Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: (SQL) recip , rid=12, got: "" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(Marshall.Leman@iwa-online.net), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [local_domains] => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: Marshall.Leman@iwa-online.net, marshall.leman@iwa-online.net, @iwa-online.net, @.iwa-online.net, @.net, @. Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql sel_wblist "Marshall.Leman@iwa-online.net", query args: "20", [Marshall.Leman@iwa-online.net,12], [marshall.leman@iwa-online.net,12], [@iwa-online.net,12], [@.iwa-online.net,12], [@.net,12], [@.,12] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql begin, nontransaction Feb 3 07:02:25 hostname amavis[11103]: (11103-18) sql: executing clause: SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?,?)) ORDER BY spamfilter_wblist.priority DESC Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql, "Marshall.Leman@iwa-online.net" no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(wb), "Marshall.Leman@iwa-online.net" no matching records Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) wbl: (SQL) recip , rid=20, got: "" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [blacklist_recip] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [blacklist_sender,blacklist_sender] => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [whitelist_recip] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_acl(Marshall.Leman@iwa-online.net), no match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [whitelist_sender,whitelist_sender] => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) query_keys: mailbox@domain.tld, mailbox@, domain.tld, .domain.tld, .tld, . Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_hash(mailbox@domain.tld) matches keys: "."=>ARRAY(0x3c1cd18) Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [score_recip,score_sender], 1 matches for "mailbox@domain.tld", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3c1ce80),{}] Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_re("Marshall.Leman@iwa-online.net"), no matches Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [score_sender] => undef, "Marshall.Leman@iwa-online.net" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) SpamControl: calling spam scanner SpamAssassin Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) prolong_timer spam_scan_sa_pre: timer 476, was 336, deadline in 479.9 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(sa_userconf) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(sa_userconf) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field, no such fields: sa_userconf Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [sa_userconf] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(sa_username) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field(sa_username) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup_sql_field, no such fields: sa_username Feb 3 07:02:25 hostname amavis[11103]: (11103-18) lookup [sa_username] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:25 hostname amavis[11103]: (11103-18) SA user config: "", username: "amavis", 0 Feb 3 07:02:25 hostname amavis[11103]: (11103-18) calling SA parse (0), SA vers 3.4.0, 3.004000, data as GLOB, recips_ind [0], user: "amavis" Feb 3 07:02:25 hostname amavis[11103]: (11103-18) get_deadline SA check - deadline in 479.9 s, set to 475.000 s Feb 3 07:02:25 hostname amavis[11103]: (11103-18) CALLING SA check (0) Feb 3 07:02:25 hostname postfix/smtpd[15081]: disconnect from 68-67-82-237.wavecable.com[68.67.82.237] Feb 3 07:02:26 hostname amavis[11103]: (11103-18) DONE SA check (0) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline spam_scan_sa - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer spam_scan_sa: timer 336, was 476, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) spam_scan: score=21.024 autolearn=no autolearn_force=no tests=[BAYES_99=3.5,BAYES_999=0.2,CK_HELO_DYNAMIC_SPLIT_IP=1.499,DATE_IN_FUTURE_06_12=1.947,DKIM_ADSP_NXDOMAIN=0.9,HEADER_FROM_DIFFERENT_DOMAINS=0.001,HK_RANDOM_ENVFROM=0.001,HTML_MESSAGE=0.001,HTML_MIME_NO_HTML_TAG=0.377,MIME_HTML_ONLY=0.723,RCVD_IN_BL_SPAMCOP_NET=1.347,RCVD_IN_BRBL_LASTEXT=1.449,RCVD_IN_SBL_CSS=3.335,RCVD_IN_XBL=0.375,RDNS_DYNAMIC=0.982,SPF_PASS=-0.001,TO_NO_BRKTS_HTML_ONLY=1.599,TVD_RCVD_IP=0.001,URIBL_BLOCKED=0.001,URIBL_DBL_ABUSE_REDIR=0.001,URIBL_PH_SURBL=0.61,URIBL_SC_SURBL=0.568,URIBL_WS_SURBL=1.608] recips=0 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline spam_scan - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer spam_scan: timer 336, was 336, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag_level) rec=0, "mailbox@domain.tld" result: "0.01" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_tag_level] => true, "mailbox@domain.tld" matches, result="0.01", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag2_level) rec=0, "mailbox@domain.tld" result: "0.1" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_tag2_level] => true, "mailbox@domain.tld" matches, result="0.1", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag3_level) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag3_level) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field, no such fields: spam_tag3_level Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_tag3_level] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_kill_level) rec=0, "mailbox@domain.tld" result: "4.5" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_kill_level] => true, "mailbox@domain.tld" matches, result="4.5", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(message_size_limit) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(message_size_limit) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [message_size_limit] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_lover) rec=0, "mailbox@domain.tld" result: "0" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [Lovers2,spam_lovers] => false, "mailbox@domain.tld" matches, result="0", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) blocking contents category is (6) for mailbox@domain.tld Feb 3 07:02:26 hostname amavis[11103]: (11103-18) final_destiny 0, recip mailbox@domain.tld Feb 3 07:02:26 hostname amavis[11103]: (11103-18) blocking ccat=6, SMTP response: 250 2.7.0 Ok, discarded, id=11103-18 - spam Feb 3 07:02:26 hostname amavis[11103]: (11103-18) do_notify_and_quar: ccat=Spam (6,0) ("6":Spam, "5":Spammy, "1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(6), qar_mth= Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_quarantine_to) rec=0, "mailbox@domain.tld" result: "quarantine@domain.tld" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_quarantine_to] => true, "mailbox@domain.tld" matches, result="quarantine@domain.tld", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_quarantine_cutoff_level) rec=0, "mailbox@domain.tld" result: "50" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_quarantine_cutoff_level] => true, "mailbox@domain.tld" matches, result="50", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_admin) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_admin) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_admin] => undef, "mailbox@domain.tld" does not match Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_quarantine_bysender_to] => undef, "wfvmf@katsma.com" does not match Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag_level) rec=0, "mailbox@domain.tld" result: "0.01" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_tag_level] => true, "mailbox@domain.tld" matches, result="0.01", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_tag2_level) rec=0, "mailbox@domain.tld" result: "0.1" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_tag2_level] => true, "mailbox@domain.tld" matches, result="0.1", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(spam_kill_level) rec=0, "mailbox@domain.tld" result: "4.5" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_kill_level] => true, "mailbox@domain.tld" matches, result="4.5", matching_key="/cached/" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header_edits_for_quar: -> , Yes, score=21.024 tag=0.01 tag2=0.1 kill=4.5 tests=[BAYES_999=0.2, BAYES_99=3.5, CK_HELO_DYNAMIC_SPLIT_IP=1.499, DATE_IN_FUTURE_06_12=1.947, DKIM_ADSP_NXDOMAIN=0.9, HEADER_FROM_DIFFERENT_DOMAINS=0.001, HK_RANDOM_ENVFROM=0.001, HTML_MESSAGE=0.001, HTML_MIME_NO_HTML_TAG=0.377, MIME_HTML_ONLY=0.723, RCVD_IN_BL_SPAMCOP_NET=1.347, RCVD_IN_BRBL_LASTEXT=1.449, RCVD_IN_SBL_CSS=3.335, RCVD_IN_XBL=0.375, RDNS_DYNAMIC=0.982, SPF_PASS=-0.001, TO_NO_BRKTS_HTML_ONLY=1.599, TVD_RCVD_IP=0.001, URIBL_BLOCKED=0.001, URIBL_DBL_ABUSE_REDIR=0.001, URIBL_PH_SURBL=0.61, URIBL_SC_SURBL=0.568, URIBL_WS_SURBL=1.608] autolearn=no autolearn_force=no Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Spam-Flag: YES\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Spam-Score: 21.024\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Spam-Level: *********************\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Spam-Status: Yes, score=21.024 tag=0.01 tag2=0.1 kill=4.5\n\ttests=[BAYES_999=0.2, BAYES_99=3.5, CK_HELO_DYNAMIC_SPLIT_IP=1.499,\n\tDATE_IN_FUTURE_06_12=1.947, DKIM_ADSP_NXDOMAIN=0.9,\n\tHEADER_FROM_DIFFERENT_DOMAINS=0.001, HK_RANDOM_ENVFROM=0.001,\n\tHTML_MESSAGE=0.001, HTML_MIME_NO_HTML_TAG=0.377, MIME_HTML_ONLY=0.723,\n\tRCVD_IN_BL_SPAMCOP_NET=1.347, RCVD_IN_BRBL_LASTEXT=1.449,\n\tRCVD_IN_SBL_CSS=3.335, RCVD_IN_XBL=0.375, RDNS_DYNAMIC=0.982,\n\tSPF_PASS=-0.001, TO_NO_BRKTS_HTML_ONLY=1.599, TVD_RCVD_IP=0.001,\n\tURIBL_BLOCKED=0.001, URIBL_DBL_ABUSE_REDIR=0.001, URIBL_PH_SURBL=0.61,\n\tURIBL_SC_SURBL=0.568, URIBL_WS_SURBL=1.608]\n\tautolearn=no autolearn_force=no\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) quar: scanner provided X-Spam-Checker-Version, inhibited by %allowed_added_header_fields Feb 3 07:02:26 hostname amavis[11103]: (11103-18) quar: scanner provided X-Spam-Flag, but we preferred our own Feb 3 07:02:26 hostname amavis[11103]: (11103-18) quar: scanner provided X-Spam-Level, but we preferred our own Feb 3 07:02:26 hostname amavis[11103]: (11103-18) quar: scanner provided X-Spam-Status, but we preferred our own Feb 3 07:02:26 hostname amavis[11103]: (11103-18) do_notify_and_quarantine: quarantine quarantine@domain.tld Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Quarantine-ID: \n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Envelope-To-Blocked: \n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: X-Envelope-To: \n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) header: Received: from hostname.domain.tld ([127.0.0.1])\n\tby localhost (hostname.domain.tld [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id lZhqNh2_obyI for ;\n\tTue, 3 Feb 2015 07:02:25 +1000 (AEST)\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) DO_QUARANTINE, smtp:[127.0.0.1]:10025, -> Feb 3 07:02:26 hostname amavis[11103]: (11103-18) about to connect to smtp:[127.0.0.1]:10025, SEND from -> Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline fwd_init - deadline in 479.1 s, set to 480.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp session: setting up a new session Feb 3 07:02:26 hostname amavis[11103]: (11103-18) establish_or_refresh, state: down Feb 3 07:02:26 hostname amavis[11103]: (11103-18) new socket by IO::Socket::INET to [127.0.0.1]:10025, timeout 35, blocking Feb 3 07:02:26 hostname postfix/smtpd[15091]: connect from localhost.localdomain[127.0.0.1] Feb 3 07:02:26 hostname amavis[11103]: (11103-18) connected to [127.0.0.1]:10025 successfully Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=1, flush=0, wr=0, timeout=35 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop read 49 chars< 220 hostname.domain.tld ESMTP Postfix (Ubuntu)\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp greeting: 220 hostname.domain.tld ESMTP Postfix (Ubuntu) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp cmd> EHLO localhost Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=1, wr=1, timeout=300 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: sending Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop sent 16> EHLO localhost\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=1, flush=0, wr=0, timeout=300 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop read 178 chars< 250-hostname.domain.tld\r\n250-PIPELINING\r\n250-SIZE\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH PLAIN LOGIN\r\n250-AUTH=PLAIN LOGIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp resp to EHLO: 250 hostname.domain.tld\nPIPELINING\nSIZE\nVRFY\nETRN\nSTARTTLS\nAUTH PLAIN LOGIN\nAUTH=PLAIN LOGIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN Feb 3 07:02:26 hostname amavis[11103]: (11103-18) tls active=0, capable=1, sec_level=0 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) Remote host presents itself as: hostname.domain.tld, handles DSN, handles PIPELINING Feb 3 07:02:26 hostname amavis[11103]: (11103-18) AUTH not needed, user='', MTA offers 'PLAIN LOGIN' Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp cmd> MAIL FROM: ENVID=AM.lZhqNh2_obyI.20150202T210226Z@hostname.domain.tld BODY=7BIT Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp cmd> RCPT TO: NOTIFY=NEVER Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp cmd> DATA Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=1, wr=1, timeout=120 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: sending Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop sent 153> MAIL FROM: ENVID=AM.lZhqNh2_obyI.20150202T210226Z@hostname.domain.tld BODY=7BIT\r\nRCPT TO: NOTIFY=NEVER\r\nDATA\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=1, flush=0, wr=0, timeout=300 Feb 3 07:02:26 hostname postfix/smtpd[15091]: 0D525124AC: client=localhost.localdomain[127.0.0.1] Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with .\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp resp to MAIL (pip): 250 2.1.0 Ok Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp resp to RCPT (pip) (): 250 2.1.5 Ok Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp resp to DATA: 354 End data with . Feb 3 07:02:26 hostname amavis[11103]: (11103-18) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x86e6d60) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp connection_cache disabled, sending QUIT Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp cmd> QUIT Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=0, flush=1, wr=1, timeout=479.987 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: sending Feb 3 07:02:26 hostname postfix/cleanup[15087]: 0D525124AC: message-id=<515464700269274-TQYLRXOUDZSTOIGAWSUW@dns279.iwa-online.net> Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop sent 1776> X-Envelope-To: \r\nX-Envelope-To-Blocked: \r\nX-Quarantine-ID: \r\nX-Spam-Flag: YES\r\nX-Spam-Score: 21.024\r\nX-Spam-Level: ********************* [...] Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: needline=1, flush=0, wr=0, timeout=479.987 Feb 3 07:02:26 hostname postfix/smtpd[15091]: disconnect from localhost.localdomain[127.0.0.1] Feb 3 07:02:26 hostname postfix/qmgr[5225]: 0D525124AC: from=, size=1961, nrcpt=1 (queue active) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop: receiving Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rw_loop read 51 chars< 250 2.0.0 Ok: queued as 0D525124AC\r\n221 2.0.0 Bye\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) smtp resp to data-dot (): 250 2.0.0 Ok: queued as 0D525124AC Feb 3 07:02:26 hostname amavis[11103]: (11103-18) Amavis::Out::SMTP::Session close, disconnecting Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline fwd-end-chkpnt - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) SEND from -> ,BODY=7BIT ENVID=AM.lZhqNh2_obyI.20150202T210226Z@hostname.domain.tld 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0D525124AC Feb 3 07:02:26 hostname amavis[11103]: (11103-18) one_response_for_all : 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 0D525124AC' Feb 3 07:02:26 hostname amavis[11103]: (11103-18) DO_QUARANTINE done Feb 3 07:02:26 hostname amavis[11103]: (11103-18) skip admin notification, no administrators Feb 3 07:02:26 hostname amavis[11103]: (11103-18) do_notify_and_quarantine - done Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(forward_method) rec=0, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field(forward_method) rec=1, "mailbox@domain.tld" result: undef Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_sql_field, no such fields: forward_method Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [forward_method] => true, "mailbox@domain.tld" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) delivery method is smtp:[127.0.0.1]:10025, recips: mailbox@domain.tld Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline quar+notif - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer quar+notif: timer 336, was 336, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) DSN: sender NOT credible, SA: 21.024, Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup: (scalar) matches, result="100" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup [spam_dsn_cutoff_level_bysender] => true, "wfvmf@katsma.com" matches, result="100", matching_key="(constant:100)" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) dsn: . 250 Spam -> : on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=, destiny=0, mta_resp: "250 2.7.0 Ok, discarded, id=11103-18 - spam" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) DSN: SUCC (discarded) . 250 Spam, destiny=DISCARD: -> Feb 3 07:02:26 hostname amavis[11103]: (11103-18) one_response_for_all : all DISCARD, '250 2.7.0 Ok, discarded, id=11103-18 - spam' Feb 3 07:02:26 hostname amavis[11103]: (11103-18) notif=N, suppressed=0, ndn_needed=, exit=99, 250 2.7.0 Ok, discarded, id=11103-18 - spam Feb 3 07:02:26 hostname amavis[11103]: (11103-18) status counters: InMsgsStatus{Discarded,DiscardedInbound} Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline delivery-notification - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer delivery-notification: timer 336, was 336, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) fish_out_ip_from_received: 68.67.82.237 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) lookup_ip_acl (publicnetworks) arr.obj: key="68.67.82.237" matches "::FFFF:0:0/96", result=1 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) parse_ip_address_from_received: 68.67.82.237 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) Blocked SPAM {DiscardedInbound,Quarantined}, [68.67.82.237]:43721 [68.67.82.237] -> , quarantine: quarantine@domain.tld, Queue-ID: 97D3812334, Message-ID: <515464700269274-TQYLRXOUDZSTOIGAWSUW@dns279.iwa-online.net>, mail_id: lZhqNh2_obyI, Hits: 21.024, size: 671, 975 ms Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline main_log_entry - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer main_log_entry: timer 336, was 336, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) TIMING-SA total 749 ms - parse: 3.1 (0.4%), extract_message_metadata: 15 (2.1%), get_uri_detail_list: 0.85 (0.1%), tests_pri_-1000: 10 (1.3%), tests_pri_-950: 1.05 (0.1%), tests_pri_-900: 0.94 (0.1%), tests_pri_-400: 10 (1.4%), check_bayes: 9 (1.2%), b_tokenize: 2.6 (0.4%), b_tok_get_all: 2.1 (0.3%), b_comp_prob: 1.80 (0.2%), b_tok_touch_all: 0.11 (0.0%), b_finish: 0.76 (0.1%), tests_pri_0: 690 (92.2%), check_dkim_adsp: 161 (21.5%), check_spf: 497 (66.3%), poll_dns_idle: 470 (62.7%), check_pyzor: 0.18 (0.0%), tests_pri_500: 3.7 (0.5%), get_report: 0.65 (0.1%) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) updating snmp variables Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline check done - deadline in 479.1 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer check done: timer 336, was 336, deadline in 479.1 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) sending SMTP response: "250 2.7.0 Ok, discarded, id=11103-18 - spam" Feb 3 07:02:26 hostname amavis[11103]: (11103-18) ESMTP> 250 2.7.0 Ok, discarded, id=11103-18 - spam Feb 3 07:02:26 hostname postfix/smtp[15088]: 97D3812334: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=1.7, delays=0.76/0/0.01/0.98, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=11103-18 - spam) Feb 3 07:02:26 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:26 hostname amavis[11103]: (11103-18) TempDir::strip: /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh Feb 3 07:02:26 hostname amavis[11103]: (11103-18) rmdir_recursively: /var/lib/amavis/tmp/amavis-20150203T050600-11103-KtomlmRh/parts, excl=1 Feb 3 07:02:26 hostname postfix/qmgr[5225]: 97D3812334: removed Feb 3 07:02:26 hostname amavis[11103]: (11103-18) size: 671, TIMING [total 982 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 3 (0%)1, lookup_sql: 5 (1%)1, SMTP pre-DATA-flush: 2 (0%)1, SMTP DATA: 31 (3%)5, check_init: 1 (0%)5, digest_hdr: 1 (0%)5, digest_body_dkim: 1 (0%)5, mime_decode: 8 (1%)6, get-file-type1: 63 (6%)12, parts_decode: 1 (0%)12, check_header: 4 (0%)13, AV-scan-1: 22 (2%)15, lookup_sql: 6 (1%)15, lookup_sql: 3 (0%)16, lookup_sql: 9 (1%)17, lookup_sql: 5 (0%)17, spam-wb-list: 6 (1%)18, SA parse: 11 (1%)19, SA check: 744 (76%)95, decide_mail_destiny: 6 (1%)95, notif-quar: 2 (0%)96, quar-hdrs: 6 (1%)96, fwd-connect: 11 (1%)97, fwd-mail-pip: 5 (0%)98, fwd-rcpt-pip: 0 (0%)98, fwd-data-chkpnt: 0 (0%)98, write-header: 1 (0%)98, fwd-data-contents: 0 (0%)98, fwd-end-chkpnt: 3 (0%)98, prepare-dsn: 2 (0%)98, main_log_entry: 9 (1%)99, update_snmp: 2 (0%)100, SMTP pre-response: 2 (0%)100, SMTP response: 2 (0%)100, unlink-1-files: 0 (0%)100, rundown: 1 (0%)100 Feb 3 07:02:26 hostname amavis[11103]: (11103-18) idle_proc, 6: was busy, 969.0 ms, total idle 6961.501 s, busy 24.379 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) idle_proc, 5: was idle, 0.1 ms, total idle 6961.501 s, busy 24.379 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) ESMTP< QUIT\r\n Feb 3 07:02:26 hostname amavis[11103]: (11103-18) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel Feb 3 07:02:26 hostname amavis[11103]: (11103-18) switch_to_client_time 480 s, smtp response sent Feb 3 07:02:26 hostname amavis[11103]: (11103-18) SMTP session over, timer stopped Feb 3 07:02:26 hostname amavis[11103]: (11103-18) exiting process_request Feb 3 07:02:26 hostname amavis[11103]: (11103-18) idle_proc, bye: was busy, 2.1 ms, total idle 6961.501 s, busy 24.381 s Feb 3 07:02:26 hostname amavis[11103]: (11103-18) load: 0 %, total idle 6961.501 s, busy 24.381 s Feb 3 07:02:26 hostname dovecot: lda(quarantine@domain.tld): sieve: msgid=<515464700269274-TQYLRXOUDZSTOIGAWSUW@dns279.iwa-online.net>: stored mail into mailbox 'INBOX' Feb 3 07:02:26 hostname postfix/pipe[15092]: 0D525124AC: to=, relay=dovecot, delay=0.04, delays=0/0/0/0.03, dsn=2.0.0, status=sent (delivered via dovecot service) Feb 3 07:02:26 hostname postfix/qmgr[5225]: 0D525124AC: removed