1 Topic by alvirmob

  • alvirmob
  • Member
  • Offline
  • Registered: 2019-06-21
  • Posts: 4

Topic: server does not apply the DKIM signature

Dear Team,
The server we use hosts three email domains.
I'm trying to add DKIM signing to outbound emails. I followed these guidelines
https://docs.iredmail.org/sign.dkim.sig … omain.html
The keys are in the DNS. The tests are successful
# amavisd-new testkeys
TESTING#1 test.ru: dkim._domainkey.test.com => pass
TESTING#2 test.uk: dkim._domainkey.test.uk => pass
TESTING#3 test.hk: dkim._domainkey.test.hk => pass

However, the server does not apply the signature. Please advise.
Amavis setup file below
https://pastebin.com/UBZPLGd4
main.cf
https://pastebin.com/902gr332
master.cf
https://pastebin.com/ZraSxKhC

I'm not sure if the /etc/nginx/ssl/ certificates are used

Thanks!

----

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

2 Reply by Neutro (edited by Neutro 2019-06-26 03:41:48)

  • Neutro
  • Member
  • Offline
  • Registered: 2014-03-17
  • Posts: 123

Re: server does not apply the DKIM signature

Hi,

Please do not delete the pre-existing bloc when you post a message and use it to give the requested informations to help us help you better.

in your amavis config file:

#
# Disable DKIM signing globally, because it's controlled per policy bank.
$enable_dkim_signing = 1;

This line should be commented out. It is by default on my server and DKIM signing works fine.

Then restart your server and use mail-tester.com to check if DKIM signing works or not

3 Reply by alvirmob

  • alvirmob
  • Member
  • Offline
  • Registered: 2019-06-21
  • Posts: 4

Re: server does not apply the DKIM signature

Hi.
Sorry. Here is it:
==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 0.9.8 PGSQL edition.
- Deployed with iRedMail Easy or the downloadable installer? System was deployed using downloadable installer
- Linux/BSD distribution name and version: Ubuntu 18.04 LTS
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): PGSQL
- Web server (Apache or Nginx): Apache
- Manage mail accounts with iRedAdmin-Pro? No
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Neutro wrote:

This line should be commented out. It is by default on my server and DKIM signing works fine.

It is already enabled in my case

# Enable DKIM verification globally.
$enable_dkim_verification = 1;
 
# Disable DKIM signing globally, because it's controlled per policy bank.
$enable_dkim_signing = 1;

mail-tester.com told me that my email have no DKIM signature.

4 Reply by Neutro (edited by Neutro 2019-06-26 16:19:05)

  • Neutro
  • Member
  • Offline
  • Registered: 2014-03-17
  • Posts: 123

Re: server does not apply the DKIM signature

Sorry if i was not clear enough.

When I said "commented out", I meant "disabled".

This is my server setup where DKIM works fine (i removed my domain name with red squares for confidentiality):

Post's attachments

amavis_conf.png
amavis_conf.png 18.56 kb, 3 downloads since 2019-06-26 

You don't have the permssions to download the attachments of this post.

5 Reply by alvirmob

  • alvirmob
  • Member
  • Offline
  • Registered: 2019-06-21
  • Posts: 4

Re: server does not apply the DKIM signature

I turn on the debug log in amavis and send email.

 tail -f /var/log/mail.log
