1 Topic by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Topic: Can't pass DKIM signature verification because of extra space

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.6.4 (updated from 1.6.0)
- Deployed with iRedMail Easy or the downloadable installer? downloadable installer
- Linux/BSD distribution name and version: Ubuntu 22.04.03
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? no
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Hello,
I'm trying to pass DKIM verification through mxtoolbox deliverability service but can't.

I have 3 domains on my mail server. 2 of them work perfect. But last domain can't pass the DKIM verification.

I compare the difference between domains and found, that DKIM signature of last domain has an extra space:

v=1; a=rsa-sha256; c=relaxed/simple; d= my-domain-name.com; h=content-transfer-encoding:content-type :subject:from:to:content-language:user-agent:mime-version:date :message-id; s=dkim; t=1694823469; x=1695687470; bh=F7ndoL6kX66T 9FqSrturyhoqoYalK7+UwtaSPf1tGLY=; b=ocFw3TFQsIQ7B1i1nEO5LE+jz65o Y7Q74VwdFZHoUddoOyvgtwQE6NZZFujT0ji/w5OAKC9NK9EG5XAJIDTNPhD/HpTi w6WEbiZcKsrVVXVKZDW88uStwRXa9D2gwFjEbb0A57VuHKLvbUhD35J1e/qp98Nu 22T80uSX6eYNunrKW2N490aySboez1VplXMvL6213Rc6iMBToX6+OccpxL5v2Cvk +pxnY0rLyGWE61wBwgkZkJJ3moTcYXTV1+r9hVOHgCjy7DlxhPvJeLMh2+7uLrt+ 8Irc8FqvO1mmwWDCFnsi4WcajS0ec0nY0CI0sdhaD0rKRwsnIPN2E2OvdQ==

Take a look on "d= my-domain-name.com; " it has the space after "d=". That is all the difference between correct domains and incorrect one.

I tried:

  • Update iredmail to the latest version.

  • Run "apt update".

  • Recreate the domain through iRedAdmin.

  • Use other DKIM verification services. But they note the same issue "DKIM signature is not verified"

The rows from file "/etc/amavis/conf.d/50-user". They have no extra spaces.

dkim_key('my-domain-name.com', 'dkim', '/var/lib/dkim/my-domain-name.com.pem');
...
"my-domain-name.com"  => { d => "my-domain-name.com", a => 'rsa-sha256', ttl => 10*24*3600 },

----

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,352

Re: Can't pass DKIM signature verification because of extra space

Looks like the domain name in /etc/amavis/conf.d/50-user has an extra space, i suggest double check:

@dkim_signature_options_bysender_maps = ({
    "domain.com"  => { d => "domain.com", ...},

    # catch-all (one dkim key for all domains)
    '.' => {d => 'PH_FIRST_DOMAIN', ...},
});

3 Reply by Cthulhu

  • Cthulhu
  • Member
  • Offline
  • Registered: 2019-06-04
  • Posts: 955

Re: Can't pass DKIM signature verification because of extra space

does the domain contain special chars?

4 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

ZhangHuangbin wrote:

Looks like the domain name in /etc/amavis/conf.d/50-user has an extra space, i suggest double check:

@dkim_signature_options_bysender_maps = ({
    "domain.com"  => { d => "domain.com", ...},

    # catch-all (one dkim key for all domains)
    '.' => {d => 'PH_FIRST_DOMAIN', ...},
});

No, it doesn't have any spaces. The 

 d => "domain.com"

section is correct.

5 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

Cthulhu wrote:

does the domain contain special chars?

It has only Latin characters and two "-". It has 3 words that breaks by "-". It looks like this "my-domain-name.com".

6 Reply by Axenic (edited by Axenic 2023-11-18 15:01:11)

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

I did some research.

First: I run amavisd in debug mode using command

amavisd-new -c  /etc/amavis/conf.d/50-user debug

and sent an email to ping@tools.mxtoolbox.com. The output log is attached to message. I found next interesting moments:

1. Take a look on rows 202 and 203. Why do they have prefix "\n\t"?
2. Take a look on row 281. It has ASCII characters. Is it a problem?

Second: I run command

grep -rls $'\tmy-site-domain.com' .

and found that only these files contain "\t" symbol before domain name

/proc/kcore
/proc/2420432/task/2420432/cmdline
/proc/2420432/cmdline

I hope this debug information could help to find the problem place.

