1 Topic by legendsxxxhunter (edited by legendsxxxhunter 2024-07-12 02:30:01)

  • legendsxxxhunter
  • Member
  • Offline
  • Registered: 2024-07-08
  • Posts: 6

Topic: Amavis DKIM Problem

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.6.8
- Deployed with iRedMail Easy or the downloadable installer? Downloadable Installer
- Linux/BSD distribution name and version: Ubuntu 20.04 64 Bit LTS
- 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,

When I send an email, it only processes through port 10024 of amavis and sends the email without a DKIM signature, without using port 10026. How can I resolve this issue? I want the emails to be sent with DKIM signatures. There is no spam in the outgoing emails; amavis log outputs indicate that there is no spam, with outputs such as "X-Spam-Flag: no". This problem has nothing to do with spam or bad emails.

I have a frontend nginx mail proxy server. It connects to it, performs authentication, and redirects me to my mail server, and I send emails this way. When I connect to the nginx mail proxy server and send emails, the emails go without DKIM signatures as shown below. But if I connect directly to the mail server without the frontend server, the emails are sent with DKIM signatures without any issues.

Is there a way to solve this problem?

/var/log/mail.log:

Jul 11 21:09:18 mail postfix/postscreen[63868]: CONNECT from [my_proxy_server_ip]:41236 to [my_iredmail_server_ip]:25
Jul 11 21:09:18 mail postfix/dnsblog[63870]: addr my_proxy_server_ip listed by domain zen.spamhaus.org as 127.255.255.254
Jul 11 21:09:18 mail postfix/postscreen[63868]: PASS OLD [my_proxy_server_ip]:41236
Jul 11 21:09:18 mail postfix/smtpd[63872]: connect from unknown[my_proxy_server_ip]
Jul 11 21:09:18 mail postfix/smtpd[63872]: discarding EHLO keywords: CHUNKING
Jul 11 21:09:18 mail postfix/smtpd[63872]: discarding EHLO keywords: CHUNKING
Jul 11 21:09:18 mail postfix/smtpd[63872]: 4WKjRL5Lczz7y6n: client=unknown[my_home_ip], sasl_method=PLAIN, sasl_username=sendermail@mydomain.com
Jul 11 21:09:18 mail postfix/cleanup[63877]: 4WKjRL5Lczz7y6n: message-id=<53503349-ceca-47b1-b960-83e31491b467@mydomain.com>
Jul 11 21:09:18 mail postfix/qmgr[63540]: 4WKjRL5Lczz7y6n: from=<sendermail@mydomain.com>, size=601, nrcpt=1 (queue active)
Jul 11 21:09:18 mail amavis[33192]: Net::Server: 2024/07/11-21:09:18 CONNECT TCP Peer: "[127.0.0.1]:36484" Local: "[127.0.0.1]:10024"
Jul 11 21:09:18 mail amavis[33192]: loaded base policy bank
Jul 11 21:09:18 mail amavis[33192]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Jul 11 21:09:18 mail amavis[33192]: process_request: fileno sock=11, STDIN=0, STDOUT=1
Jul 11 21:09:18 mail amavis[33192]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: process_request: suggested_protocol="" on a TCP socket
Jul 11 21:09:18 mail amavis[33192]: (33192-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 4: was busy, 7.2 ms, total idle 0.000 s, busy 0.007 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp readline: read 28 bytes, new size: 28
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.000 s, busy 0.007 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) SMTP< EHLO mail.mydomain.com\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-[127.0.0.1]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-VRFY
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-PIPELINING
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-SIZE
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-8BITMIME
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-SMTPUTF8
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250-DSN
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 1.4 ms, total idle 0.000 s, busy 0.009 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp readline: read 262 bytes, new size: 262
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.009 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< XFORWARD ADDR=my_home_ip PORT=41236\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 0.7 ms, total idle 0.001 s, busy 0.009 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.009 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< XFORWARD PROTO=ESMTP HELO=[192.168.1.106] IDENT=4WKjRL5Lczz7y6n SOURCE=REMOTE\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.010 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.010 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< MAIL FROM:<sendermail@mydomain.com> SIZE=601 BODY=8BITMIME\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) check_mail_begin_task: task_count=1
Jul 11 21:09:18 mail amavis[33192]: (33192-01) TempDir::prepare_dir: created directory /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP
Jul 11 21:09:18 mail amavis[33192]: (33192-01) TempDir::prepare_file: creating file /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/email.txt
Jul 11 21:09:18 mail amavis[33192]: (33192-01) TempDir::prepare_file: layers: unix,perlio
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="my_home_ip", no match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [debug_sender] => undef, "sendermail@mydomain.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) mesage size set to a declared size 601
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 2.1.0 Sender <sendermail@mydomain.com> OK
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 3.8 ms, total idle 0.001 s, busy 0.014 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.014 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< RCPT TO:<receiver@gmail.com> ORCPT=rfc822;receiver@gmail.com\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup => undef, "receiver@gmail.com", no lookup tables
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [local_domains] => true,  "receiver@gmail.com" matches, result="1", matching_key="(constant:1)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) query_keys: receiver@gmail.com, receiver, @gmail.com, @.gmail.com, @.com, @.
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql sel_policy "receiver@gmail.com", query args: [receiver@gmail.com,-3], [receiver,-3], [@gmail.com,-3], [@.gmail.com,-3], [@.com,-3], [@.,-3]
Jul 11 21:09:18 mail amavis[33192]: (33192-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
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin, nontransaction
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Connecting to SQL database server
Jul 11 21:09:18 mail amavis[33192]: (33192-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
Jul 11 21:09:18 mail amavis[33192]: (33192-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
Jul 11 21:09:18 mail amavis[33192]: (33192-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
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql: "receiver@gmail.com" matches catchall, local=>undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql(receiver@gmail.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_su...
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ...bject_tag=>-, spam_subject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(message_size_limit) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [message_size_limit] => undef, "receiver@gmail.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 2.1.5 Recipient <receiver@gmail.com> OK
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 10.4 ms, total idle 0.001 s, busy 0.024 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.024 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< DATA\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP [127.0.0.1]:10024 /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP: <sendermail@mydomain.com> -> <receiver@gmail.com> SIZE=601 BODY=8BITMIME Received: from mail.mydomain.com ([127.0.0.1]) by mail.mydomain.com (mail.mydomain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <receiver@gmail.com>; Thu, 11 Jul 2024 21:09:18 +0300 (+03)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, receiving data
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp copy: read 610 bytes into buffer, new size: 610
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp copy: 6 bytes still buffered at end
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< .<CR><LF>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) DNS resolver created, UDP payload size 1220, NS: 127.0.0.53
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_body_digest: reading header section from memory
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_body_digest: feeding header section to DKIM verifier
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_body_digest: sending h/b separator to DKIM
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_body_digest: reading mail body from memory, 0 DKIM signatures
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_body_digest: message size 601, header+sep 584, body 17
Jul 11 21:09:18 mail amavis[33192]: (33192-01) body type (8bit-MIMEtransport): labeled 8BITMIME, good (h=0, b=1)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) body hash: ad19582d353988915fad20ec5cb98b93
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ip_from_received: my_home_ip
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_ip_acl (public_nets) arr.obj: key="my_home_ip" matches "::ffff:0:0/96", result=1
Jul 11 21:09:18 mail amavis[33192]: (33192-01) trace: ESMTP://[127.0.0.1]:36484 < ESMTPA://[my_home_ip]:41236
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Original mail size: 601; quota set to: 300500 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin, nontransaction
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jul 11 21:09:18 mail amavis[33192]: (33192-01) save_info_preliminary YAnhv6RTJlvw, sender id: 1, sendermail@mydomain.com, exists
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin, nontransaction
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jul 11 21:09:18 mail amavis[33192]: (33192-01) orcpt_encode rfc822, receiver@gmail.com, smtputf8
Jul 11 21:09:18 mail amavis[33192]: (33192-01) save_info_preliminary YAnhv6RTJlvw, recip id: 2, receiver@gmail.com (ORCPT rfc822;receiver@gmail.com), exists
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin transaction
Jul 11 21:09:18 mail amavis[33192]: (33192-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 (?,?,?,?,?,?,?,?,?,?,?)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql commit
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Checking: YAnhv6RTJlvw [my_home_ip] <sendermail@mydomain.com> -> <receiver@gmail.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) 2822.From: <sendermail@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(local) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [local_domains] => true,  "receiver@gmail.com" matches, result="1", matching_key="(constant:1)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(bypass_virus_checks) rec=0, "receiver@gmail.com" result: "0"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [bypass_virus_checks] => false, "receiver@gmail.com" matches, result="0", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(bypass_banned_checks) rec=0, "receiver@gmail.com" result: "0"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [bypass_banned_checks] => false, "receiver@gmail.com" matches, result="0", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(bypass_spam_checks) rec=0, "receiver@gmail.com" result: "0"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [bypass_spam_checks] => false, "receiver@gmail.com" matches, result="0", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(id) rec=0, "receiver@gmail.com" result: "1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [users.id], 1 matches for "receiver@gmail.com", results: "/cached/"=>"1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(policy_id) rec=0, "receiver@gmail.com" result: "1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [users.policy_id] => true,  "receiver@gmail.com" matches, result="1", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Extracting mime components from a string
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Issued a new file name: p001
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Charging 15 bytes to remaining quota 300500 (out of 300500, (0%)) - by mime_decode
Jul 11 21:09:18 mail amavis[33192]: (33192-01) p001 1 Content-Type: text/plain, 8bit, size: 15, SHA1 digest: 1dca431b5a2ca0d73c3e1cfdd92175d123fd2ca1
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) decode_parts: level=1, #parts=1 : p001
Jul 11 21:09:18 mail amavis[33192]: (33192-01) running file(1) on 1 files, arglist size 18
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_command: [63879] /usr/bin/file p001 </dev/null 2>&1
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: target fd1 closing, to become (65) &=15
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: target fd1 dup2 from fd15 (65) &=15
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: source fd15 closed
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 11 21:09:18 mail amavis[63879]: (33192-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 11 21:09:18 mail amavis[33192]: (33192-01) result line from file(1): p001: UTF-8 Unicode text\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_re("UTF-8 Unicode text") matches key "(?^i:^UTF.* Unicode text\\b)", result="txt"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [map_full_type_to_short_type] => true,  "UTF-8 Unicode text" matches, result="txt", matching_key="(?^i:^UTF.* Unicode text\\b)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) File-type of p001: UTF-8 Unicode text; (txt)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) decompose_part: p001 - atomic
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(bypass_header_checks) rec=0, "receiver@gmail.com" result: "0"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [bypass_header_checks] => false, "receiver@gmail.com" matches, result="0", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) check_header: 0, OK
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(bypass_header_checks) rec=0, "receiver@gmail.com" result: "0"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [bypass_header_checks] => false, "receiver@gmail.com" matches, result="0", matching_key="/cached/"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Checking for banned types and filenames
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(banned_rulenames) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="DEFAULT"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [banned_filename], 1 matches for "receiver@gmail.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) collect banned table[0]: receiver@gmail.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x5578e6d6cf80)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) starting banned checks - traversing message structure tree
Jul 11 21:09:18 mail amavis[33192]: (33192-01) check_for_banned (p001) text/plain,.txt
Jul 11 21:09:18 mail amavis[33192]: (33192-01) doing banned check for receiver@gmail.com on text/plain,.txt
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_re(["text/plain",".txt"]), no matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [check_bann:receiver@gmail.com] => undef, ["text/plain",".txt"] does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_re("P=p001\tL=1\tM=text/plain\tT=txt"), no matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=txt" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) p.path receiver@gmail.com: "P=p001,L=1,M=text/plain,T=txt"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) banned check: any=0, all=N (1)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_re("MAIL"), no matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Calling virus scanners, 1 files to scan in /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts
Jul 11 21:09:18 mail amavis[33192]: (33192-01) invoking av-scanner clamav-socket
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ask_daemon: proto=DFLT, spawn=0, (clamav-socket) /var/run/clamav/clamd.ctl
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_av (clamav-socket): query template(1,0): CONTSCAN {}\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline run_av_pre - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline run_av_scan - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer run_av_scan: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_av Using (clamav-socket): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) clamav-socket: Connecting to socket  /var/run/clamav/clamd.ctl
Jul 11 21:09:18 mail amavis[33192]: (33192-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jul 11 21:09:18 mail amavis[33192]: (33192-01) connected to /var/run/clamav/clamd.ctl successfully
Jul 11 21:09:18 mail amavis[33192]: (33192-01) clamav-socket: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts\n to socket /var/run/clamav/clamd.ctl
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: sending 73 chars
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts: OK\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop read: got eof
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline ask_daemon_internal - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline run_av_3 - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer run_av_3: timer 288, was 288, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_av (clamav-socket) result: /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts: OK\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_av (clamav-socket): CLEAN
Jul 11 21:09:18 mail amavis[33192]: (33192-01) run_av (clamav-socket) result: clean
Jul 11 21:09:18 mail amavis[33192]: (33192-01) wbl: checking sender <sendermail@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) wbl: (SQL) recip <receiver@gmail.com>, 1 matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="1"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [local_domains] => true,  "sendermail@mydomain.com" matches, result="1", matching_key="(constant:1)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) query_keys: sendermail@mydomain.com, sendermail, @mydomain.com, @.mydomain.com, @.net.tr, @.tr, @.
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql sel_wblist "sendermail@mydomain.com", query args: "1", [sendermail@mydomain.com,-3], [sendermail,-3], [@mydomain.com,-3], [@.mydomain.com,-3], [@.net.tr,-3], [@.tr,-3], [@.,-3]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql select: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin, nontransaction
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql: preparing and executing (8 args): SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql, "sendermail@mydomain.com" no match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(wb), "sendermail@mydomain.com" no matching records
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup => undef, "sendermail@mydomain.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) wbl: (SQL) recip <receiver@gmail.com>, rid=1, got: ""
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [blacklist_recip<receiver@gmail.com>] => undef, "receiver@gmail.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [blacklist_sender<sendermail@mydomain.com>,blacklist_sender] => undef, "sendermail@mydomain.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [whitelist_recip<receiver@gmail.com>] => undef, "receiver@gmail.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) query_keys: sendermail@mydomain.com, sendermail@, mydomain.com, .mydomain.com, .net.tr, .tr, .
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_hash(sendermail@mydomain.com) matches key "mydomain.com", result=1
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [whitelist_sender<sendermail@mydomain.com>,whitelist_sender] => true,  "sendermail@mydomain.com" matches, result="1", matching_key="mydomain.com"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) wbl: recip <receiver@gmail.com> whitelisted sender <sendermail@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) query_keys: receiver@gmail.com, receiver@, gmail.com, .gmail.com, .com, .
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_hash(receiver@gmail.com) matches keys: "."=>ARRAY(0x5578e7504d40)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [score_recip<receiver@gmail.com>,score_sender], 1 matches for "receiver@gmail.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x5578e74346d0),{ietf-123-owner@loki.ietf.org=>"-3",clp-request@comp.nus.edu.sg=>"-3",donotreply@sendmail.org=>"-3",noreply@freshmeat.net=>"-3",.example.net=>"1",owner-technews@postel.acm.org=>"-3",clusternews@linuxnetworx.com=>"-3",securityfocus.com=>"-3",cert-advisory@us-cert.gov=>"-3",yahoo-dev-null@yahoo-inc.com=>"-3",mailman-announce-admin@python.org=>"-3",security-alerts@linuxsecurity.com=>"-3",owner-alert@iss.net=>"-3",spamassassin.apache.org=>"-3",nobody@cert.org=>"-3",owner-postfix-announce@postfix.org=>"-3",notification-return@lists.sophos.com=>"-3",amavis-user-admin@lists.sourceforge.net=>"-3",sendmail-announce-request@lists.sendmail.org=>"-3",rt-users-admin@lists.fsck.com=>"-3",owner-postfix-users@postfix.org=>"-3",cvs-commits-list-admin@gnome.org=>"-3",lvs-users-admin@linuxvirtualserver.org=>"-3",owne...
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ...r-textbreakingnews@cnnimail12.cnn.com=>"-5",amavis-user-bounces@lists.sourceforge.net=>"-3",returns.groups.yahoo.com=>"-3",emailnews@genomeweb.com=>"-5",sendermail@example.net=>"3",ntbugtraq@listserv.ntbugtraq.com=>"-3",owner-sendmail-announce@lists.sendmail.org=>"-3",slashdot@slashdot.org=>"-3",surveys-errors@lists.nua.ie=>"-3",ca+envelope@sendmail.org=>"-3"}]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_re("sendermail@mydomain.com"), no matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) query_keys: cached sendermail@mydomain.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_hash(sendermail@mydomain.com), no matches
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [score_sender<sendermail@mydomain.com>] => undef, "sendermail@mydomain.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) wbl: whitelisted sender <sendermail@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sender white/blacklisted, skipping spam_scan
Jul 11 21:09:18 mail amavis[33192]: (33192-01) bounce unverifiable, <sendermail@mydomain.com> -> <receiver@gmail.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_tag_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="2"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_tag_level] => true,  "receiver@gmail.com" matches, result="2", matching_key="(constant:2)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_tag2_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="6.2"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_tag2_level] => true,  "receiver@gmail.com" matches, result="6.2", matching_key="(constant:6.2)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_tag3_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_tag3_level] => undef, "receiver@gmail.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_kill_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="6.9"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_kill_level] => true,  "receiver@gmail.com" matches, result="6.9", matching_key="(constant:6.9)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(message_size_limit) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [message_size_limit] => undef, "receiver@gmail.com" does not match
Jul 11 21:09:18 mail amavis[33192]: (33192-01) final_destiny (ccat=0) is PASS, recip receiver@gmail.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) final_destiny PASS, recip receiver@gmail.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jul 11 21:09:18 mail amavis[33192]: (33192-01) do_notify_and_quarantine: not quarantining, q_method off
Jul 11 21:09:18 mail amavis[33192]: (33192-01) skip admin notification, no administrators
Jul 11 21:09:18 mail amavis[33192]: (33192-01) do_notify_and_quarantine - done
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(forward_method) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [forward_method] => true,  "receiver@gmail.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) delivery method is 1, recips: receiver@gmail.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_tag_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="2"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_tag_level] => true,  "receiver@gmail.com" matches, result="2", matching_key="(constant:2)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup_sql_field(spam_tag2_level) rec=0, "receiver@gmail.com" result: undef
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="6.2"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_tag2_level] => true,  "receiver@gmail.com" matches, result="6.2", matching_key="(constant:6.2)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) headers CLUSTERING: NEW CLUSTER <receiver@gmail.com>: score=x, tag=0, tag2=0, local=1, bl=, s=, mangle=
Jul 11 21:09:18 mail amavis[33192]: (33192-01) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at mail.mydomain.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) header: X-Virus-Scanned: Debian amavisd-new at mail.mydomain.com\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) header encoded (all-ASCII): Received: from mail.mydomain.com ([127.0.0.1])\n by mail.mydomain.com (mail.mydomain.com [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id YAnhv6RTJlvw\n for <receiver@gmail.com>;\n Thu, 11 Jul 2024 21:09:18 +0300 (+03)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) header: Received: from mail.mydomain.com ([127.0.0.1])\n\tby mail.mydomain.com (mail.mydomain.com [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id YAnhv6RTJlvw for <receiver@gmail.com>;\n\tThu, 11 Jul 2024 21:09:18 +0300 (+03)\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) headers CLUSTERING: done all 1 recips in one go
Jul 11 21:09:18 mail amavis[33192]: (33192-01) about to connect to smtp:[127.0.0.1]:10025, YAnhv6RTJlvw FWD from <sendermail@mydomain.com> -> <receiver@gmail.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp session: setting up a new session
Jul 11 21:09:18 mail amavis[33192]: (33192-01) establish_or_refresh, state: down
Jul 11 21:09:18 mail amavis[33192]: (33192-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Jul 11 21:09:18 mail amavis[33192]: (33192-01) connected to [127.0.0.1]:10025 successfully
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jul 11 21:09:18 mail postfix/10025/smtpd[63881]: connect from mail.mydomain.com[127.0.0.1]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop read 41 chars< 220 mail.mydomain.com ESMTP Postfix\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp greeting: 220 mail.mydomain.com ESMTP Postfix, dt: 11.6 ms
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp cmd> EHLO mail.mydomain.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: sending 28 chars
Jul 11 21:09:18 mail postfix/10025/smtpd[63881]: discarding EHLO keywords: CHUNKING
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop sent 28> EHLO mail.mydomain.com\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop read 142 chars< 250-mail.mydomain.com\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-AUTH PLAIN LOGIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp resp to EHLO: 250 mail.mydomain.com\nPIPELINING\nSIZE 15728640\nETRN\nAUTH PLAIN LOGIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Jul 11 21:09:18 mail amavis[33192]: (33192-01) tls active=0, capable=, sec_level=0
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Remote host presents itself as: mail.mydomain.com, handles DSN, PIPELINING, 8BITMIME
Jul 11 21:09:18 mail amavis[33192]: (33192-01) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp cmd> MAIL FROM:<sendermail@mydomain.com> BODY=8BITMIME
Jul 11 21:09:18 mail amavis[33192]: (33192-01) orcpt_encode rfc822, receiver@gmail.com, encode_for_smtp
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp cmd> RCPT TO:<receiver@gmail.com> ORCPT=rfc822;receiver@gmail.com
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp cmd> DATA
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: sending 133 chars
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop sent 133> MAIL FROM:<sendermail@mydomain.com> BODY=8BITMIME\r\nRCPT TO:<receiver@gmail.com> ORCPT=rfc822;receiver@gmail.com\r\nDATA\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 11 21:09:18 mail postfix/10025/smtpd[63881]: 4WKjRL6kJvz7y6v: client=mail.mydomain.com[127.0.0.1]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-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
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp resp to RCPT (pip) (<receiver@gmail.com>): 250 2.1.5 Ok
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x5578edf77d30)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp connection_cache disabled, sending QUIT
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp cmd> QUIT
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.976
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: sending 913 chars
Jul 11 21:09:18 mail postfix/cleanup[63877]: 4WKjRL6kJvz7y6v: message-id=<53503349-ceca-47b1-b960-83e31491b467@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop sent 913> X-Virus-Scanned: Debian amavisd-new at mail.mydomain.com\r\nReceived: from mail.mydomain.com ([127.0.0.1])\r\n\tby mail.mydomain.com (mail.mydomain.com [127.0.0.1]) (amavisd-new, port 10024 [...]
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.976
Jul 11 21:09:18 mail postfix/10025/smtpd[63881]: disconnect from mail.mydomain.com[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 11 21:09:18 mail postfix/qmgr[63540]: 4WKjRL6kJvz7y6v: from=<sendermail@mydomain.com>, size=1116, nrcpt=1 (queue active)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop: receiving
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rw_loop read 56 chars< 250 2.0.0 Ok: queued as 4WKjRL6kJvz7y6v\r\n221 2.0.0 Bye\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) smtp resp to data-dot (<receiver@gmail.com>): 250 2.0.0 Ok: queued as 4WKjRL6kJvz7y6v, dt: 1.8 ms
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Amavis::Out::SMTP::Session close, disconnecting
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) YAnhv6RTJlvw FWD from <sendermail@mydomain.com> -> <receiver@gmail.com>, BODY=8BITMIME 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4WKjRL6kJvz7y6v
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline forwarding - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer forwarding: timer 288, was 288, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) DSN: sender NOT credible, SA: 0.000, <sendermail@mydomain.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup: (scalar) matches, result="10"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) lookup [spam_dsn_cutoff_level_bysender] => true,  "sendermail@mydomain.com" matches, result="10", matching_key="(constant:10)"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) dsn: from MTA 250 NonBlocking:Clean <sendermail@mydomain.com> -> <receiver@gmail.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 4WKjRL6kJvz7y6v"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <sendermail@mydomain.com> -> <receiver@gmail.com>
Jul 11 21:09:18 mail amavis[33192]: (33192-01) delivery_status_notification: notif 0 bytes, suppressed: no
Jul 11 21:09:18 mail amavis[33192]: (33192-01) one_response_for_all, per_recip_capable: N, suppressed: N
Jul 11 21:09:18 mail amavis[33192]: (33192-01) one_response_for_all <sendermail@mydomain.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 4WKjRL6kJvz7y6v'
Jul 11 21:09:18 mail amavis[33192]: (33192-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 4WKjRL6kJvz7y6v
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline delivery-notification - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline snmp-counters - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) orcpt_encode rfc822, receiver@gmail.com, smtputf8
Jul 11 21:09:18 mail amavis[33192]: (33192-01) oldest_public_ip_addr_from_received: my_home_ip
Jul 11 21:09:18 mail amavis[33192]: (33192-01) Passed CLEAN {RelayedInbound}, [my_home_ip]:41236 [my_home_ip] ESMTP/ESMTP <sendermail@mydomain.com> -> <receiver@gmail.com>, (ESMTPA://[my_home_ip]:41236), Queue-ID: 4WKjRL5Lczz7y6n, Message-ID: <53503349-ceca-47b1-b960-83e31491b467@mydomain.com>, mail_id: YAnhv6RTJlvw, b: rRlYLTU5i, Hits: -, size: 601, queued_as: 4WKjRL6kJvz7y6v, Subject: "meraba dünya (raw: =?UTF-8?Q?meraba_d=C3=BCnya?=)", From: <sendermail@mydomain.com>, User-Agent: Mozilla_Thunderbird, helo=[192.168.1.106], 122 ms
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline main_log_entry - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql begin transaction
Jul 11 21:09:18 mail amavis[33192]: (33192-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 (?,?,?,?,?,?,?,?,?,?,?,?)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) save_info_final YAnhv6RTJlvw, orig=N, chks=VHB, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <53503349-ceca-47b1-b960-83e31491b467@mydomain.com>, From: 'xxx <sendermail@mydomain.com>', Subject: 'meraba dünya'
Jul 11 21:09:18 mail amavis[33192]: (33192-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=?
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sql commit
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline check done - deadline in 479.9 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer check done: timer 288, was 288, deadline in 479.9 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4WKjRL6kJvz7y6v"
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4WKjRL6kJvz7y6v
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail postfix/amavis/smtp[63878]: 4WKjRL5Lczz7y6n: to=<receiver@gmail.com>, relay=0.0.0.0[0.0.0.0]:10024, delay=0.26, delays=0.11/0.02/0.01/0.12, 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 4WKjRL6kJvz7y6v)
Jul 11 21:09:18 mail amavis[33192]: (33192-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP
Jul 11 21:09:18 mail amavis[33192]: (33192-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20240711T210918-33192-FV_3ubJP/parts, excl=1
Jul 11 21:09:18 mail postfix/qmgr[63540]: 4WKjRL5Lczz7y6n: removed
Jul 11 21:09:18 mail amavis[33192]: (33192-01) size: 601, TIMING [total 132 ms] - sql-prepare: 3.9 (3%)3, SMTP greeting: 3.3 (3%)5, SMTP EHLO: 1.8 (1%)7, SMTP pre-MAIL: 1.9 (1%)8, mkdir tempdir: 1.1 (1%)9, create email.txt: 0.3 (0%)9, SMTP MAIL: 1.9 (1%)11, sql-connect: 9 (7%)17, lookup_sql: 1.5 (1%)18, SMTP pre-DATA-flush: 1.5 (1%)20, SMTP DATA: 0.4 (0%)20, check_init: 0.4 (0%)20, digest_hdr: 2.5 (2%)22, digest_body_dkim: 0.5 (0%)22, collect_info: 2.0 (2%)24, gen_mail_id: 3.6 (3%)27, mkdir parts: 1.7 (1%)28, mime_decode: 7 (5%)33, get-file-type1: 14 (11%)43, parts_decode: 0.3 (0%)44, check_header: 0.8 (1%)44, AV-scan-1: 13 (10%)54, lookup_sql: 1.7 (1%)55, spam-wb-list: 1.7 (1%)57, decide_mail_destiny: 1.2 (1%)58, notif-quar: 0.4 (0%)58, fwd-connect: 18 (14%)71, fwd-mail-pip: 7 (6%)77, fwd-rcpt-pip: 0.4 (0%)77, fwd-data-chkpnt: 0.0 (0%)77, write-header: 0.8 (1%)78, fwd-data-contents: 0.0 (0%)78, fwd-end-chkpnt: 5.0 (4%)82, prepare-dsn: 3.0 (2%)84, report: 3.7 (3%)87, main_log_entry: 9 (7%)94, sql-u...
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ...pdate: 7 (5%)99, SMTP pre-response: 0.2 (0%)99, SMTP response: 0.3 (0%)99, unlink-1-files: 0.3 (0%)99, rundown: 0.7 (1%)100
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 6: was busy, 108.0 ms, total idle 0.001 s, busy 0.132 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.132 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP< QUIT\r\n
Jul 11 21:09:18 mail amavis[33192]: (33192-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jul 11 21:09:18 mail amavis[33192]: (33192-01) switch_to_client_time 480 s, smtp response sent
Jul 11 21:09:18 mail amavis[33192]: (33192-01) SMTP session over, timer stopped
Jul 11 21:09:18 mail amavis[33192]: (33192-01) exiting process_request
Jul 11 21:09:18 mail amavis[33192]: (33192-01) idle_proc, bye: was busy, 2.6 ms, total idle 0.001 s, busy 0.135 s
Jul 11 21:09:18 mail amavis[33192]: (33192-01) load: 99 %, total idle 0.001 s, busy 0.135 s
Jul 11 21:09:19 mail postfix/smtp[63882]: Trusted TLS connection established to gmail-smtp-in.l.google.com[64.233.167.26]:25: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature ECDSA (P-256) server-digest SHA256
Jul 11 21:09:20 mail postfix/smtp[63882]: 4WKjRL6kJvz7y6v: to=<receiver@gmail.com>, relay=gmail-smtp-in.l.google.com[64.233.167.26]:25, delay=1.2, delays=0.01/0.02/0.7/0.52, dsn=2.0.0, status=sent (250 2.0.0 OK  1720721360 5b1f17b1804b1-427958d518esi24248365e9.183 - gsmtp)
Jul 11 21:09:20 mail postfix/qmgr[63540]: 4WKjRL6kJvz7y6v: removed
Jul 11 21:09:23 mail postfix/smtpd[63872]: disconnect from unknown[my_home_ip] ehlo=2 xclient=0/1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=7/8

----

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

Re: Amavis DKIM Problem

Port 10024 is used to process inbound messages, so no DKIM signing, just DKIM verification.
If you send email through port 465 (SSL) or 587 (submission, TLS), the email will be DKIM signed.

3 Reply by legendsxxxhunter (edited by legendsxxxhunter 2024-07-14 19:54:40)

  • legendsxxxhunter
  • Member
  • Offline
  • Registered: 2024-07-08
  • Posts: 6

Re: Amavis DKIM Problem

ZhangHuangbin wrote:

Port 10024 is used to process inbound messages, so no DKIM signing, just DKIM verification.
If you send email through port 465 (SSL) or 587 (submission, TLS), the email will be DKIM signed.

Thank you for your response. Yes, I realized this during my research yesterday. The Auth-Port information in my auth.php file was returning 25 for SMTP. I changed it to 587. However, after changing it to 587, I encountered the issue below. I have also included my auth.php and nginx mail proxy configuration. Could you please review and tell me if there is any mistake?

I am making my mail connection with the command:
openssl s_client -starttls smtp -connect mail.my_proxy_server_ip.com:587 -ign_eof

/var/log/mail.log:

Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: connect from unknown[my_proxy_server_ip]
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: smtp_stream_setup: maxtime=300 enable_deadline=0
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: name_mask: chunking
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 220 mail.mydomain.com ESMTP Postfix
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: watchdog_pat: 0x55b7b1a018f0
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: < unknown[my_proxy_server_ip]: EHLO mail.mydomain.com
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: dict_pcre_lookup: /etc/postfix/command_filter.pcre: EHLO mail.mydomain.com
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: discarding EHLO keywords: CHUNKING
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: match_list_match: unknown: no match
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: match_list_match: my_proxy_server_ip: no match
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-mail.mydomain.com
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-PIPELINING
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-SIZE 15728640
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-ETRN
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-STARTTLS
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-XCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT LOGIN DESTADDR DESTPORT
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-ENHANCEDSTATUSCODES
Jul 12 22:05:34 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250-8BITMIME
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_proxy_server_ip]: 250 DSN
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: watchdog_pat: 0x55b7b1a018f0
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: < unknown[my_proxy_server_ip]: XCLIENT ADDR=my_agent_ip NAME=[UNAVAILABLE]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: dict_pcre_lookup: /etc/postfix/command_filter.pcre: XCLIENT ADDR=my_agent_ip NAME=[UNAVAILABLE]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_authorized_xclient_hosts: unknown ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_authorized_xclient_hosts: my_agent_ip ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_list_match: unknown: no match
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_list_match: my_agent_ip: no match
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 127.0.0.1
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? 127.0.0.1
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? [::1]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? [::1]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_home_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_home_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_agent_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_agent_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: name_mask: chunking
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 220 mail.mydomain.com ESMTP Postfix
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: watchdog_pat: 0x55b7b1a018f0
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: < unknown[my_agent_ip]: EHLO mail.mydomain.com
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: dict_pcre_lookup: /etc/postfix/command_filter.pcre: EHLO mail.mydomain.com
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: discarding EHLO keywords: CHUNKING
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_list_match: unknown: no match
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_list_match: my_agent_ip: no match
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-mail.mydomain.com
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-PIPELINING
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-SIZE 15728640
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-ETRN
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-STARTTLS
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-ENHANCEDSTATUSCODES
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250-8BITMIME
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 250 DSN
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: watchdog_pat: 0x55b7b1a018f0
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: < unknown[my_agent_ip]: AUTH PLAIN 77+9c2VuZGVybWFpbEBteWRvbWFpbi5jb23vv71hc2QxMjMzMjEtLQ==
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: dict_pcre_lookup: /etc/postfix/command_filter.pcre: AUTH PLAIN 77+9c2VuZGVybWFpbEBteWRvbWFpbi5jb23vv71hc2QxMjMzMjEtLQ==
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 530 5.7.0 Must issue a STARTTLS command first
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: watchdog_pat: 0x55b7b1a018f0
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: smtp_get: EOF
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 127.0.0.1
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? 127.0.0.1
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? [::1]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? [::1]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_proxy_server_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_home_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_home_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? my_agent_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: match_hostaddr: smtpd_client_event_limit_exceptions: my_agent_ip ~? my_agent_ip
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: lost connection after EHLO from unknown[my_agent_ip]
Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: disconnect from unknown[my_agent_ip] ehlo=2 xclient=0/1 auth=0/1 commands=2/4


nginx mail proxy configuration:

mail {

server_name mail.mydomain.com;
auth_http localhost/auth/auth.php;
pop3_capabilities "TOP" "USER" "UIDL" "PIPELINING" "SASL";
imap_capabilities "IMAP4rev1" "UIDPLUS" "IDLE" "LITERAL+" "QUOTA";
smtp_capabilities "SIZE 53477376" "8BITMIME" "ENHANCEDSTATUSCODES" "PIPELINING" "DSN";

proxy_smtp_auth on;
proxy on;
proxy_pass_error_message on;
proxy_timeout 300s;

starttls                   on;
ssl_protocols              TLSv1.2 TLSv1.3;
ssl_ciphers                HIGH:!ADH:!MD5:@STRENGTH;
ssl_session_cache          shared:TLSSL:16m;
ssl_session_timeout        10m;
ssl_certificate            /etc/letsencrypt/live/mail.mydomain.com/fullchain.pem;
ssl_certificate_key        /etc/letsencrypt/live/mail.mydomain.com/privkey.pem;
ssl_dhparam                /etc/ssl/certs/dhparam.pem;

      server {
                listen     25;
                listen     [::]:25;
                protocol   smtp;
                smtp_auth  none;
                starttls   only;
                auth_http_header PORT 25;
        }

        server {
                listen     465 ssl;
                listen     [::]:465 ssl;
                protocol   smtp;
                smtp_auth  login plain;
                auth_http_header PORT 465;
        }

        server {
                listen     587;
                listen     [::]:587;
                protocol   smtp;
                smtp_auth  login plain;
                starttls   only;
                auth_http_header PORT 587;
        }

        server {
                listen     110;
                listen     [::]:110;
                protocol   pop3;
                starttls   only;
        }

        server {
                listen     995 ssl;
                listen     [::]:995 ssl;
                protocol   pop3;
        }

        server {
                listen     143;
                listen     [::]:143;
                protocol   imap;
                starttls   only;
        }

        server {
                listen     993 ssl;
                listen     [::]:993 ssl;
                protocol   imap;
        }
}


auth.php codes:

    header("HTTP/1.0 200 OK");
    header("Auth-Status: OK");
    header("Auth-Server: $server");
    header("Auth-Port: $port"); // If the request is using the SMTP protocol, the $port variable will be set to 587.
    exit();


Postfix main.cf:

smtpd_authorized_xclient_hosts = my_proxy_server_ip

4 Reply by Cthulhu

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

Re: Amavis DKIM Problem

Since this is your own implementation and i still dont understand your problems, i can only give you this:

https://docs.iredmail.org/used.componen … ig-picture

this is full documentation about mail flow, both inbound and outbound

5 Reply by ZhangHuangbin

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

Re: Amavis DKIM Problem

legendsxxxhunter wrote:

Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 530 5.7.0 Must issue a STARTTLS command first

Does your client have smtp authentication enabled?

6 Reply by legendsxxxhunter

  • legendsxxxhunter
  • Member
  • Offline
  • Registered: 2024-07-08
  • Posts: 6

Re: Amavis DKIM Problem

ZhangHuangbin wrote:
legendsxxxhunter wrote:

Jul 12 22:05:35 mail postfix/submission/smtpd[54599]: > unknown[my_agent_ip]: 530 5.7.0 Must issue a STARTTLS command first

Does your client have smtp authentication enabled?

Yes, I am connecting with the following command. I also tried it with applications like Thunderbird. I get this log output in all of them.

The command I used:

openssl s_client -starttls smtp -connect mail.mydomain.com:587 -ign_eof

7 Reply by ZhangHuangbin

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

Re: Amavis DKIM Problem

You don't have directive `proxy_pass` in "server {}" block?
How does Nginx know which backend servers it should proxy the smtp requests to?

8 Reply by legendsxxxhunter (edited by legendsxxxhunter 2024-07-15 23:19:35)

  • legendsxxxhunter
  • Member
  • Offline
  • Registered: 2024-07-08
  • Posts: 6

Re: Amavis DKIM Problem

ZhangHuangbin wrote:

You don't have directive `proxy_pass` in "server {}" block?
How does Nginx know which backend servers it should proxy the smtp requests to?

Unfortunately, the proxy_pass feature is not available in the NGINX mail proxy.

It finds the iRedMail server via auth.php. I reach the domain from the entered email address and check the domain on my servers. For whichever iRedMail server this domain is on, I write that server's IP address in the Auth-Server section. I also detect the port through the auth_http_header PORT information and protocol information, and send it to that port via Auth-Port. If possible, I can share all the information with you via a private conversation on Telegram when you are available, and then update this topic as a guide to provide accurate information to people once the issue is resolved. I think it would be helpful. I can even send you the server information if you wish. But I need to know the entire process; I've been struggling with this for 14 days sad I couldn't find any resources.