Jun 26 12:13:36 mail02 amavis[5338]: Net::Server: Parent ready for children.
Jun 26 12:13:36 mail02 amavis[5352]: Net::Server: Child Preforked (5352)
Jun 26 12:13:36 mail02 amavis[5352]: entered child_init_hook
Jun 26 12:13:36 mail02 amavis[5352]: storage and lookups will use the same connection to SQL
Jun 26 12:13:36 mail02 amavis[5352]: SpamControl: init_child on SpamAssassin done
Jun 26 12:13:36 mail02 amavis[5353]: Net::Server: Child Preforked (5353)
Jun 26 12:13:36 mail02 amavis[5346]: SpamControl: init_child on SpamAssassin done
Jun 26 12:13:36 mail02 amavis[5353]: entered child_init_hook
Jun 26 12:13:36 mail02 amavis[5353]: storage and lookups will use the same connection to SQL
Jun 26 12:13:36 mail02 amavis[5353]: SpamControl: init_child on SpamAssassin done
Jun 26 12:14:27 mail02 postfix/submission/smtpd[5461]: connect from ip-a-b-c-d.***.com[d.c.b.a]
Jun 26 12:14:27 mail02 postfix/submission/smtpd[5461]: Anonymous TLS connection established from ip-a-b-c-d.***.com[d.c.b.a]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 26 12:14:27 mail02 postfix/submission/smtpd[5461]: D4341D660E6: client=ip-a-b-c-d.***.com[d.c.b.a], sasl_method=LOGIN, sasl_username=test@test.com
Jun 26 12:14:28 mail02 postfix/cleanup[5024]: D4341D660E6: message-id=<016f01d52bff$8efa97a0$acefc6e0$@test.com>
Jun 26 12:14:28 mail02 postfix/qmgr[1591]: D4341D660E6: from=<test@test.com>, size=2742, nrcpt=1 (queue active)
Jun 26 12:14:28 mail02 amavis[5343]: Net::Server: 2019/06/26-12:14:28 CONNECT TCP Peer: "[127.0.0.1]:36126" Local: "[127.0.0.1]:10026"
Jun 26 12:14:28 mail02 amavis[5343]: loaded base policy bank
Jun 26 12:14:28 mail02 amavis[5343]: loaded policy bank "ORIGINATING"
Jun 26 12:14:28 mail02 amavis[5343]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Jun 26 12:14:28 mail02 amavis[5343]: process_request: fileno sock=10, STDIN=0, STDOUT=1
Jun 26 12:14:28 mail02 amavis[5343]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: process_request: suggested_protocol="" on a TCP socket
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 4: was busy, 3.7 ms, total idle 0.000 s, busy 0.004 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp readline: read 24 bytes, new size: 24
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.000 s, busy 0.004 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) SMTP< EHLO mail02.test.com\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-[127.0.0.1]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-VRFY
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-PIPELINING
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-SIZE
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-8BITMIME
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-SMTPUTF8
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250-DSN
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 0.9 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp readline: read 238 bytes, new size: 238
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< XFORWARD NAME=ip-a-b-c-d.***.com ADDR=d.c.b.a PORT=59055\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 0.4 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< XFORWARD PROTO=ESMTP HELO=DESKTOPNI9G1S4 IDENT=D4341D660E6 SOURCE=REMOTE\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 0.3 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.000 s, busy 0.005 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< MAIL FROM:<test@test.com> SIZE=2742\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) check_mail_begin_task: task_count=1
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) TempDir::prepare_dir: created directory /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) TempDir::prepare_file: creating file /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/email.txt
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) TempDir::prepare_file: layers: unix,perlio
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="a.b.c.d", no match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [debug_sender] => undef, "test@test.com" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) mesage size set to a declared size 2742
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 2.1.0 Sender <test@test.com> OK
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 2.1 ms, total idle 0.000 s, busy 0.007 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.0 ms, total idle 0.000 s, busy 0.007 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< RCPT TO:<other_test@ya.ru> ORCPT=rfc822;other_test@ya.ru\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup => undef, "other_test@ya.ru", no lookup tables
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="1"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [local_domains] => true,  "other_test@ya.ru" matches, result="1", matching_key="(constant:1)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) query_keys: other_test@ya.ru, other_test, @ya.ru, @.ya.ru, @.ru, @.
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql sel_policy "other_test@ya.ru", query args: [other_test@ya.ru,-3], [other_test,-3], [@ya.ru,-3], [@.ya.ru,-3], [@.ru,-3], [@.,-3]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) 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
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql begin, nontransaction
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Connecting to SQL database server
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) connect_to_sql: trying 'DBI:Pg:database=amavisd;host=127.0.0.1;port=5432'
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) connect_to_sql: 'DBI:Pg:database=amavisd;host=127.0.0.1;port=5432' succeeded
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: preparing and executing (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
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql, "other_test@ya.ru" no match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(message_size_limit), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [message_size_limit] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 2.1.5 Recipient <other_test@ya.ru> OK
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 10.9 ms, total idle 0.000 s, busy 0.018 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.018 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< DATA\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP [127.0.0.1]:10026 /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK: <test@test.com> -> <other_test@ya.ru> SIZE=2742 Received: from mail02.test.com ([127.0.0.1]) by mail02.test.com (mail02.test.com [127.0.0.1]) (amavisd-new, port 10026) with ESMTP for <other_test@ya.ru>; Wed, 26 Jun 2019 12:14:28 +0300 (MSK)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, receiving data
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp copy: read 2529 bytes into buffer, new size: 2529
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp copy: 6 bytes still buffered at end
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< .<CR><LF>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Actual message size 2520 B less than the declared 2742 B
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) DNS resolver created, UDP payload size 1220, NS: 127.0.0.53
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_body_digest: reading header section from memory
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_body_digest: feeding header section to DKIM verifier
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_body_digest: sending h/b separator to DKIM
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_body_digest: reading mail body from memory, 0 DKIM signatures
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_body_digest: message size adjusted 2520 -> 2519, header+sep 359, body 2160
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) body type (8bit-MIMEtransport): unlabeled, good (h=0, b=0)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) body hash: c399b3566fc7f74fcf158bcd6d15d1ee
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prepending client's IP address to trace: a.b.c.d
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_ip_acl (public_nets) arr.obj: key="a.b.c.d" matches "::ffff:0:0/96", result=1
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) trace: ESMTP://[127.0.0.1]:36126 < ESMTP://[a.b.c.d]:59055
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Original mail size: 2519; quota set to: 1259500 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql begin, nontransaction
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) save_info_preliminary VWv7MEET8fyY, sender id: 76, test@test.com, exists
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql begin, nontransaction
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) orcpt_encode rfc822, other_test@ya.ru, smtputf8
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) save_info_preliminary VWv7MEET8fyY, recip id: 80, other_test@ya.ru (ORCPT rfc822;other_test@ya.ru), exists
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql begin transaction
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: preparing and executing (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql commit
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Checking: VWv7MEET8fyY ORIGINATING [a.b.c.d] <test@test.com> -> <other_test@ya.ru>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) 2822.From: <test@test.com>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(local), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="1"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [local_domains] => true,  "other_test@ya.ru" matches, result="1", matching_key="(constant:1)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(bypass_virus_checks), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="0"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [bypass_virus_checks] => false, "other_test@ya.ru" matches, result="0", matching_key="(constant:0)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(bypass_banned_checks), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [bypass_banned_checks] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(bypass_spam_checks), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="0"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [bypass_spam_checks] => false, "other_test@ya.ru" matches, result="0", matching_key="(constant:0)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(id), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [users.id] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(policy_id), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [users.policy_id] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Extracting mime components from a string
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Issued a new file name: p001
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Issued a new file name: p002
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) mime_decode_preamble: 1 lines
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Issued a new pseudo part: p003
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) p003 1 Content-Type: multipart/alternative
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) mime_decode_epilogue: 1 lines
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Charging 8 bytes to remaining quota 1259500 (out of 1259500, (0%)) - by mime_decode
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) p001 1/1 Content-Type: text/plain, 7bit, size: 8, SHA1 digest: e9cc2fd4c27b4c4fec500c3089f59bfb72dcbacd
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) reparenting p001 from p000 to p003
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Charging 1670 bytes to remaining quota 1259492 (out of 1259500, (0%)) - by mime_decode
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) p002 1/2 Content-Type: text/html, QP, size: 1670, SHA1 digest: c721ea5fd70414526f7880ed98a79ba73c96a2ac
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) reparenting p002 from p000 to p003
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) running file(1) on 2 files, arglist size 23
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_command: [5486] /usr/bin/file p001 p002 </dev/null 2>&1
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: target fd1 closing, to become (65) &=14
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: target fd1 dup2 from fd14 (65) &=14
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: source fd14 closed
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jun 26 12:14:28 mail02 amavis[5486]: (05343-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) result line from file(1): p001: ASCII text\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) File-type of p001: ASCII text; (asc)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) result line from file(1): p002: HTML document, ASCII text, with very long lines\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("HTML document, ASCII text, with very long lines") matches key "(?^i:\\btext\\b)", result="asc"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [map_full_type_to_short_type] => true,  "HTML document, ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) File-type of p002: HTML document, ASCII text, with very long lines; (asc)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) decompose_part: p001 - atomic
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) decompose_part: p002 - atomic
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(bypass_header_checks), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [bypass_header_checks] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) check_header: 0, OK
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(bypass_header_checks), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [bypass_header_checks] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Checking for banned types and filenames
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(banned_rulenames), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="DEFAULT"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [banned_filename], 1 matches for "other_test@ya.ru", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) collect banned table[0]: other_test@ya.ru, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x55a0027a96a0)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) starting banned checks - traversing message structure tree
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) doing banned check for other_test@ya.ru on multipart/alternative | text/plain,.asc
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [check_bann:other_test@ya.ru] => undef, ["multipart/alternative","text/plain",".asc"] does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc"), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) p.path other_test@ya.ru: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) doing banned check for other_test@ya.ru on multipart/alternative | text/html,.asc
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [check_bann:other_test@ya.ru] => undef, ["multipart/alternative","text/html",".asc"] does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc"), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) p.path other_test@ya.ru: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) banned check: any=0, all=N (1)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("MAIL"), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) invoking av-scanner clamav-socket
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ask_daemon: proto=DFLT, spawn=0, (clamav-socket) /var/run/clamav/clamd.ctl
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_av (clamav-socket): query template(1,1): CONTSCAN {}\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline run_av_pre - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline run_av_scan - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer run_av_scan: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_av Using (clamav-socket): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) clamav-socket: Connecting to socket  /var/run/clamav/clamd.ctl
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) connected to /var/run/clamav/clamd.ctl successfully
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) clamav-socket: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts\n to socket /var/run/clamav/clamd.ctl
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: sending 73 chars
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts: OK\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read: got eof
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline ask_daemon_internal - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline run_av_3 - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer run_av_3: timer 288, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_av (clamav-socket) result: /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts: OK\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_av (clamav-socket): CLEAN
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) run_av (clamav-socket) result: clean
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) wbl: checking sender <test@test.com>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) wbl: (SQL) recip <other_test@ya.ru>, 0 matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [blacklist_recip<other_test@ya.ru>] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [blacklist_sender<test@test.com>,blacklist_sender] => undef, "test@test.com" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [whitelist_recip<other_test@ya.ru>] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_acl(test@test.com), no match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [whitelist_sender<test@test.com>,whitelist_sender] => undef, "test@test.com" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) query_keys: other_test@ya.ru, other_test@, ya.ru, .ya.ru, .ru, .
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_hash(other_test@ya.ru) matches keys: "."=>ARRAY(0x55a002efeaa8)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [score_recip<other_test@ya.ru>,score_sender], 1 matches for "other_test@ya.ru", results: "."=>[Amavis::Lookup::RE=ARRAY(0x55a002d5f310),{sender@example.net=>"3",slashdot@slashdot.org=>"-3",owner-technews@postel.acm.org=>"-3",security-alerts@linuxsecurity.com=>"-3",owner-textbreakingnews@cnnimail12.cnn.com=>"-5",cert-advisory@us-cert.gov=>"-3",mailman-announce-admin@python.org=>"-3",.example.net=>"1",clp-request@comp.nus.edu.sg=>"-3",sendmail-announce-request@lists.sendmail.org=>"-3",owner-postfix-users@postfix.org=>"-3",rt-users-admin@lists.fsck.com=>"-3",amavis-user-admin@lists.sourceforge.net=>"-3",donotreply@sendmail.org=>"-3",yahoo-dev-null@yahoo-inc.com=>"-3",owner-sendmail-announce@lists.sendmail.org=>"-3",notification-return@lists.sophos.com=>"-3",ietf-123-owner@loki.ietf.org=>"-3",ntbugtraq@listserv.ntbugtraq.com=>"-3",returns.groups.yahoo.com=>"-3",amavis-user-bounces@lists.sourceforge.net=>"-3",surveys-errors@lists.nua.ie=>"-3",nobody@cert.org=>...
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ..."-3",noreply@freshmeat.net=>"-3",ca+envelope@sendmail.org=>"-3",cvs-commits-list-admin@gnome.org=>"-3",owner-alert@iss.net=>"-3",emailnews@genomeweb.com=>"-5",owner-postfix-announce@postfix.org=>"-3",spamassassin.apache.org=>"-3",clusternews@linuxnetworx.com=>"-3",securityfocus.com=>"-3",lvs-users-admin@linuxvirtualserver.org=>"-3"}]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_re("test@test.com"), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) query_keys: test@test.com, a.chaika@, test.com, .test.com, .ru, .
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_hash(test@test.com), no matches
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [score_sender<test@test.com>] => undef, "test@test.com" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) SpamControl: calling spam scanner SpamAssassin
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline spam_scan_sa_pre - deadline in 480.0 s, set to 476.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(sa_userconf), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [sa_userconf] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(sa_username), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [sa_username] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) SA user config: "", username: "amavis", 0, (0)other_test@ya.ru
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) calling SA parse (0), SA vers 3.4.2, 3.004002, data as STRING_REF, recips_ind [0], user: "amavis"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline SA check - deadline in 480.0 s, set to 475.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) mimepart digest: e9cc2fd4c27b4c4fec500c3089f59bfb72dcbacd:text/plain
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) mimepart digest: c721ea5fd70414526f7880ed98a79ba73c96a2ac:text/html
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) CALLING SA check (0)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) DONE SA check (0)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline spam_scan_sa - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer spam_scan_sa: timer 288, was 476, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) spam_scan: score=0.1 autolearn=no autolearn_force=no tests=[HTML_MESSAGE=0.001,MIME_HTML_MOSTLY=0.1,NO_RECEIVED=-0.001,NO_RELAYS=-0.001,TVD_SPACE_RATIO=0.001] recips=0
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline spam_scan - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer spam_scan: timer 288, was 288, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_tag_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="2"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_tag_level] => true,  "other_test@ya.ru" matches, result="2", matching_key="(constant:2)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_tag2_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="6.2"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_tag2_level] => true,  "other_test@ya.ru" matches, result="6.2", matching_key="(constant:6.2)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_tag3_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_tag3_level] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_kill_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="6.9"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_kill_level] => true,  "other_test@ya.ru" matches, result="6.9", matching_key="(constant:6.9)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(message_size_limit), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [message_size_limit] => undef, "other_test@ya.ru" does not match
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) final_destiny (ccat=0) is PASS, recip other_test@ya.ru
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) final_destiny PASS, recip other_test@ya.ru
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) do_notify_and_quarantine: not quarantining, q_method off
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) skip admin notification, no administrators
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) do_notify_and_quarantine - done
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(forward_method), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [forward_method] => true,  "other_test@ya.ru" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) delivery method is 1, recips: other_test@ya.ru
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_tag_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="2"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_tag_level] => true,  "other_test@ya.ru" matches, result="2", matching_key="(constant:2)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup_sql_field(spam_tag2_level), "other_test@ya.ru" no matching records
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="6.2"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_tag2_level] => true,  "other_test@ya.ru" matches, result="6.2", matching_key="(constant:6.2)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) headers CLUSTERING: NEW CLUSTER <other_test@ya.ru>: score=0.1, tag=0, tag2=0, local=1, bl=, s=, mangle=
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at mail02.test.com
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) header: X-Virus-Scanned: Debian amavisd-new at mail02.test.com\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) fwd: scanner provided a header field X-Spam-Level, but we preferred our own
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) fwd: scanner provided a header field X-Spam-Status, but we preferred our own
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) headers CLUSTERING: done all 1 recips in one go
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) dkim: not signing mail which is not originating from our site
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) about to connect to smtp:[127.0.0.1]:10025, VWv7MEET8fyY FWD from <test@test.com> -> <other_test@ya.ru>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp session: setting up a new session
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) establish_or_refresh, state: down
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) connected to [127.0.0.1]:10025 successfully
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jun 26 12:14:28 mail02 postfix/10025/smtpd[4694]: connect from mail02.test.com[127.0.0.1]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read 37 chars< 220 mail02.test.com ESMTP Postfix\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp greeting: 220 mail02.test.com ESMTP Postfix, dt: 0.7 ms
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp cmd> EHLO mail02.test.com
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: sending 24 chars
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop sent 24> EHLO mail02.test.com\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read 130 chars< 250-mail02.test.com\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250 SMTPUTF8\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp resp to EHLO: 250 mail02.test.com\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nSMTPUTF8
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) tls active=0, capable=, sec_level=0
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Remote host presents itself as: mail02.test.com, handles DSN, PIPELINING, 8BITMIME, SMTPUTF8
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) AUTH not needed, user='', MTA offers ''
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp cmd> MAIL FROM:<test@test.com> BODY=7BIT
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) orcpt_encode rfc822, other_test@ya.ru, encode_for_smtp
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp cmd> RCPT TO:<other_test@ya.ru> ORCPT=rfc822;other_test@ya.ru
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp cmd> DATA
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: sending 97 chars
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop sent 97> MAIL FROM:<test@test.com> BODY=7BIT\r\nRCPT TO:<other_test@ya.ru> ORCPT=rfc822;other_test@ya.ru\r\nDATA\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jun 26 12:14:28 mail02 postfix/10025/smtpd[4694]: 3A5CFD66114: client=mail02.test.com[127.0.0.1]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp resp to RCPT (pip) (<other_test@ya.ru>): 250 2.1.5 Ok
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x55a00881cf60)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp connection_cache disabled, sending QUIT
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp cmd> QUIT
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.953
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: sending 2587 chars
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop sent 2587> X-Virus-Scanned: Debian amavisd-new at mail02.test.com\r\nFrom: "Alex Chaika" <test@test.com>\r\nTo: <other_test@ya.ru>\r\nSubject: ddkim\r\nDate: Wed, 26 Jun 2019 12:14:28 +0300\r\nMessage-ID: <016f01d52bff [...]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.953
Jun 26 12:14:28 mail02 postfix/cleanup[4998]: 3A5CFD66114: message-id=<016f01d52bff$8efa97a0$acefc6e0$@test.com>
Jun 26 12:14:28 mail02 postfix/qmgr[1591]: 3A5CFD66114: from=<test@test.com>, size=2761, nrcpt=1 (queue active)
Jun 26 12:14:28 mail02 postfix/10025/smtpd[4694]: disconnect from mail02.test.com[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop: receiving
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rw_loop read 52 chars< 250 2.0.0 Ok: queued as 3A5CFD66114\r\n221 2.0.0 Bye\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) smtp resp to data-dot (<other_test@ya.ru>): 250 2.0.0 Ok: queued as 3A5CFD66114, dt: 7.3 ms
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Amavis::Out::SMTP::Session close, disconnecting
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) VWv7MEET8fyY FWD from <test@test.com> -> <other_test@ya.ru>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline forwarding - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer forwarding: timer 288, was 288, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) DSN: sender NOT credible, SA: 0.100, <test@test.com>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup: (scalar) matches, result="10"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) lookup [spam_dsn_cutoff_level_bysender] => true,  "test@test.com" matches, result="10", matching_key="(constant:10)"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) dsn: from MTA 250 NonBlocking:Clean <test@test.com> -> <other_test@ya.ru>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <test@test.com> -> <other_test@ya.ru>
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) delivery_status_notification: notif 0 bytes, suppressed: no
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) one_response_for_all, per_recip_capable: N, suppressed: N
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) one_response_for_all <test@test.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114'
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline delivery-notification - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline snmp-counters - deadline in 479.9 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.9 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) orcpt_encode rfc822, other_test@ya.ru, smtputf8
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) oldest_public_ip_addr_from_received: a.b.c.d
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) Passed CLEAN {RelayedInbound}, ORIGINATING [a.b.c.d]:59055 [a.b.c.d] <test@test.com> -> <other_test@ya.ru>, Queue-ID: D4341D660E6, Message-ID: <016f01d52bff$8efa97a0$acefc6e0$@test.com>, mail_id: VWv7MEET8fyY, Hits: 0.1, size: 2519, queued_as: 3A5CFD66114, 198 ms, Tests: [HTML_MESSAGE=0.001,MIME_HTML_MOSTLY=0.1,NO_RECEIVED=-0.001,NO_RELAYS=-0.001,TVD_SPACE_RATIO=0.001]
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline main_log_entry - deadline in 479.8 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.8 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql begin transaction
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: preparing and executing (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) save_info_final VWv7MEET8fyY, orig=N, chks=VSHB, cont.ty=C, q.type= , q.to=, dsn=N, score=0.1, Message-ID: <016f01d52bff$8efa97a0$acefc6e0$@test.com>, From: '"Alex Chaika" <test@test.com>', Subject: 'ddkim'
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql: preparing and executing (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sql commit
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) TIMING-SA total 48 ms - parse: 1.07 (2.3%), extract_message_metadata: 5 (11.0%), get_uri_detail_list: 0.15 (0.3%), tests_pri_-1000: 3.3 (7.0%), tests_pri_-950: 0.79 (1.7%), tests_pri_-900: 0.77 (1.6%), tests_pri_-90: 0.64 (1.3%), tests_pri_0: 27 (55.9%), check_dkim_adsp: 1.92 (4.0%), check_spf: 0.16 (0.3%), tests_pri_20: 0.61 (1.3%), tests_pri_30: 0.69 (1.4%), check_pyzor: 0.09 (0.2%), tests_pri_500: 2.2 (4.6%), get_report: 0.15 (0.3%)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline check done - deadline in 479.8 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer check done: timer 288, was 288, deadline in 479.8 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114"
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 postfix/amavis/smtp[4983]: D4341D660E6: to=<other_test@ya.ru>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.48, delays=0.28/0/0.01/0.2, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3A5CFD66114)
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20190626T121428-05343-SUG7qVJK/parts, excl=1
Jun 26 12:14:28 mail02 postfix/qmgr[1591]: D4341D660E6: removed
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) size: 2519, TIMING [total 204 ms] - sql-prepare: 1.9 (1%)1, SMTP greeting: 1.7 (1%)2, SMTP EHLO: 1.1 (1%)2, SMTP pre-MAIL: 1.2 (1%)3, mkdir tempdir: 0.7 (0%)3, create email.txt: 0.2 (0%)3, SMTP MAIL: 1.0 (0%)4, sql-connect: 9 (4%)8, lookup_sql: 1.7 (1%)9, SMTP pre-DATA-flush: 1.1 (1%)10, SMTP DATA: 27 (13%)23, check_init: 0.2 (0%)23, digest_hdr: 1.0 (0%)23, digest_body_dkim: 0.3 (0%)24, collect_info: 0.6 (0%)24, gen_mail_id: 6 (3%)27, mkdir parts: 1.1 (1%)27, mime_decode: 7 (3%)31, get-file-type2: 13 (6%)37, parts_decode: 0.2 (0%)37, check_header: 0.7 (0%)37, AV-scan-1: 9 (4%)42, spam-wb-list: 1.6 (1%)42, SA msg read: 0.5 (0%)43, SA parse: 2.1 (1%)44, SA check: 46 (22%)66, decide_mail_destiny: 2.1 (1%)67, notif-quar: 0.2 (0%)67, fwd-connect: 3.7 (2%)69, fwd-mail-pip: 44 (22%)91, fwd-rcpt-pip: 0.2 (0%)91, fwd-data-chkpnt: 0.0 (0%)91, write-header: 0.3 (0%)91, fwd-data-contents: 0.1 (0%)91, fwd-end-chkpnt: 8 (4%)95, prepare-dsn: 1.2 (1%)96, report: 1.2 (...
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ...1%)96, main_log_entry: 2.1 (1%)97, sql-update: 4.4 (2%)99, SMTP pre-response: 0.2 (0%)100, SMTP response: 0.2 (0%)100, unlink-2-files: 0.2 (0%)100, rundown: 0.5 (0%)100
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 6: was busy, 185.3 ms, total idle 0.001 s, busy 0.204 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.204 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP< QUIT\r\n
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) switch_to_client_time 480 s, smtp response sent
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) SMTP session over, timer stopped
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) exiting process_request
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) idle_proc, bye: was busy, 1.4 ms, total idle 0.001 s, busy 0.205 s
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) load: 100 %, total idle 0.001 s, busy 0.205 s
Jun 26 12:14:28 mail02 postfix/out_ru/smtp[5494]: Trusted TLS connection established to mx.yandex.ru[213.180.204.89]:25: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jun 26 12:14:29 mail02 postfix/out_ru/smtp[5494]: 3A5CFD66114: to=<other_test@ya.ru>, relay=mx.yandex.ru[213.180.204.89]:25, delay=1.3, delays=0.02/0.02/0.47/0.83, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued on mxfront6o.mail.yandex.net as 1561540469-d0RZh1x3Ks-ESrimttu)
Jun 26 12:14:29 mail02 postfix/qmgr[1591]: 3A5CFD66114: removed
Jun 26 12:14:30 mail02 postfix/submission/smtpd[5461]: disconnect from ip-a-b-c-d.***.com[d.c.b.a] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8