Output log:

Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: Net::Server: 2023/11/09-01:34:50 CONNECT TCP Peer: "[127.0.0.1]:59558" Local: "[127.0.0.1]:10026"
Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: post_accept_hook: invoking child_init_hook which was skipped
Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: entered child_init_hook
Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: storage and lookups will use the same connection to SQL
Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: loaded base policy bank
Nov  9 01:34:50.804 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: loaded policy bank "ORIGINATING"
Nov  9 01:34:50.805 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Nov  9 01:34:50.805 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: process_request: fileno sock=10, STDIN=0, STDOUT=1
Nov  9 01:34:50.805 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.805 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Nov  9 01:34:50.805 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: process_request: suggested_protocol="" on a TCP socket
Nov  9 01:34:50.806 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Nov  9 01:34:50.806 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.806 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 4: was busy, 1.8 ms, total idle 0.000 s, busy 0.002 s
Nov  9 01:34:50.807 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp readline: read 23 bytes, new size: 23
Nov  9 01:34:50.807 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.9 ms, total idle 0.001 s, busy 0.002 s
Nov  9 01:34:50.807 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) SMTP< EHLO mail.mymailserver.com\r\n
Nov  9 01:34:50.807 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.807 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-[127.0.0.1]
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-VRFY
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-PIPELINING
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-SIZE
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-ENHANCEDSTATUSCODES
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-8BITMIME
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-SMTPUTF8
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-DSN
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 1.8 ms, total idle 0.001 s, busy 0.004 s
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp readline: read 260 bytes, new size: 260
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.004 s
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< XFORWARD ADDR=176.124.200.110 PORT=56362\r\n
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 2.5.0 Ok XFORWARD
Nov  9 01:34:50.809 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 0.7 ms, total idle 0.001 s, busy 0.004 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.004 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< XFORWARD PROTO=ESMTP HELO=[0.0.0.0] IDENT=4SQkyy49wgz4xdd SOURCE=REMOTE\r\n
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 2.5.0 Ok XFORWARD
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.005 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.005 s
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< MAIL FROM:<admin@my-site-domain.com> SIZE=637 BODY=8BITMIME\r\n
Nov  9 01:34:50.810 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.811 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.811 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) check_mail_begin_task: task_count=1
Nov  9 01:34:50.812 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) TempDir::prepare_dir: created directory /var/lib/amavis/tmp/amavis-20231109T013450-1263265-Fxhtpgjw
Nov  9 01:34:50.812 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) TempDir::prepare_file: creating file /var/lib/amavis/tmp/amavis-20231109T013450-1263265-Fxhtpgjw/email.txt
Nov  9 01:34:50.813 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) TempDir::prepare_file: layers: unix,perlio
Nov  9 01:34:50.813 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="176.124.200.110", no match
Nov  9 01:34:50.813 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [debug_sender] => undef, "admin@my-site-domain.com" does not match
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) mesage size set to a declared size 637
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 2.1.0 Sender <admin@my-site-domain.com> OK
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 3.6 ms, total idle 0.001 s, busy 0.008 s
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.008 s
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< RCPT TO:<ping@tools.mxtoolbox.com> ORCPT=rfc822;ping@tools.mxtoolbox.com\r\n
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.814 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup => undef, "ping@tools.mxtoolbox.com", no lookup tables
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="1"
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [local_domains] => true,  "ping@tools.mxtoolbox.com" matches, result="1", matching_key="(constant:1)"
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) query_keys: ping@tools.mxtoolbox.com, ping, @tools.mxtoolbox.com, @.tools.mxtoolbox.com, @.mxtoolbox.com, @.com, @.
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql sel_policy "ping@tools.mxtoolbox.com", query args: [ping@tools.mxtoolbox.com,-3], [ping,-3], [@tools.mxtoolbox.com,-3], [@.tools.mxtoolbox.com,-3], [@.mxtoolbox.com,-3], [@.com,-3], [@.,-3]
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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
Nov  9 01:34:50.815 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql begin, nontransaction
Nov  9 01:34:50.816 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Connecting to SQL database server
Nov  9 01:34:50.816 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
Nov  9 01:34:50.819 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
Nov  9 01:34:50.819 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql: preparing and executing (7 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
Nov  9 01:34:50.820 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql: "ping@tools.mxtoolbox.com" matches catchall, local=>undef
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql(ping@tools.mxtoolbox.com) matches, result=(id=>"1", priority=>"0", policy_id=>"1", email=>"@.", fullname=>-, id=>"1", policy_name=>"@.", virus_lover=>"N", spam_lover=>"Y", unchecked_lover=>-, banned_files_lover=>"N", bad_header_lover=>"Y", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", virus_quarantine_to=>"virus-quarantine", spam_quarantine_to=>"", banned_quarantine_to=>"banned-quarantine", 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=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(message_size_limit) rec=0, "ping@tools.mxtoolbox.com" result: undef
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [message_size_limit] => undef, "ping@tools.mxtoolbox.com" does not match
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 2.1.5 Recipient <ping@tools.mxtoolbox.com> OK
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 7.3 ms, total idle 0.001 s, busy 0.016 s
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.002 s, busy 0.016 s
Nov  9 01:34:50.821 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< DATA\r\n
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP [127.0.0.1]:10026 /var/lib/amavis/tmp/amavis-20231109T013450-1263265-Fxhtpgjw: <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com> SIZE=637 BODY=8BITMIME Received: from mail.mymailserver.com ([127.0.0.1]) by mail.mymailserver.com (mail.mymailserver.com [127.0.0.1]) (amavisd-new, port 10026) with ESMTP for <ping@tools.mxtoolbox.com>; Thu,  9 Nov 2023 01:34:50 +0000 (UTC)
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.822 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, receiving data
Nov  9 01:34:50.851 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp copy: read 646 bytes into buffer, new size: 646
Nov  9 01:34:50.851 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp copy: 6 bytes still buffered at end
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< .<CR><LF>
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.852 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.853 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) DNS resolver created, UDP payload size 1220, NS: 127.0.0.53
Nov  9 01:34:50.853 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_body_digest: reading header section from memory
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_body_digest: feeding header section to DKIM verifier
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_body_digest: sending h/b separator to DKIM
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_body_digest: reading mail body from memory, 0 DKIM signatures
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.854 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.855 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_body_digest: message size 637, header+sep 627, body 10
Nov  9 01:34:50.855 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) body type (8bit-MIMEtransport): labeled 8BITMIME unnecessarily (h=0, b=0)
Nov  9 01:34:50.855 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) body hash: 588791a2c9772aa40ffa49b26b781884
Nov  9 01:34:50.855 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ip_from_received: 176.124.200.110
Nov  9 01:34:50.856 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Nov  9 01:34:50.856 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_ip_acl (public_nets) arr.obj: key="176.124.200.110" matches "::ffff:0:0/96", result=1
Nov  9 01:34:50.856 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) trace: ESMTP://[127.0.0.1]:59558 < ESMTPSA://[176.124.200.110]:56362
Nov  9 01:34:50.856 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Original mail size: 637; quota set to: 318500 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
Nov  9 01:34:50.857 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql begin, nontransaction
Nov  9 01:34:50.857 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Nov  9 01:34:50.858 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) save_info_preliminary bcwldgYOr8GN, sender id: 800, admin@my-site-domain.com, exists
Nov  9 01:34:50.858 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql begin, nontransaction
Nov  9 01:34:50.858 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Nov  9 01:34:50.858 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) orcpt_encode rfc822, ping@tools.mxtoolbox.com, smtputf8
Nov  9 01:34:50.858 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) save_info_preliminary bcwldgYOr8GN, recip id: 1210, ping@tools.mxtoolbox.com (ORCPT rfc822;ping@tools.mxtoolbox.com), exists
Nov  9 01:34:50.859 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql begin transaction
Nov  9 01:34:50.859 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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 (?,?,?,?,?,?,?,?,?,?,?)
Nov  9 01:34:50.859 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql commit
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Checking: bcwldgYOr8GN ORIGINATING [176.124.200.110] <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) 2822.From: <admin@my-site-domain.com>
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(local) rec=0, "ping@tools.mxtoolbox.com" result: undef
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="1"
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [local_domains] => true,  "ping@tools.mxtoolbox.com" matches, result="1", matching_key="(constant:1)"
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="1"
Nov  9 01:34:50.862 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup => true,  "ping@tools.mxtoolbox.com" matches, result="1", matching_key="(constant:1)"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(bypass_banned_checks) rec=0, "ping@tools.mxtoolbox.com" result: "0"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [bypass_banned_checks] => false, "ping@tools.mxtoolbox.com" matches, result="0", matching_key="/cached/"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="1"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup => true,  "ping@tools.mxtoolbox.com" matches, result="1", matching_key="(constant:1)"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(id) rec=0, "ping@tools.mxtoolbox.com" result: "1"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [users.id], 1 matches for "ping@tools.mxtoolbox.com", results: "/cached/"=>"1"
Nov  9 01:34:50.863 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(policy_id) rec=0, "ping@tools.mxtoolbox.com" result: "1"
Nov  9 01:34:50.864 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [users.policy_id] => true,  "ping@tools.mxtoolbox.com" matches, result="1", matching_key="/cached/"
Nov  9 01:34:50.864 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Extracting mime components from a string
Nov  9 01:34:50.867 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Issued a new file name: p001
Nov  9 01:34:50.868 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Charging 8 bytes to remaining quota 318500 (out of 318500, (0%)) - by mime_decode
Nov  9 01:34:50.868 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) p001 1 Content-Type: text/plain, 7bit, size: 8, SHA1 digest: 0035a4e61d2c5106399c9b4718919ba3aafbe292
Nov  9 01:34:50.868 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.868 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.868 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.869 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.869 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) decode_parts: level=1, #parts=1 : p001
Nov  9 01:34:50.869 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) running file(1) on 1 files, arglist size 18
Nov  9 01:34:50.872 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) run_command: [1263294] /usr/bin/file p001 </dev/null 2>&1
Nov  9 01:34:50.892 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) result line from file(1): p001: ASCII text\n
Nov  9 01:34:50.893 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Nov  9 01:34:50.894 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Nov  9 01:34:50.894 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) File-type of p001: ASCII text; (asc)
Nov  9 01:34:50.895 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) decompose_part: p001 - atomic
Nov  9 01:34:50.895 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.895 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
Nov  9 01:34:50.895 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(bypass_header_checks) rec=0, "ping@tools.mxtoolbox.com" result: "0"
Nov  9 01:34:50.895 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [bypass_header_checks] => false, "ping@tools.mxtoolbox.com" matches, result="0", matching_key="/cached/"
Nov  9 01:34:50.896 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) check_header: 0, OK
Nov  9 01:34:50.896 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(bypass_header_checks) rec=0, "ping@tools.mxtoolbox.com" result: "0"
Nov  9 01:34:50.896 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [bypass_header_checks] => false, "ping@tools.mxtoolbox.com" matches, result="0", matching_key="/cached/"
Nov  9 01:34:50.896 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Checking for banned types and filenames
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(banned_rulenames) rec=0, "ping@tools.mxtoolbox.com" result: undef
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="DEFAULT"
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [banned_filename], 1 matches for "ping@tools.mxtoolbox.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) collect banned table[0]: ping@tools.mxtoolbox.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x55c4a68a9c00)
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) starting banned checks - traversing message structure tree
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) check_for_banned (p001) text/plain,.asc
Nov  9 01:34:50.897 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) doing banned check for ping@tools.mxtoolbox.com on text/plain,.asc
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_re(["text/plain",".asc"]), no matches
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [check_bann:ping@tools.mxtoolbox.com] => undef, ["text/plain",".asc"] does not match
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_re("P=p001\tL=1\tM=text/plain\tT=asc"), no matches
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does not match
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) p.path ping@tools.mxtoolbox.com: "P=p001,L=1,M=text/plain,T=asc"
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) banned check: any=0, all=N (1)
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) no anti-virus code loaded, skipping virus_scan
Nov  9 01:34:50.898 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) no anti-spam code loaded, skipping spam_scan
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(message_size_limit) rec=0, "ping@tools.mxtoolbox.com" result: undef
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [message_size_limit] => undef, "ping@tools.mxtoolbox.com" does not match
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) final_destiny (ccat=0) is PASS, recip ping@tools.mxtoolbox.com
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) final_destiny PASS, recip ping@tools.mxtoolbox.com
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) do_notify_and_quarantine: not quarantining, q_method off
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) skip admin notification, no administrators
Nov  9 01:34:50.899 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) do_notify_and_quarantine - done
Nov  9 01:34:50.900 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_sql_field(forward_method) rec=0, "ping@tools.mxtoolbox.com" result: undef
Nov  9 01:34:50.900 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Nov  9 01:34:50.900 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [forward_method] => true,  "ping@tools.mxtoolbox.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Nov  9 01:34:50.900 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) delivery method is 1, recips: ping@tools.mxtoolbox.com
Nov  9 01:34:50.900 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) headers CLUSTERING: NEW CLUSTER <ping@tools.mxtoolbox.com>: score=x, tag=0, tag2=0, local=1, bl=, s=, mangle=
Nov  9 01:34:50.901 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header encoded (all-ASCII): Received: from mail.mymailserver.com ([127.0.0.1])\n by mail.mymailserver.com (mail.mymailserver.com [127.0.0.1]) (amavisd-new, port 10026)\n with ESMTP\n id bcwldgYOr8GN\n for <ping@tools.mxtoolbox.com>;\n Thu,  9 Nov 2023 01:34:50 +0000 (UTC)
Nov  9 01:34:50.901 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header: Received: from mail.mymailserver.com ([127.0.0.1])\n\tby mail.mymailserver.com (mail.mymailserver.com [127.0.0.1]) (amavisd-new, port 10026)\n\twith ESMTP id bcwldgYOr8GN for <ping@tools.mxtoolbox.com>;\n\tThu,  9 Nov 2023 01:34:50 +0000 (UTC)\n
Nov  9 01:34:50.901 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) headers CLUSTERING: done all 1 recips in one go
Nov  9 01:34:50.902 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) dkim: candidate originators: From:<admin@my-site-domain.com>
Nov  9 01:34:50.902 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) query_keys: admin@my-site-domain.com, admin@, my-site-domain.com, .my-site-domain.com, .com, .
Nov  9 01:34:50.902 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup_hash(admin@my-site-domain.com) matches keys: "my-site-domain.com"=>HASH(0x55c4a66c9c40), "."=>HASH(0x55c4a66cca88)
Nov  9 01:34:50.902 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [dkim_signature_options_bysender], 2 matches for "admin@my-site-domain.com", results: "my-site-domain.com"=>{ttl=>"864000",d=>"my-site-domain.com",a=>"rsa-sha256"}, "."=>{c=>"relaxed/simple",a=>"rsa-sha256",ttl=>"2592000",d=>"mymailserver.com"}
Nov  9 01:34:50.902 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) dkim: signature options for admin@my-site-domain.com(From): c=relaxed/simple; a=rsa-sha256; ttl=864000; d=my-site-domain.com
Nov  9 01:34:50.903 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) dkim: signing (author), From: <admin@my-site-domain.com> (From:<admin@my-site-domain.com>), KEY.key_ind=>2, a=>rsa-sha256, c=>relaxed/simple, d=>my-site-domain.com, s=>dkim, ttl=>864000, x=>1700357691
Nov  9 01:34:50.903 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) write_header: 1, Amavis::Out::SMTP=HASH(0x55c4a8942a38)
Nov  9 01:34:50.908 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header encoded (all-ASCII): DKIM-Signature:  v=1; a=rsa-sha256; c=relaxed/simple; d=\n\tmy-site-domain.com; h=content-transfer-encoding:content-type\n\t:subject:from:to:content-language:user-agent:mime-version:date\n\t:message-id; s=dkim; t=1699493690; x=1700357691; bh=K8YGWR03X8jc\n\teZFoH1h/klHBge2yBDqD7XXs4Wub6aw=; b=UF7x0GeKtzPQ+xGNbZJZLnwsqnbQ\n\tuUg6G1i9PAbRM5dPGbTNY/6RwXilsEKOGhJvXiG3DXZsVHqeXVYP42cJti3n23Zs\n\tTbqz57/Dr/OXOos1geRr5LZVqMa7+FIiv3TrE4WkHofxi5Qlgd2OYdSLs5H9sXIH\n\to9gaRCj4QwdUpAE=
Nov  9 01:34:50.908 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header: DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=\n\tmy-site-domain.com; h=content-transfer-encoding:content-type\n\t:subject:from:to:content-language:user-agent:mime-version:date\n\t:message-id; s=dkim; t=1699493690; x=1700357691; bh=K8YGWR03X8jc\n\teZFoH1h/klHBge2yBDqD7XXs4Wub6aw=; b=UF7x0GeKtzPQ+xGNbZJZLnwsqnbQ\n\tuUg6G1i9PAbRM5dPGbTNY/6RwXilsEKOGhJvXiG3DXZsVHqeXVYP42cJti3n23Zs\n\tTbqz57/Dr/OXOos1geRr5LZVqMa7+FIiv3TrE4WkHofxi5Qlgd2OYdSLs5H9sXIH\n\to9gaRCj4QwdUpAE=\n
Nov  9 01:34:50.916 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header encoded (all-ASCII): Authentication-Results: mail.mymailserver.com (amavisd-new);\n dkim=pass (1024-bit key)\n reason="pass (just generated, assumed good)"\n header.d=my-site-domain.com
Nov  9 01:34:50.916 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) header: Authentication-Results: mail.mymailserver.com (amavisd-new);\n\tdkim=pass (1024-bit key) reason="pass (just generated, assumed good)"\n\theader.d=my-site-domain.com\n
Nov  9 01:34:50.917 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) about to connect to smtp:[127.0.0.1]:10025, bcwldgYOr8GN FWD from <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>
Nov  9 01:34:50.917 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
Nov  9 01:34:50.917 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp session: setting up a new session
Nov  9 01:34:50.917 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) establish_or_refresh, state: down
Nov  9 01:34:50.918 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Nov  9 01:34:50.923 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) connected to [127.0.0.1]:10025 successfully
Nov  9 01:34:50.923 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Nov  9 01:34:50.930 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: receiving
Nov  9 01:34:50.930 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop read 36 chars< 220 mail.mymailserver.com ESMTP Postfix\r\n
Nov  9 01:34:50.930 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp greeting: 220 mail.mymailserver.com ESMTP Postfix, dt: 12.9 ms
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp cmd> EHLO mail.mymailserver.com
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: sending 23 chars
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop sent 23> EHLO mail.mymailserver.com\r\n
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: receiving
Nov  9 01:34:50.931 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop read 143 chars< 250-mail.mymailserver.com\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250-SMTPUTF8\r\n250 CHUNKING\r\n
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp resp to EHLO: 250 mail.mymailserver.com\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nSMTPUTF8\nCHUNKING
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) tls active=0, capable=, sec_level=0
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Remote host presents itself as: mail.mymailserver.com, handles DSN, PIPELINING, 8BITMIME, SMTPUTF8
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) AUTH not needed, user='', MTA offers ''
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp cmd> MAIL FROM:<admin@my-site-domain.com> BODY=7BIT
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) orcpt_encode rfc822, ping@tools.mxtoolbox.com, encode_for_smtp
Nov  9 01:34:50.932 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp cmd> RCPT TO:<ping@tools.mxtoolbox.com> ORCPT=rfc822;ping@tools.mxtoolbox.com
Nov  9 01:34:50.933 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp cmd> DATA
Nov  9 01:34:50.933 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Nov  9 01:34:50.933 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: sending 132 chars
Nov  9 01:34:50.933 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop sent 132> MAIL FROM:<admin@my-site-domain.com> BODY=7BIT\r\nRCPT TO:<ping@tools.mxtoolbox.com> ORCPT=rfc822;ping@tools.mxtoolbox.com\r\nDATA\r\n
Nov  9 01:34:50.933 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Nov  9 01:34:50.943 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: receiving
Nov  9 01:34:50.943 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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
Nov  9 01:34:50.943 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp resp to RCPT (pip) (<ping@tools.mxtoolbox.com>): 250 2.1.5 Ok
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x55c4a7b3fae8)
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp connection_cache disabled, sending QUIT
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp cmd> QUIT
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.973
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: sending 1512 chars
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop sent 1512> Authentication-Results: mail.mymailserver.com (amavisd-new);\r\n\tdkim=pass (1024-bit key) reason="pass (just generated, assumed good)"\r\n\theader.d=my-site-domain.com\r\nDKIM-Signature: v=1; a=rsa-sha256; c= [...]
Nov  9 01:34:50.944 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.973
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop: receiving
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rw_loop read 56 chars< 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD\r\n221 2.0.0 Bye\r\n
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) smtp resp to data-dot (<ping@tools.mxtoolbox.com>): 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD, dt: 9.7 ms
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Amavis::Out::SMTP::Session close, disconnecting
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.954 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.9 s
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) bcwldgYOr8GN FWD from <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline forwarding - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer forwarding: timer 288, was 288, deadline in 479.9 s
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) DSN: sender is credible (orig), SA: 0.000, <admin@my-site-domain.com>
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup: (scalar) matches, result="18"
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => true,  "admin@my-site-domain.com" matches, result="18", matching_key="(constant:18)"
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) dsn: from MTA 250 NonBlocking:Clean <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD"
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) delivery_status_notification: notif 0 bytes, suppressed: no
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) one_response_for_all, per_recip_capable: N, suppressed: N
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) one_response_for_all <admin@my-site-domain.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 4SQkyy6hQcz4xfD'
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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 4SQkyy6hQcz4xfD
Nov  9 01:34:50.955 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline delivery-notification - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.956 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.9 s
Nov  9 01:34:50.956 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInternal,RelayedUntaggedOriginating}
Nov  9 01:34:50.956 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline snmp-counters - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.956 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.9 s
Nov  9 01:34:50.956 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) orcpt_encode rfc822, ping@tools.mxtoolbox.com, smtputf8
Nov  9 01:34:50.963 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) oldest_public_ip_addr_from_received: 176.124.200.110
Nov  9 01:34:50.966 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Passed CLEAN {RelayedInternal}, ORIGINATING LOCAL [176.124.200.110]:56362 [176.124.200.110] ESMTP/ESMTP <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>, (ESMTPSA://[176.124.200.110]:56362), Queue-ID: 4SQkyy49wgz4xdd, Message-ID: <e67031ae-7ede-4286-b128-613daf34eaef@my-site-domain.com>, mail_id: bcwldgYOr8GN, b: WIeRosl3K, Hits: -, size: 637, queued_as: 4SQkyy6hQcz4xfD, Subject: "Test 2", From: <admin@my-site-domain.com>, User-Agent: Mozilla_Thunderbird, helo=[0.0.0.0], dkim_new=dkim:my-site-domain.com, 161 ms
Nov  9 01:34:50.971 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) _WARN: Argument "x" isn't numeric in sprintf at /usr/sbin/amavisd-new line 15872.
Nov  9 01:34:50.971 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) _WARN: Argument "x" isn't numeric in sprintf at /usr/sbin/amavisd-new line 15874.
Nov  9 01:34:50.971 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) _WARN: Argument "x" isn't numeric in sprintf at /usr/sbin/amavisd-new line 15876.
Nov  9 01:34:50.972 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) Passed CLEAN, <admin@my-site-domain.com> -> <ping@tools.mxtoolbox.com>, Hits: -, tag=0, tag2=0, kill=0, queued_as: 4SQkyy6hQcz4xfD, L/0/0/0
Nov  9 01:34:50.973 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline main_log_entry - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.973 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.9 s
Nov  9 01:34:50.973 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql begin transaction
Nov  9 01:34:50.973 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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 (?,?,?,?,?,?,?,?,?,?,?,?)
Nov  9 01:34:50.975 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) save_info_final bcwldgYOr8GN, orig=Y, chks=HB, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <e67031ae-7ede-4286-b128-613daf34eaef@my-site-domain.com>, From: 'Имя отправителя <admin@my-site-domain.com>', Subject: 'Test 2'
Nov  9 01:34:50.978 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-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=?
Nov  9 01:34:50.979 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sql commit
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline check done - deadline in 479.9 s, set to 288.000 s
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer check done: timer 288, was 288, deadline in 479.9 s
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD"
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4SQkyy6hQcz4xfD
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20231109T013450-1263265-Fxhtpgjw
Nov  9 01:34:50.981 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20231109T013450-1263265-Fxhtpgjw/parts, excl=1
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) size: 637, TIMING [total 178 ms] - sql-prepare: 0.9 (0%)0, SMTP greeting: 0.9 (0%)1, SMTP EHLO: 2.7 (2%)3, SMTP pre-MAIL: 2.0 (1%)4, mkdir tempdir: 1.8 (1%)5, create email.txt: 0.4 (0%)5, SMTP MAIL: 0.8 (0%)5, sql-connect: 5 (3%)8, lookup_sql: 1.7 (1%)9, SMTP pre-DATA-flush: 1.7 (1%)10, SMTP DATA: 30 (17%)27, check_init: 0.2 (0%)27, digest_hdr: 1.9 (1%)28, digest_body_dkim: 0.8 (0%)28, collect_info: 1.5 (1%)29, gen_mail_id: 5 (3%)32, mkdir parts: 2.4 (1%)34, mime_decode: 4.3 (2%)36, get-file-type1: 26 (15%)51, parts_decode: 0.4 (0%)51, check_header: 1.5 (1%)52, decide_mail_destiny: 2.7 (2%)53, notif-quar: 0.3 (0%)53, write-header: 4.9 (3%)56, fwd-data-dkim: 3.2 (2%)58, fwd-connect: 25 (14%)72, fwd-mail-pip: 11 (6%)78, fwd-rcpt-pip: 0.2 (0%)78, fwd-data-chkpnt: 0.0 (0%)78, write-header: 0.3 (0%)79, fwd-data-contents: 0.0 (0%)79, fwd-end-chkpnt: 11 (6%)85, prepare-dsn: 0.9 (1%)85, report: 1.5 (1%)86, main_log_entry: 15 (9%)95, sql-update: 8 (5%)99, SMTP pre-response: 0.3 (0%)99, SMTP response: 0.2 (0%)100, unlink-1-files: 0.3 (0%)100, rundown: 0.6 (0%)100
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 6: was busy, 160.9 ms, total idle 0.002 s, busy 0.177 s
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.002 s, busy 0.177 s
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP< QUIT\r\n
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Nov  9 01:34:50.982 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Nov  9 01:34:50.983 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Nov  9 01:34:50.983 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) switch_to_client_time 480 s, smtp response sent
Nov  9 01:34:50.983 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) SMTP session over, timer stopped
Nov  9 01:34:50.984 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) extra modules loaded: Net/DNS/RR/A.pm, Net/DNS/RR/AAAA.pm, Net/DNS/RR/OPT.pm
Nov  9 01:34:50.984 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) exiting process_request
Nov  9 01:34:50.986 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) idle_proc, bye: was busy, 3.5 ms, total idle 0.002 s, busy 0.180 s
Nov  9 01:34:50.988 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) load: 99 %, total idle 0.002 s, busy 0.180 s

