1 Topic by drosalevan (edited by drosalevan 2015-08-13 16:37:41)

  • drosalevan
  • Member
  • Offline
  • Registered: 2015-06-11
  • Posts: 14

Topic: Amavis BAD-HEADER and white list

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.2
- Linux/BSD distribution name and version: Debian 7
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Apache
- Manage mail accounts with iRedAdmin-Pro?
- Related log if you're reporting an issue: 

Blocked BAD-HEADER-0 {DiscardedInternal,Quarantined}, MYUSERS LOCAL [***]:58522 [***] <robot@***.com> -> <user@***.net>, quarantine: 6AlTwtciAlAP, Queue-ID: 6EE122026D, Message-ID: <20150810064746738.C9835AB600AB6F11@info>, mail_id: 6AlTwtciAlAP, Hits: -, size: 234362, 210 ms
Aug 10 09:46:28 mail postfix/smtp[24696]: 6EE122026D: to=<user@***.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.28, delays=0.06/0/0/0.22, dsn=2.6.0, status=sent (250 2.6.0 Ok, discarded, id=24659-09 - BAD HEADER)

debug log iredapd

2015-08-13 11:30:16 DEBUG --> Apply plugin: amavisd_wblist
2015-08-13 11:30:16 DEBUG Possible policy senders: ['@.', 'robot@domain.com', '@domain.com', '@.domain.com', '@com', '@.com', '1.1.1.4', '1.1.1.*', '1.1.*.4', '1.*.$
2015-08-13 11:30:16 DEBUG Possible policy recipients: ['@.', 'user@domain.net', '@domain.net', '@.domain.net', '@net', '@.net', 'user@*']
2015-08-13 11:30:16 DEBUG SQL: Get policy senders: SELECT id,email FROM mailaddr WHERE email IN ('@.', 'robot@domain.com', '@domain.com', '@.domain.com', '@com', '@.com', '1$
2015-08-13 11:30:16 DEBUG Senders (in sql table: amavisd.mailaddr): [(2L, 'robot@domain.com'), (1L, '@domain.com')]
2015-08-13 11:30:16 DEBUG SQL: Get policy recipients: SELECT id,email FROM users WHERE email IN ('@.', 'user@domain.net', '@domain.net', '@.domain.net', '@net', '@.net', 'user@*$
2015-08-13 11:30:16 DEBUG Recipients (in `amavisd.users`): [(1L, '@.')]
2015-08-13 11:30:16 DEBUG SQL: Get wblist: SELECT rid,sid,wb FROM wblist WHERE sid IN (2, 1) AND rid IN (1)
2015-08-13 11:30:16 DEBUG Found per-recipient white/blacklists: [(1L, 1L, 'W')]
2015-08-13 11:30:16 DEBUG <-- Result: OK wblist=(1, 1, 'W')
2015-08-13 11:30:16 INFO [37.9.129.14] RCPT, robot@domain.com -> user@domain.net, OK wblist=(1, 1, 'W')
2015-08-13 11:30:16 DEBUG Session ended

====

I'va added sender in global whitelist, but anyway message from this sender go to quarantined mails as "Bad Header". This emails from software which sending info emails to subscribers and I can't modify any system info like HEADER in this software sad

Plugin amavisd_wblist enabled in config file.

How can I bypass amavis header check for whitelist?


Thank you

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Amavis BAD-HEADER and white list

I can see '@domain.com' is globally whitelisted in iRedAPD log. we need to turn on debug mode in Amavisd to see why it doesn't bypass bad-header check for this sender.

Also, another solution is: disable bad-header check in Amavisd config file.

3 Reply by drosalevan (edited by drosalevan 2015-08-13 18:33:17)

  • drosalevan
  • Member
  • Offline
  • Registered: 2015-06-11
  • Posts: 14

Re: Amavis BAD-HEADER and white list

Now @domain.com is whitelisted only for 1 domain

Problem with BAD header in  X-Amavis-Alert: BAD HEADER SECTION, Non-encoded non-ASCII data (and not UTF-8) (char C4 hex): Subject: \\x{C4}\\x{EE}\\x{EA}\\x{F3}\\x{EC}\\x{E5}\\x{ED}\\x{F2}\\x{FB} \\x{E7}\\x{E0}  Ju[...]

Debug log from amavis

Aug 13 11:55:12 mail amavis[24088]: (24088-04) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 4: was busy, 6.4 ms, total idle 46.390 s, busy 2.611 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp readline: read 24 bytes, new size: 24
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.4 ms, total idle 46.391 s, busy 2.611 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) SMTP< EHLO mail.domain.com\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-[127.0.0.1]
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-VRFY
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-PIPELINING
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-SIZE
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-ENHANCEDSTATUSCODES
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-8BITMIME
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-SMTPUTF8
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250-DSN
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 1.4 ms, total idle 46.391 s, busy 2.612 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp readline: read 251 bytes, new size: 251
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.2 ms, total idle 46.391 s, busy 2.612 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< XFORWARD NAME=customer.net ADDR=1.1.1.4 PORT=59040\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 2.5.0 Ok XFORWARD
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 0.6 ms, total idle 46.391 s, busy 2.613 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.1 ms, total idle 46.391 s, busy 2.613 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< XFORWARD PROTO=ESMTP HELO=Billing IDENT=3A14222291 SOURCE=REMOTE\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 2.5.0 Ok XFORWARD
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 0.5 ms, total idle 46.391 s, busy 2.613 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.1 ms, total idle 46.391 s, busy 2.613 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< MAIL FROM:<robot@domain.com> SIZE=89483 BODY=8BITMIME\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) check_mail_begin_task: task_count=4
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="1.1.1.4", no match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [local_domains] => true,  "robot@domain.com" matches, result="1", matching_key="(constant:1)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) query_keys: cached robot@domain.com
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql sel_policy "robot@domain.com", query args: [robot@domain.com,-3], [robot,-3], [@domain.com,-3], [@.domain.com,-3], [@.com,-3], [@.,-3]
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql select: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin, nontransaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (6 args): SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql: "robot@domain.com" matches catchall, local=>undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql(robot@domain.com) matches, result=(id=>"3", priority=>"5", policy_id=>"0", email=>"@domain.com", fullname=>-, id=>"3", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, spam_quarantine_to=>-, banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, 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_subject_tag2=>-, spam_subject_t...
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ...ag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"3")
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql(robot@domain.com) matches, result=(id=>"1", priority=>"0", policy_id=>"0", email=>"@.", fullname=>-, id=>"1", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, spam_quarantine_to=>-, banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, 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_subject_tag2=>-, spam_subject_tag3=>-, mes...
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ...sage_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(local) rec=0, "robot@domain.com" result: "1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field, no such fields: local
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [local_domains] => true,  "robot@domain.com" matches, result="1", matching_key="id=>"3", priority=>"5", policy_id=>"0", email=>"@domain.com", fullname=>-, id=>"3", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, spam_quarantine_to=>-, banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, 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...
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ...=>-, spam_subject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"3""
Aug 13 11:55:12 mail amavis[24088]: (24088-04) loaded policy bank "MYUSERS"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [debug_sender] => undef, "robot@domain.com" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) mesage size set to a declared size 89483
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 2.1.0 Sender <robot@domain.com> OK
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 11.0 ms, total idle 46.391 s, busy 2.624 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.3 ms, total idle 46.391 s, busy 2.624 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< RCPT TO:<user@domain.net> ORCPT=rfc822;user@domain.net\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup => undef, "user@domain.net", no lookup tables
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [local_domains] => true,  "user@domain.net" matches, result="1", matching_key="(constant:1)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) query_keys: user@domain.net, user, @domain.net, @.domain.net, @.net, @.
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql sel_policy "user@domain.net", query args: [user@domain.net,-3], [user,-3], [@domain.net,-3], [@.domain.net,-3], [@.net,-3], [@.,-3]
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql select: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin, nontransaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (6 args): SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql: "user@domain.net" matches catchall, local=>undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql(user@domain.net) matches, result=(id=>"3", priority=>"5", policy_id=>"0", email=>"@domain.net", fullname=>-, id=>"3", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, spam_quarantine_to=>-, banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, 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_subject_tag2=>-, spam_subject_tag3...
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ...=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"3")
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql(user@domain.net) matches, result=(id=>"1", priority=>"0", policy_id=>"0", email=>"@.", fullname=>-, id=>"1", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, spam_quarantine_to=>-, banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, 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_subject_tag2=>-, spam_subject_tag3=>-, messag...
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ...e_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(message_size_limit) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(message_size_limit) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [message_size_limit] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 2.1.5 Recipient <user@domain.net> OK
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 6.8 ms, total idle 46.391 s, busy 2.631 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.2 ms, total idle 46.391 s, busy 2.631 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< DATA\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP :10024 /var/lib/amavis/tmp/amavis-20150813T115423-24088-NFk5YDvm: <robot@domain.com> -> <user@domain.net> SIZE=89483 BODY=8BITMIME Received: from mail.domain.com ([127.0.0.1]) by mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <user@domain.net>; Thu, 13 Aug 2015 11:55:12 +0300 (MSK)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, receiving data
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp copy: read 65536 bytes into buffer, new size: 65536
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp copy: read 23956 bytes into buffer, new size: 23956
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp copy: 6 bytes still buffered at end
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< .<CR><LF>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) smtp connection cache, dt: 7.7, state: 0
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_body_digest: reading header section from memory
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_body_digest: feeding header section to DKIM verifier
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_body_digest: sending h/b separator to DKIM
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_body_digest: reading mail body from memory, 0 DKIM signatures
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_body_digest: message size 89483, header+sep 565, body 88918
Aug 13 11:55:12 mail amavis[24088]: (24088-04) body type (8bit-MIMEtransport): labeled 8BITMIME, good (h=1, b=1)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) body hash: 3228046728aec0b8b54f944a5ccc432d
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ip_from_received: 1.1.1.4
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_ip_acl (public_nets) arr.obj: key="1.1.1.4" matches "::ffff:0:0/96", result=1
Aug 13 11:55:12 mail amavis[24088]: (24088-04) trace: ESMTP://[127.0.0.1]:32980 < ESMTP://[1.1.1.4]:59040
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Original mail size: 89483; quota set to: 44741500 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin, nontransaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Aug 13 11:55:12 mail amavis[24088]: (24088-04) save_info_preliminary eOpmz1Axlr06, sender id: 42, robot@domain.com, exists
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin, nontransaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Aug 13 11:55:12 mail amavis[24088]: (24088-04) orcpt_encode rfc822, user@domain.net, smtputf8
Aug 13 11:55:12 mail amavis[24088]: (24088-04) save_info_preliminary eOpmz1Axlr06, recip id: 4, user@domain.net (ORCPT rfc822;user@domain.net), exists
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin transaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql commit
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Checking: eOpmz1Axlr06 MYUSERS [1.1.1.4] <robot@domain.com> -> <user@domain.net>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) 2822.From: <robot@domain.com>, 2822.Sender: <robot@domain.com>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(local) rec=0, "user@domain.net" result: "1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field, no such fields: local
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [local_domains] => true,  "user@domain.net" matches, result="1", matching_key="/cached/"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup => true,  "user@domain.net" matches, result="1", matching_key="(constant:1)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup => true,  "user@domain.net" matches, result="1", matching_key="(constant:1)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_spam_checks) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_spam_checks) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [bypass_spam_checks] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(id) rec=0, "user@domain.net" result: "3"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(id) rec=1, "user@domain.net" result: "1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [users.id], 2 matches for "user@domain.net", results: "/cached/"=>"3", "/cached/"=>"1"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(policy_id) rec=0, "user@domain.net" result: "0"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [users.policy_id] => false, "user@domain.net" matches, result="0", matching_key="/cached/"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Extracting mime components from a string
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Issued a new file name: p001
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Issued a new file name: p002
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Issued a new file name: p003
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Issued a new file name: p004
Aug 13 11:55:12 mail amavis[24088]: (24088-04) mime_decode_preamble: 1 lines
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Issued a new pseudo part: p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) p005 1 Content-Type: multipart/mixed
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Charging 218 bytes to remaining quota 44741500 (out of 44741500, (0%)) - by mime_decode
Aug 13 11:55:12 mail amavis[24088]: (24088-04) p001 1/1 Content-Type: text/plain, size: 218 B, name:
Aug 13 11:55:12 mail amavis[24088]: (24088-04) reparenting p001 from p000 to p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Charging 45036 bytes to remaining quota 44741282 (out of 44741500, (0%)) - by mime_decode
Aug 13 11:55:12 mail amavis[24088]: (24088-04) p002 1/2 Content-Type: application/octet-stream, size: 45036 B, name: \\xD1\\xF7\\xE5\\xF21.pdf
Aug 13 11:55:12 mail amavis[24088]: (24088-04) reparenting p002 from p000 to p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Charging 11774 bytes to remaining quota 44696246 (out of 44741500, (0%)) - by mime_decode
Aug 13 11:55:12 mail amavis[24088]: (24088-04) p003 1/3 Content-Type: application/octet-stream, size: 11774 B, name: \\xD1\\xF7\\xE5\\xF2-\\xF4\\xE0\\xEA\\xF2\\xF3\\xF0\\xE01.pdf
Aug 13 11:55:12 mail amavis[24088]: (24088-04) reparenting p003 from p000 to p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Charging 7426 bytes to remaining quota 44684472 (out of 44741500, (0%)) - by mime_decode
Aug 13 11:55:12 mail amavis[24088]: (24088-04) p004 1/4 Content-Type: application/octet-stream, size: 7426 B, name: \\xC0\\xEA\\xF21.pdf
Aug 13 11:55:12 mail amavis[24088]: (24088-04) reparenting p004 from p000 to p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline mime_decode - deadline in 479.9 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer mime_decode: timer 288, was 288, deadline in 479.9 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline mime_decode-1 - deadline in 479.9 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer mime_decode-1: timer 288, was 288, deadline in 479.9 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) decode_parts: level=1, #parts=5 : p001, p002, p003, p004, p005
Aug 13 11:55:12 mail amavis[24088]: (24088-04) running file(1) on 4 files, arglist size 33
Aug 13 11:55:12 mail amavis[24088]: (24088-04) run_command: [24150] /usr/bin/file p001 p002 p003 p004 </dev/null 2>&1
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: target fd0 closing, to become < /dev/null
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: target fd1 closing, to become (65) &=17
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: target fd1 dup2 from fd17 (65) &=17
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: source fd17 closed
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: target fd2 closing, to become (65) &1
Aug 13 11:55:12 mail amavis[24150]: (24088-04) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Aug 13 11:55:12 mail amavis[24088]: (24088-04) result line from file(1): p001: ISO-8859 text\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_re("ISO-8859 text") matches key "(?^:^ISO-8859.*\\btext\\b)", result="txt"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [map_full_type_to_short_type] => true,  "ISO-8859 text" matches, result="txt", matching_key="(?^:^ISO-8859.*\\btext\\b)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) File-type of p001: ISO-8859 text; (txt)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) result line from file(1): p002: PDF document, version 1.3\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_re("PDF document, version 1.3") matches key "(?^:^PDF document\\b)", result="pdf"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [map_full_type_to_short_type] => true,  "PDF document, version 1.3" matches, result="pdf", matching_key="(?^:^PDF document\\b)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) File-type of p002: PDF document, version 1.3; (pdf)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) result line from file(1): p003: PDF document, version 1.3\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_re("PDF document, version 1.3") matches key "(?^:^PDF document\\b)", result="pdf"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [map_full_type_to_short_type] => true,  "PDF document, version 1.3" matches, result="pdf", matching_key="(?^:^PDF document\\b)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) File-type of p003: PDF document, version 1.3; (pdf)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) result line from file(1): p004: PDF document, version 1.3\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_re("PDF document, version 1.3") matches key "(?^:^PDF document\\b)", result="pdf"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [map_full_type_to_short_type] => true,  "PDF document, version 1.3" matches, result="pdf", matching_key="(?^:^PDF document\\b)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) File-type of p004: PDF document, version 1.3; (pdf)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) decompose_part: p001 - atomic
Aug 13 11:55:12 mail amavis[24088]: (24088-04) decompose_part: p002 - atomic
Aug 13 11:55:12 mail amavis[24088]: (24088-04) decompose_part: p003 - atomic
Aug 13 11:55:12 mail amavis[24088]: (24088-04) decompose_part: p004 - atomic
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline parts_decode - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer parts_decode: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_header_checks) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_header_checks) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [bypass_header_checks] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) check_header: 2, Non-encoded non-ASCII data (and not UTF-8) (char C4 hex): Subject: \\x{C4}\\x{EE}\\x{EA}\\x{F3}\\x{EC}\\x{E5}\\x{ED}\\x{F2}\\x{FB} \\x{E7}\\x{E0}  Ju[...]
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_header_checks) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bypass_header_checks) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [bypass_header_checks] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Checking for banned types and filenames
Aug 13 11:55:12 mail amavis[24088]: (24088-04) skipping banned check: all recipients bypass banned checks
Aug 13 11:55:12 mail amavis[24088]: (24088-04) banned check: any=0, all=Y (1)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) bypassing of virus checks requested
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_lover) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_lover) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [Lovers1,bad_header_lovers] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) bypassing of spam checks, message will be blocked anyway due to 4
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag_level) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag_level) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="2"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [spam_tag_level] => true,  "user@domain.net" matches, result="2", matching_key="(constant:2)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag2_level) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag2_level) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="6.31"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [spam_tag2_level] => true,  "user@domain.net" matches, result="6.31", matching_key="(constant:6.31)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag3_level) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_tag3_level) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [spam_tag3_level] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_kill_level) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(spam_kill_level) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="6.31"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [spam_kill_level] => true,  "user@domain.net" matches, result="6.31", matching_key="(constant:6.31)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(message_size_limit) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(message_size_limit) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [message_size_limit] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_lover) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_lover) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [Lovers2,bad_header_lovers] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) blocking ccat (4) differs from ccat_maj=4,2, user@domain.net, final_destiny 0
Aug 13 11:55:12 mail amavis[24088]: (24088-04) final_destiny 0, recip user@domain.net
Aug 13 11:55:12 mail amavis[24088]: (24088-04) blocking ccat=4, SMTP response: 250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER
Aug 13 11:55:12 mail amavis[24088]: (24088-04) do_notify_and_quar: ccat=BadHdr8bit (4,2) ("4,2":BadHdr8bit, "4":BadHdr, "1":Clean, "0":CatchAll) ccat_block=(4), qar_mth=
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_quarantine_to) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(bad_header_quarantine_to) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (scalar) matches, result="bad-header-quarantine"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [bad_header_quarantine_to] => true,  "user@domain.net" matches, result="bad-header-quarantine", matching_key="(constant:bad-header-quarantine)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup => undef, "user@domain.net", no lookup tables
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header_edits_for_quar: rec_bl_ccat=(4,0), ccat=(4,2) user@domain.net
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Amavis-Alert: BAD HEADER SECTION, Non-encoded non-ASCII data (and not UTF-8) (char C4 hex): Subject: \\x{C4}\\x{EE}\\x{EA}\\x{F3}\\x{EC}\\x{E5}\\x{ED}\\x{F2}\\x{FB} \\x{E7}\\x{E0}  Ju[...]
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Amavis-Alert: BAD HEADER SECTION, Non-encoded non-ASCII data (and not UTF-8)\n\t(char C4 hex): Subject:\n\t\\x{C4}\\x{EE}\\x{EA}\\x{F3}\\x{EC}\\x{E5}\\x{ED}\\x{F2}\\x{FB} \\x{E7}\\x{E0} \n\tJu[...]\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header_edits_for_quar: <robot@domain.com> -> <user@domain.net>, No, score=x tag=x tag2=x kill=x tests=[] autolearn=unavailable
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Spam-Flag: NO
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Spam-Flag: NO\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Spam-Score: 0
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Spam-Score: 0\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Spam-Level:
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Spam-Level:\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Spam-Status: No,\n score=x\n tag=x\n tag2=x\n kill=x\n tests=[]\n autolearn=unavailable
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Spam-Status: No, score=x tag=x tag2=x kill=x tests=[] autolearn=unavailable\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) do_notify_and_quarantine: quarantine bad-header-quarantine
Aug 13 11:55:12 mail amavis[24088]: (24088-04) generate_mail_id retry: lJpBk3zWK1b+
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Quarantine-ID: <eOpmz1Axlr06>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Quarantine-ID: <eOpmz1Axlr06>\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Envelope-To-Blocked: <user@domain.net>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Envelope-To-Blocked: <user@domain.net>\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): X-Envelope-To: <user@domain.net>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: X-Envelope-To: <user@domain.net>\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header encoded (all-ASCII): Received: from mail.domain.com ([127.0.0.1])\n by mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id eOpmz1Axlr06\n for <user@domain.net>;\n Thu, 13 Aug 2015 11:55:12 +0300 (MSK)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) header: Received: from mail.domain.com ([127.0.0.1])\n\tby mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id eOpmz1Axlr06 for <user@domain.net>;\n\tThu, 13 Aug 2015 11:55:12 +0300 (MSK)\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) DO_QUARANTINE, sql:, <robot@domain.com> -> <user@domain.net>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) delivering to sql:, SEND via SQL (DBI:mysql:database=amavisd;host=127.0.0.1;port=3306): <robot@domain.com> -> <user@domain.net>, mail_id eOpmz1Axlr06
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin transaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Amavis::IO::SQL::open w drv=mysql (INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)); key=eOpmz1Axlr06, p_tag=0
Aug 13 11:55:12 mail amavis[24088]: (24088-04) write_header: 1, Amavis::IO::SQL=HASH(0x8d94788)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql print: key: (eOpmz1Axlr06, 1), p_tag=0, size=16384
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql print: key: (eOpmz1Axlr06, 2), p_tag=0, size=16384
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql print: key: (eOpmz1Axlr06, 3), p_tag=0, size=16384
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql print: key: (eOpmz1Axlr06, 4), p_tag=0, size=16384
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql print: key: (eOpmz1Axlr06, 5), p_tag=0, size=16384
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql flush: key: (eOpmz1Axlr06, 6), p_tag=0, rx_t=1439456112, size=7011
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (4 args): INSERT INTO quarantine (partition_tag, mail_id, chunk_ind, mail_text) VALUES (?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql commit
Aug 13 11:55:12 mail amavis[24088]: (24088-04) one_response_for_all, per_recip_capable: N, suppressed: N
Aug 13 11:55:12 mail amavis[24088]: (24088-04) one_response_for_all <robot@domain.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.6.0 Ok, Stored to sql db as mail_id eOpmz1Axlr06, id=24088-04'
Aug 13 11:55:12 mail amavis[24088]: (24088-04) quar_types: Q, quar_to: eOpmz1Axlr06
Aug 13 11:55:12 mail amavis[24088]: (24088-04) DO_QUARANTINE done
Aug 13 11:55:12 mail amavis[24088]: (24088-04) skip admin notification, no administrators
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(warnbadhrecip) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(warnbadhrecip) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [warnbadhrecip] => undef, "user@domain.net" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) do_notify_and_quarantine - done
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(forward_method) rec=0, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup_sql_field(forward_method) rec=1, "user@domain.net" result: undef
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [forward_method] => true,  "user@domain.net" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) delivery method is 1, recips: user@domain.net
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline quar+notif - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer quar+notif: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) DSN: sender is credible (orig), SA: 0.000, <robot@domain.com>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "robot@domain.com" does not match
Aug 13 11:55:12 mail amavis[24088]: (24088-04) dsn: . 250 BadHdr <robot@domain.com> -> <user@domain.net>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=, destiny=0, mta_resp: "250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) DSN: SUCC (discarded) . 250 BadHdr, destiny=DISCARD: <robot@domain.com> -> <user@domain.net>
Aug 13 11:55:12 mail amavis[24088]: (24088-04) delivery_status_notification: notif 0 bytes, suppressed: no
Aug 13 11:55:12 mail amavis[24088]: (24088-04) one_response_for_all, per_recip_capable: N, suppressed: N
Aug 13 11:55:12 mail amavis[24088]: (24088-04) one_response_for_all <robot@domain.com>: all DISCARD, '250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER'
Aug 13 11:55:12 mail amavis[24088]: (24088-04) notif=N, suppressed=0, ndn_needed=, exit=99, 250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline delivery-notification - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) status counters: InMsgsStatus{Discarded,DiscardedInternal,DiscardedOriginating}
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline snmp-counters - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) orcpt_encode rfc822, user@domain.net, smtputf8
Aug 13 11:55:12 mail amavis[24088]: (24088-04) oldest_public_ip_addr_from_received: 1.1.1.4
Aug 13 11:55:12 mail amavis[24088]: (24088-04) Blocked BAD-HEADER-0 {DiscardedInternal,Quarantined}, MYUSERS LOCAL [1.1.1.4]:59040 [1.1.1.4] <robot@domain.com> -> <user@domain.net>, quarantine: eOpmz1Axlr06, Queue-ID: 3A14222291, Message-ID: <20150813085548731.055562FCFA841D83@billing>, mail_id: eOpmz1Axlr06, Hits: -, size: 89483, 278 ms
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline main_log_entry - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql begin transaction
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) save_info_final eOpmz1Axlr06, orig=Y, chks=HB, cont.ty=H, q.type=Q, q.to=eOpmz1Axlr06, dsn=N, score=0, Message-ID: <20150813085548731.055562FCFA841D83@Billing>, From: '"user" <robot@domain.com>', Subject: 'ÄîêóìåÃòû çà   July 2015'
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql: executing clause (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sql commit
Aug 13 11:55:12 mail amavis[24088]: (24088-04) updating snmp variables in BDB
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline check done - deadline in 479.8 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer check done: timer 288, was 288, deadline in 479.8 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) sending SMTP response: "250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER"
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER
Aug 13 11:55:12 mail postfix/smtp[23970]: 3A14222291: to=<user@domain.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.33, delays=0.03/0/0.01/0.28, dsn=2.6.0, status=sent (250 2.6.0 Ok, discarded, id=24088-04 - BAD HEADER)
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) TempDir::strip: /var/lib/amavis/tmp/amavis-20150813T115423-24088-NFk5YDvm
Aug 13 11:55:12 mail amavis[24088]: (24088-04) rmdir_recursively: /var/lib/amavis/tmp/amavis-20150813T115423-24088-NFk5YDvm/parts, excl=1
Aug 13 11:55:12 mail amavis[24088]: (24088-04) size: 89483, TIMING [total 298 ms] - SMTP greeting: 6 (2%)2, SMTP EHLO: 1.7 (1%)3, SMTP pre-MAIL: 1.8 (1%)3, lookup_sql: 8 (3%)6, lookup_sql: 9 (3%)9, SMTP pre-DATA-flush: 4.0 (1%)10, SMTP DATA: 21 (7%)17, check_init: 2.9 (1%)18, digest_hdr: 2.4 (1%)19, digest_body_dkim: 1.5 (0%)19, collect_info: 8 (3%)22, gen_mail_id: 12 (4%)26, mime_decode: 25 (8%)35, get-file-type4: 99 (33%)68, parts_decode: 3.1 (1%)69, check_header: 6 (2%)71, decide_mail_destiny: 17 (6%)76, notif-quar: 2.9 (1%)77, quar-hdrs: 7 (2%)80, write-header: 10 (4%)83, fwd-sql: 10 (3%)87, prepare-dsn: 3.7 (1%)88, report: 2.9 (1%)89, main_log_entry: 13 (4%)93, sql-update: 8 (3%)96, update_snmp: 4.4 (1%)97, SMTP pre-response: 0.7 (0%)98, SMTP response: 2.5 (1%)98, unlink-4-files: 0.7 (0%)99, rundown: 4.1 (1%)100
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 6: was busy, 271.0 ms, total idle 46.391 s, busy 2.902 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, 5: was idle, 0.2 ms, total idle 46.392 s, busy 2.902 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP< QUIT\r\n
Aug 13 11:55:12 mail amavis[24088]: (24088-04) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Aug 13 11:55:12 mail amavis[24088]: (24088-04) switch_to_client_time 480 s, smtp response sent
Aug 13 11:55:12 mail amavis[24088]: (24088-04) SMTP session over, timer stopped
Aug 13 11:55:12 mail amavis[24088]: (24088-04) exiting process_request
Aug 13 11:55:12 mail amavis[24088]: (24088-04) idle_proc, bye: was busy, 9.4 ms, total idle 46.392 s, busy 2.912 s
Aug 13 11:55:12 mail amavis[24088]: (24088-04) load: 6 %, total idle 46.392 s, busy 2.912 s
Aug 13 11:55:59 mail amavis[24088]: (24088-04) Net::Server: 2015/08/13-11:55:59 CONNECT TCP Peer: "[127.0.0.1]:32985" Local: "[127.0.0.1]:10024"

