1

I have a Postfix (2.10.1) / Dovecot server running on Centos 7. From specific servers I get about 50 copies of the same email every weekend, I tried a wireshark but it uses STARTTLS so its all encrypted, so I turned on logging in postfix. Everything looks fine, then I get a huge delay in-between the DATA and the QUEUED. See Below. Note the time stamp, it takes 4 minutes and 14 seconds, there also is no QUIT at the end and I think and the remote server is timing out so it just keeps sending the message. I noticed the delay appears to be with opendkim, so any idea how to fix this? Is this a opendkim issue? Why is it checking the DKIM during the DATA transmission? Why would it take that long to check a DKIM Signature? So far this is only happening to about three senders I know of, but its getting quite bothersome. Thanks!

Sep  5 15:15:10 services postfix/smtpd[17135]: > unknown[54.240.15.240]: 250 2.1.5 Ok
Sep  5 15:15:10 services postfix/smtpd[17135]: < unknown[54.240.15.240]: DATA
Sep  5 15:15:10 services postfix/smtpd[17135]: report data to all milters
Sep  5 15:15:10 services postfix/smtpd[17135]: milter_macro_lookup: "i"
Sep  5 15:15:10 services postfix/smtpd[17135]: milter_macro_lookup: result "4A0FB12A7"
Sep  5 15:15:10 services postfix/smtpd[17135]: milter8_data_event: milter inet:127.0.0.1:8891: data command
Sep  5 15:15:10 services postfix/smtpd[17135]: skipping non-protocol event SMFIC_DATA for milter inet:127.0.0.1:8891
Sep  5 15:15:10 services postfix/smtpd[17135]: send 1 milters
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr conn_macros = j {daemon_name} v
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr helo_macros = {tls_version} {cipher} {cipher_bits} {cert_subject} {cert_issuer}
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr mail_macros = i {auth_type} {auth_authen} {auth_author} {mail_addr} {mail_host} {mail_mailer}
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr rcpt_macros = i {rcpt_addr} {rcpt_host} {rcpt_mailer}
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr data_macros = i
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr eoh_macros = i
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr eod_macros = i
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr unk_macros =
Sep  5 15:15:10 services postfix/smtpd[17135]: milter8_send: milter inet:127.0.0.1:8891
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_name = inet:127.0.0.1:8891
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_version = 2
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_actions = 273
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_events = 2
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_non_events = 768
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_state = 4
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_conn_timeout = 30
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_cmd_timeout = 30
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_msg_timeout = 300
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_action = accept
Sep  5 15:15:10 services postfix/smtpd[17135]: send attr milter_macro_list = 0
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: dummy
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: dummy
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute value: (end)
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: (list terminator)
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: (end)
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: dummy
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: dummy
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute value: (end)
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: (list terminator)
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: (end)
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: status
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: status
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute value: 0
Sep  5 15:15:10 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: (list terminator)
Sep  5 15:15:10 services postfix/smtpd[17135]: input attribute name: (end)
Sep  5 15:15:10 services postfix/smtpd[17135]: > unknown[54.240.15.240]: 354 End data with <CR><LF>.<CR><LF>
Sep  5 15:15:10 services postfix/cleanup[17137]: 4A0FB12A7: message-id=<010001830f0b97bf-95e8fbf3-db43-47f5-b374-375fb854f93d-000000@email.amazonses.com>
Sep  5 15:15:10 services opendkim[844]: 4A0FB12A7: [54.240.15.240] [54.240.15.240] not internal
Sep  5 15:15:10 services opendkim[844]: 4A0FB12A7: not authenticated
Sep  5 15:19:24 services opendkim[844]: 4A0FB12A7: message has signatures from primevideo.com, amazonses.com
Sep  5 15:19:24 services opendkim[844]: 4A0FB12A7: DKIM verification successful
Sep  5 15:19:24 services postfix/qmgr[17047]: 4A0FB12A7: from=<202209051906004530ab8903c4489cb0803dfa57e0p0na-C2PQNMO0KKWW5B@bounces.primevideo.com>, size=98742, nrcpt=1 (queue activ
e)
Sep  5 15:19:24 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: status
Sep  5 15:19:24 services postfix/smtpd[17135]: input attribute name: status
Sep  5 15:19:24 services postfix/smtpd[17135]: input attribute value: 0
Sep  5 15:19:24 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: reason
Sep  5 15:19:24 services postfix/smtpd[17135]: input attribute name: reason
Sep  5 15:19:24 services postfix/smtpd[17135]: input attribute value: (end)
Sep  5 15:19:24 services postfix/smtpd[17135]: public/cleanup socket: wanted attribute: (list terminator)
Sep  5 15:19:24 services postfix/smtpd[17135]: input attribute name: (end)
Sep  5 15:19:24 services postfix/smtpd[17135]: > unknown[54.240.15.240]: 250 2.0.0 Ok: queued as 4A0FB12A7