7 Reply by Cthulhu (edited by Cthulhu 2023-11-18 19:41:23)

  • Cthulhu
  • Member
  • Offline
  • Registered: 2019-06-04
  • Posts: 955

Re: Can't pass DKIM signature verification because of extra space

How did you edit/save your file?

\n stands for newline
\t stands for tabstop (tabulator)

seems like you saved your files ASCII encoded, could it be that you edited it with external software (like SCP) in an windows editor and saved it in wrong encoding?


Edit:

On Lin 26 you can see:

Nov  9 01:34:50.808 mail.mymailserver.com /usr/sbin/amavisd-new[1263265]: (1263265-01) ESMTP> 250-SMTPUTF8

SMTPUTF8 was disabled some time ago to fix problems with IDN:

https://github.com/iredmail/iRedMail/co … edf1fc222c

8 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

Cthulhu wrote:

How did you edit/save your file?

I copied and pasted the output debug log from Linux terminal to txt file. I'm using Ubuntu and gedit. All config files I edited using vim through terminal.

Cthulhu wrote:

SMTPUTF8 was disabled some time ago to fix problems with IDN:

Okay. I'll try this and note about result. Thank you!

9 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

I disabled SMTPUTF8 from postfix conf as you recommend. The rows are disappeared from debug logs, but the problem is not.