Anyway it's strange that Amavis isn't bypass header checks throught whitelist

UPD:  check one more time debug log and see that robot@domain.com get W attribute and whitelisted, but anyway whitelist is not working.

in mysql db amavis policy table is empty is it normal?

Aug 13 13:12:21 mail amavis[30189]: (30189-01) wbl: (SQL) recip <robot@domain.com>, 2 matches
Aug 13 13:12:21 mail amavis[30189]: (30189-01) wbl: (SQL) recip <robot@domain.com>, rid=3, got: ""
Aug 13 13:12:21 mail amavis[30189]: (30189-01) wbl: (SQL) recip <robot@domain.com>, rid=1, got: "W"
Aug 13 13:12:21 mail amavis[30189]: (30189-01) wbl: (SQL) recip <robot@domain.com> whitelisted sender <user@domain.net>

4 Reply by drosalevan

  • drosalevan
  • Member
  • Offline
  • Registered: 2015-06-11
  • Posts: 14

Re: Amavis BAD-HEADER and white list

Look's like white list is not bypass header check by amavis. White list is for spam check only. Need to write police rule for amavis to bypass header check for special users or domain.

Close topic.

5 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Amavis BAD-HEADER and white list

Could you share your (working) policy rules?

6 Reply by drosalevan

  • drosalevan
  • Member
  • Offline
  • Registered: 2015-06-11
  • Posts: 14

Re: Amavis BAD-HEADER and white list

ZhangHuangbin wrote:

Could you share your (working) policy rules?

I haven't done it yet. In progress and testing mode.

7 Reply by drosalevan

  • drosalevan
  • Member
  • Offline
  • Registered: 2015-06-11
  • Posts: 14

Re: Amavis BAD-HEADER and white list

So, I can't find solution to skip checking bad header for outgoing message per user or domain (

8 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Amavis BAD-HEADER and white list

We have another thread here, maybe we can move to this one:
http://www.iredmail.org/forum/topic9758 … ntine.html