Added master.cf -

command_directory = /usr/sbin
daemon_directory = /usr/libexec/postfix
data_directory = /var/lib/postfix
debug_peer_level = 2
smtp_tls_loglevel = 4

debugger_command =
         PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin
         ddd $daemon_directory/$process_name $process_id & sleep 5

sendmail_path = /usr/sbin/sendmail.postfix
newaliases_path = /usr/bin/newaliases.postfix
mailq_path = /usr/bin/mailq.postfix
setgid_group = postdrop
html_directory = no
manpage_directory = /usr/share/man
sample_directory = /usr/share/doc/postfix-2.10.1/samples
readme_directory = /usr/share/doc/postfix-2.10.1/README_FILES

myorigin = origindom.com

inet_protocols = all

mydestination = /etc/postfix/mydestination
unknown_local_recipient_reject_code = 550
mynetworks = 127.0.0.0/8

alias_database = hash:/etc/postfix/aliases
alias_maps = hash:/etc/postfix/aliases

home_mailbox = Maildir/
mail_spool_directory = /var/spool/mail

mailbox_command = /usr/bin/procmail

smtpd_banner = mail.origindom.com ESMTP $mail_name ($mail_version)

mynetworks_style = class
ignore_mx_lookup_error = yes
smtpd_recipient_restrictions = permit_sasl_authenticated reject_unauth_destinati                                                                                                 on
smtpd_sender_restrictions = permit_sasl_authenticated reject_unauth_destination
smtpd_sasl_authenticated_header = yes

smtpd_tls_cert_file = /etc/letsencrypt/live/mail.origindom.com/fullchain.pem
smtpd_tls_key_file = /etc/letsencrypt/live/mail.origindom.com/privkey.pem
smtpd_tls_session_cache_database = btree:/var/lib/postfix/smtpd_tls_session_cach                                                                                               e
smtpd_use_tls = yes
smtpd_tls_security_level = may
tls_random_source = dev:/dev/urandom

mailbox_size_limit = 5368709120
debug_peer_list = origindom.com
message_size_limit = 31457280
myhostname = origindom.com

smtpd_sasl_type = dovecot
smtpd_sasl_path = private/auth
smtpd_sasl_auth_enable = yes
smtp_sasl_security_options = noanonymous
smtpd_relay_restrictions = permit_mynetworks permit_inet_interfaces permit_sasl_                                                                                                 authenticated

milter_protocol = 2
smtpd_milters = inet:127.0.0.1:8891
non_smtpd_milters = $smtpd_milters
milter_default_action = accept

receive_override_options = no_address_mappings
sender_bcc_maps = hash:/etc/postfix/sender_bcc_maps
sender_canonical_maps = regexp:/etc/postfix/sender_canonical_maps
canonical_maps = hash:/etc/postfix/canonical
Jeremy
  • 11
  • 2
  • 2
    Please append your Postfix configuration as described in the [tag wiki page](https://serverfault.com/questions/tagged/postfix). However, to my experience, this could happen if the address is an alias that expands to multiple recipients and for some of them delivery *temporarily fails* (with code 4xx). Postfix retries original mail *before* alias expansion, so where delivery succeeds, it gets delivered more than once. – Nikita Kipriyanov Sep 06 '22 at 03:55
  • 2
    You are using a decade-old Postfix version, that makes me wonder how old your other components are, and if your troubles would disappear with an up-to-date system? – glts Sep 06 '22 at 07:44
  • The minimum timeout [should be 10 minutes](https://www.rfc-editor.org/rfc/rfc5321#section-4.5.3.2.6) for awaiting the 250, which is well above the 4:14 you are showing. – anx Sep 06 '22 at 10:06
  • Maybe someone (not necessarily the message affected) is exhausting some resource by submitting a lot of headers with references to domains with unresponsive servers, and that is what is slowing down opendkim? Have you set/modified `DNSTimeout` in opendkim.conf? – anx Sep 06 '22 at 10:19
  • The recipients are not alias's, and its not a issue of alias duplication, I am getting 50+ copies of the exact same message with exactly the same headers, including to/from. I will update the post with the config. The version is whatever version comes on Centos 7, and whatever its latest is. I have not adjusted anything with opendkim config, so I will look at that, that possibly could be it. – Jeremy Sep 06 '22 at 17:10
  • consider the [tutorial](https://computingforgeeks.com/installing-postfix3-on-centos-7/) to install a supported version – djdomi Sep 06 '22 at 17:37

0 Answers0