This is strartup log of amavisd-new. Maybe it helps.

root@mail:~# amavisd-new -c  /etc/amavis/conf.d/50-user debug
Nov 20 02:09:36.549 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: logging initialized, log level 0, syslog: amavis.mail
Nov 20 02:09:36.550 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Nov 20 02:09:36.550 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: starting. /usr/sbin/amavisd-new at mail.mymailserver.com amavisd-new-2.12.2 (20211013), Unicode aware, LANG="C.UTF-8"
Nov 20 02:09:36.550 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: perl=5.034000, user=, EUID: 115 (115);  group=, EGID: 122 122 (122 122)
Nov 20 02:09:36.587 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Nov 20 02:09:36.588 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: socket module IO::Socket::IP, protocol families available: INET, INET6
Nov 20 02:09:36.588 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: will bind to /var/run/amavis/amavisd.socket|unix, 127.0.0.1:10024/tcp, 127.0.0.1:10026/tcp, 127.0.0.1:10027/tcp, 127.0.0.1:9998/tcp
Nov 20 02:09:36.589 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Nov 20 02:09:36.589 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): STATUS=Preparing to bind sockets.
Nov 20 02:09:36.589 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: 2023/11/20-02:09:36 Amavis (type Net::Server) starting! pid(2715583)
Nov 20 02:09:36.594 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Binding to UNIX socket file "/var/run/amavis/amavisd.socket"
Nov 20 02:09:36.595 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Nov 20 02:09:36.595 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Binding to TCP port 10026 on host 127.0.0.1 with IPv4
Nov 20 02:09:36.596 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Binding to TCP port 10027 on host 127.0.0.1 with IPv4
Nov 20 02:09:36.596 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Binding to TCP port 9998 on host 127.0.0.1 with IPv4
Nov 20 02:09:36.596 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.
Nov 20 02:09:36.596 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: Group Not Defined.  Defaulting to EGID '122 122'
Nov 20 02:09:36.597 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Net::Server: User Not Defined.  Defaulting to EUID '115'
Nov 20 02:09:36.597 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): STATUS=The rest of pre-fork init, finding helper programs.
Nov 20 02:09:36.597 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: after_chroot_init: EUID: 115 (115);  EGID: 122 122 (122 122)
Nov 20 02:09:36.597 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: config files read: /etc/amavis/conf.d/50-user
Nov 20 02:09:36.604 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Amavis::Conf        2.412
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Archive::Zip        1.68
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Compress::Raw::Zlib 2.101
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Compress::Zlib      2.102
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Crypt::OpenSSL::RSA 0.32
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module DBD::mysql          4.050
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module DBI                 1.643
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Digest::MD5         2.58
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Digest::SHA         6.02
Nov 20 02:09:36.605 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Encode              3.08
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module File::Temp          0.2311
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module IO::Socket::IP      0.41
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module IO::Socket::SSL     2.074
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module MIME::Entity        5.509
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module MIME::Parser        5.509
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module MIME::Tools         5.509
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Mail::DKIM::Signer  1.20200907
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Mail::DKIM::Verifier 1.20200907
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Mail::Header        2.21
Nov 20 02:09:36.606 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Mail::Internet      2.21
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Net::DNS            1.33
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Net::LibIDN         0.12
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Net::Patricia       1.22
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Net::SSLeay         1.92
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Net::Server         2.009
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Scalar::Util        1.55
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Socket              2.031
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Socket6             0.29
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Time::HiRes         1.9767
Nov 20 02:09:36.607 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Module Unix::Syslog        1.1
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Amavis::ZMQ code     NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Amavis::DB code      NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: SQL base code        loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: SQL::Log code        loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: SQL::Quarantine      loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Lookup::SQL code     loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Lookup::LDAP code    NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: AM.PDP-in proto code loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: SMTP-in proto code   loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Courier proto code   NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: SMTP-out proto code  loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Pipe-out proto code  NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: BSMTP-out proto code NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Local-out proto code NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: OS_Fingerprint code  NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-VIRUS code      NOT loaded
Nov 20 02:09:36.608 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-SPAM code       NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-SPAM-EXT code   NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-SPAM-C code     NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-SPAM-Rspamd code NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: ANTI-SPAM-SA code    NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Unpackers code       loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: DKIM code            loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Tools code           NOT loaded
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found $file            at /usr/bin/file
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found $altermime       at /usr/bin/altermime
Nov 20 02:09:36.609 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Internal decoder for .mail
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: No ext program for   .F, tried: unfreeze, freeze -d, melt, fcat
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .Z    at /usr/bin/uncompress
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .gz   at /usr/bin/gzip -d
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Internal decoder for .gz   (backup, not used)
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .bz2  at /usr/bin/bzip2 -d
Nov 20 02:09:36.610 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .xz   at /usr/bin/xz -dc
Nov 20 02:09:36.611 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lzma at /usr/bin/xz -dc --format=lzma
Nov 20 02:09:36.611 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lrz  at /usr/bin/lrzip -q -k -d -o -
Nov 20 02:09:36.611 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lzo  at /usr/bin/lzop -d
Nov 20 02:09:36.611 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lz4  at /usr/bin/lz4c -d
Nov 20 02:09:36.611 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .rpm  at /usr/bin/rpm2cpio
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .cpio at /usr/bin/pax
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .tar  at /usr/bin/pax
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .deb  at /usr/bin/ar
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .rar  at /usr/bin/unrar
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .arj  at /usr/bin/arj
Nov 20 02:09:36.612 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .arc  at /usr/bin/nomarch
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: No ext program for   .zoo, tried: zoo, unzoo
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .cab  at /usr/bin/cabextract
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Internal decoder for .tnef
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .zip  at /usr/bin/7za
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .kmz  at /usr/bin/7za
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Internal decoder for .zip  (backup, not used)
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Internal decoder for .kmz  (backup, not used)
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .7z   at /usr/bin/7zr
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .gz   at /usr/bin/7za (backup, not used)
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .bz2  at /usr/bin/7za (backup, not used)
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .Z    at /usr/bin/7za (backup, not used)
Nov 20 02:09:36.613 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .tar  at /usr/bin/7za (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .xz   at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lzma at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .jar  at /usr/bin/7z
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .cpio at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .arj  at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .rar  at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .swf  at /usr/bin/7z
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .lha  at /usr/bin/7z
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .iso  at /usr/bin/7z
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .cab  at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .deb  at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.614 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .rpm  at /usr/bin/7z (backup, not used)
Nov 20 02:09:36.615 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: Found decoder for    .exe  at /usr/bin/unrar; /usr/bin/arj
Nov 20 02:09:36.615 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: No decoder for       .F   
Nov 20 02:09:36.615 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: No decoder for       .zoo
Nov 20 02:09:36.616 mail.mymailserver.com /usr/sbin/amavisd-new[2715583]: sd_notify (no socket): READY=1\nSTATUS=Initialization done.

10 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

Also I checked all mysql databases to be sure, that there is no any \t \n characters before my domain name in any row.

Notes:
1) I disabled virus/spam scanning using this instruction https://docs.iredmail.org/completely.di … assin.html section "Stop virus/spam scanning, keep DKIM signing/verification and Disclaimer".
2) I can send debug log for my other domain from this server, which works correct.