6 Reply by alvirmob

  • alvirmob
  • Member
  • Offline
  • Registered: 2019-06-21
  • Posts: 4

Re: server does not apply the DKIM signature

I try this
https://forum.iredmail.org/topic14431-d … -smtp.html

patch amavisd-new < pathfile
patching file amavisd-new
Hunk #1 succeeded at 34361 (offset 23 lines).
root@mail02:/usr/sbin# amavisd-new -h
amavisd-new-2.11.0 (20160426)

No result

7 Reply by Neutro (edited by Neutro 2019-06-26 21:44:01)

  • Neutro
  • Member
  • Offline
  • Registered: 2014-03-17
  • Posts: 123

Re: server does not apply the DKIM signature

Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) headers CLUSTERING: done all 1 recips in one go
Jun 26 12:14:28 mail02 amavis[5343]: (05343-01) dkim: not signing mail which is not originating from our site

This is what is wrong and why you dont have DKIM signing.

Your amavis setup doesn't recognize your domain "test.com" as a declared local domain for dkim.

This is what happen when i send a mail on my mail server so you can compare (i replaced my domain name by "localdomain.com"):

Jun 26 13:10:24 mail amavis[32233]: (32233-01) headers CLUSTERING: done all 1 recips in one go
Jun 26 13:10:24 mail amavis[32233]: (32233-01) dkim: candidate originators: From:<user@localdomain.com>
Jun 26 13:10:24 mail amavis[32233]: (32233-01) query_keys: cached user@localdomain.com
Jun 26 13:10:24 mail amavis[32233]: (32233-01) lookup_hash(user@localdomain.com) matches keys: "."=>HASH(xxxxxxxxxxxx)
Jun 26 13:10:24 mail amavis[32233]: (32233-01) lookup [dkim_signature_options_bysender], 1 matches for "user@localdomain.com", results: "."=>{d=>"localdomain.com",a=>"rsa-sha256",c=>"relaxed/simple",ttl=>"2592000"}
Jun 26 13:10:24 mail amavis[32233]: (32233-01) dkim: signature options for user@localdomain.com(From): a=rsa-sha256; d=localdomain.com; c=relaxed/simple; ttl=2592000
Jun 26 13:10:24 mail amavis[32233]: (32233-01) dkim: signing (author), From: <user@localdomain.com> (From:<user@localdomain.com>), KEY.key_ind=>0, a=>rsa-sha256, c=>relaxed/simple, d=>localdomain.com, s=>dkim, ttl=>2592000, x=>1564139423
Jun 26 13:10:24 mail amavis[32233]: (32233-01) write_header: 1, Amavis::Out::SMTP=HASH(xxxxxxxxxxxxxx)
Jun 26 13:10:24 mail amavis[32233]: (32233-01) header encoded (all-ASCII): DKIM-Signature:  v=1; a=rsa-sha256; c=relaxed/simple; d=localdomain.com; h=\n\tcontent-language:x-mailer:content-type:content-type:mime-version\n\t:message-id:date:date:subject:subject:to:from:from; s=dkim; t=\(...)
Jun 26 13:10:24 mail amavis[32233]: (32233-01) header: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=localdomain.com; h=\n\tcontent-language:x-mailer:content-type:content-type:mime-version\n\t:message-id:date:date:subject:subject:to:from:from; s=dkim; t=\(...)
Jun 26 13:10:24 mail amavis[32233]: (32233-01) header encoded (all-ASCII): Authentication-Results: mail.localdomain.com (amavisd-new);\n dkim=pass (1024-bit key)\n reason="pass (just generated, assumed good)"\n header.d=localdomain.com
Jun 26 13:10:24 mail amavis[32233]: (32233-01) header: Authentication-Results: mail.localdomain.com (amavisd-new); dkim=pass (1024-bit key)\n\treason="pass (just generated, assumed good)" header.d=localdomain.com\n

In your amavis config file you used simple quotes ' instead of double quotes " at @dkim_signature_options_bysender_maps, maybe it's the problem...

If it's not, i suggest you stop using specific domain dkim key and try to use 1 dkim key for all domains to see if it works for debug (# catch-all parameter in amavis config file as stated in https://docs.iredmail.org/sign.dkim.sig … omain.html "Use one DKIM key for all mail domains"

Dont forget to restart amavis service after wink

Also for new tests please set amavis log_level spam assasin to 0 ($sa_debug = 0;) as spam assasin has nothing to do here and it's only polluting your log.

Also send a test mail to mail-tester.com instead of "other_test@ya.ru" and post the log result here wink