11 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

I reinstalled iRedMail from scratch and problem is still actual.

But I found one interesting thing. If I open source of the mail the dkim signature looks like this.

DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=
    my-domain-name.com; h=content-transfer-encoding:content-type
    :subject:from:to:content-language:user-agent:mime-version:date
    :message-id; s=dkim; t=1700562025; x=1701426026; bh=fdkeB/A0FkbV
    P2k4J4pNPoeWH6vqBm9+b0C3OY87Cw8=; b=DoOB/JLekf1KAl1xwoav0pnYexUS
    Lo1z5ZY8mrP22gp0Wh2bapq4OwJZLBMWTN+kfqeu0HPL4zm0GONiEX8dZIB/Ky2W
    yTqHKhhzPTcbIvpsu5lg+EAQrG7dd/gwH7P0yiQnjCk4oedjzBu+oPwvIpwhvEEu
    t0N7VU2MQLhb4FHsB/81EaF8OrpEslKWDY9jIV4sseG637jiUfXn5jkLy9xWwtLs
    o6vJVcxiJppFS4b46B8D0DRUIcmNE+Jg1cpSM/7kFdMwNaPdaQwxQvYngyxeL8Sk
    UOnLpg4VJw1Ems5h0wpOTs6Wpy370GHwzUzJoRxbYjjl9GQXnZn0FyjcnA==

As you see each row have no more than 65 symbol length. It seems amavisd breaks line and adds \n\t before my domain name because it is tool long. It seems, this is a correct behavior, but mxtoolbox show the error.

12 Reply by ZhangHuangbin

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

Re: Can't pass DKIM signature verification because of extra space

Seems you triggered a bug of Amavisd, please try to report this issue to Amavisd team:
https://gitlab.com/amavis/amavis

13 Reply by Axenic

  • Axenic
  • Member
  • Offline
  • Registered: 2023-09-15
  • Posts: 10

Re: Can't pass DKIM signature verification because of extra space

ZhangHuangbin wrote:

Seems you triggered a bug of Amavisd, please try to report this issue to Amavisd team:
https://gitlab.com/amavis/amavis

Hello. I already did it https://gitlab.com/amavis/amavis/-/issues/113.

It seems, this is a bug of mxtoolbox. I sent a bug repport to them already. Their support team contacted with me.

I'll write results there after when we finish.