1

I have a customer attempting to use postfix to send emails with SMTP. It appears that postfix will parse the email attributes correctly, but before sending the email it begins processing it again. This happens in an endless loop. I've put postfix into debug mode and produced a log file that looks almost exactly the same as a log file produced with my own system up to the point where it repeats the parsing of the email.

The customer's end-of-log:

postfix/smtpd[29586]: connection closed
postfix/smtpd[29586]: connection established

My end-of-log:

postfix/smtpd[20539]: connection closed
postfix/smtp[20543]: 0D65814D: to=<test@mailsac.com>, relay=10.2.253.96[10.2.253.96]:25, delay=0.17, delays=0.03/0.07/0/0.06, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as O)
postfix/qmgr[19812]: 0D65814D: removed

The main.cf file has

mydomain = localhost
alias_maps = hash:/etc/aliases
queue_directory = /var/spool/postfix
command_directory = /usr/sbin
daemon_directory = /usr/libexec/postfix
mail_owner = postfix
myorigin = $mydomain
unknown_local_recipient_reject_code = 550
mynetworks = 127.0.0.0/8, [::1]/128
debug_peer_level = 2
sendmail_path = /usr/sbin/sendmail
newaliases_path = /usr/bin/newaliases
mailq_path = /usr/bin/mailq
setgid_group = postdrop
html_directory = no
manpage_directory = /usr/local/man
sample_directory = /etc/postfix
readme_directory = no
virtual_mailbox_domains = sciencelogic.em7
virtual_mailbox_base = /var/mail
virtual_mailbox_maps = hash:/etc/postfix/silo.virtual-mailbox
virtual_uid_maps = hash:/etc/postfix/silo.virtual-uid
virtual_gid_maps = hash:/etc/postfix/silo.virtual-gid
mailbox_size_limit = 0
relayhost = authnz.proofpoint.com:587
smtp_sasl_auth_enable = yes
smtp_sasl_password_maps = hash:/etc/postfix/smtp_password
smtpd_recipient_restrictions = permit_mynetworks
local_recipient_maps =

There is no information about the email being rejected in the queue log. Running mailq > mailqueue.txt did not produce any meaningful information. I've also had the customer flush the queue with postqueue -f and restart postfix, but nothing has helped.

What is causing postfix to repeat parsing the email instead of sending it?

EDIT:

The master.cf file states (shortened for space to remove all commented-out lines):

smtp      inet  n   -   n   -   -   smtpd -v
pickup    unix  n   -   n   60  1   pickup
cleanup   unix  n   -   n   -   0   cleanup
qmgr      unix  n   -   n   300     1   qmgr
tlsmgr    unix  -   -   n   1000?   1   tlsmgr
rewrite   unix  -   -   n   -   -   trivial-rewrite
bounce    unix  -   -   n   -   0   bounce
defer     unix  -   -   n   -   0   bounce
trace     unix  -   -   n   -   0   bounce
verify    unix  -   -   n   -   1   verify
flush     unix  n   -   n   1000?   0   flush
proxymap  unix  -   -   n   -   -   proxymap
proxywrite unix -   -   n   -   1   proxymap
smtp      unix  -   -   n   -   -   smtp
relay     unix  -   -   n   -   -   smtp
showq     unix  n   -   n   -   -   showq
error     unix  -   -   n   -   -   error
retry     unix  -   -   n   -   -   error
discard   unix  -   -   n   -   -   discard
local     unix  -   n   n   -   -   local
virtual   unix  -   n   n   -   -   virtual
lmtp      unix  -   -   n   -   -   lmtp
anvil     unix  -   -   n   -   1   anvil
scache    unix  -   -   n   -   1   scache

EDIT:

postqueue -p produces:

[root@sc-sl02-lab01 ~]# postqueue -p
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
8687E226F6E*     936 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

88630226F70*     935 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

92456226F71*     933 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

E0986226F74*     942 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

EF72C36B12*     930 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

F1631226F78*     930 Tue May 10 19:46:06  dev.ms.monitoring@cdw.ca
                                         minh.tang@cdw.ca

3DE91226F77*    3072 Tue May 10 19:46:11  MAILER-DAEMON
                                         dev.ms.monitoring@cdw.ca

sudo postcat -qhbe 3DE91226F77:

-- 40 Kbytes in 17 Requests.
[root@sc-sl02-lab01 ~]# sudo postcat -qhbe 3DE91226F77
*** ENVELOPE RECORDS active/3DE91226F77 ***
message_size:            3072             221               1               0            3072
message_arrival_time: Tue May 10 19:46:11 2022
create_time: Tue May 10 19:46:11 2022
named_attribute: log_message_origin=local
named_attribute: trace_flags=0
sender:
original_recipient: dev.ms.monitoring@cdw.ca
recipient: dev.ms.monitoring@cdw.ca
*** MESSAGE CONTENTS active/3DE91226F77 ***
Received: by sc-sl02-lab01.localhost (Postfix)
        id 3DE91226F77; Tue, 10 May 2022 19:46:11 +0000 (UTC)
Date: Tue, 10 May 2022 19:46:11 +0000 (UTC)
From: MAILER-DAEMON@localhost.localhost (Mail Delivery System)
Subject: Undelivered Mail Returned to Sender
To: dev.ms.monitoring@cdw.ca
Auto-Submitted: auto-replied
MIME-Version: 1.0
Content-Type: multipart/report; report-type=delivery-status;
        boundary="0A32B226F7D.1652211971/sc-sl02-lab01.localhost"
Message-Id: <20220510194611.3DE91226F77@sc-sl02-lab01.localhost>

This is a MIME-encapsulated message.

--0A32B226F7D.1652211971/sc-sl02-lab01.localhost
Content-Description: Notification
Content-Type: text/plain; charset=us-ascii

This is the mail system at host sc-sl02-lab01.localhost.

I'm sorry to have to inform you that your message could not
be delivered to one or more recipients. It's attached below.

For further assistance, please send mail to postmaster.

If you do so, please include this problem report. You can
delete your own text from the attached returned message.

                   The mail system

<minh.tang@cdw.ca>: host
    authnz.prod-c15a-awsuse.proofpoint.com[205.220.189.150] said: 530 5.7.0
    Authentication required (in reply to MAIL FROM command)

--0A32B226F7D.1652211971/sc-sl02-lab01.localhost
Content-Description: Delivery report
Content-Type: message/delivery-status

Reporting-MTA: dns; sc-sl02-lab01.localhost
X-Postfix-Queue-ID: 0A32B226F7D
X-Postfix-Sender: rfc822; dev.ms.monitoring@cdw.ca
Arrival-Date: Tue, 10 May 2022 19:46:07 +0000 (UTC)

Final-Recipient: rfc822; minh.tang@cdw.ca
Original-Recipient: rfc822;minh.tang@cdw.ca
Action: failed
Status: 5.7.0
Remote-MTA: dns; authnz.prod-c15a-awsuse.proofpoint.com
Diagnostic-Code: smtp; 530 5.7.0 Authentication required

--0A32B226F7D.1652211971/sc-sl02-lab01.localhost
Content-Description: Undelivered Message
Content-Type: message/rfc822

Return-Path: <dev.ms.monitoring@cdw.ca>
Received: from [172.16.0.1] (localhost [IPv6:::1])
        by sc-sl02-lab01.localhost (Postfix) with ESMTP id 0A32B226F7D
        for <minh.tang@cdw.ca>; Tue, 10 May 2022 19:46:07 +0000 (UTC)
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: 7bit
Subject: MAJOR Event: Load average alert,
 (Load-15) state: (True) is running above the threshold of (None)
From: EM7 LAB Event Notifier<dev.ms.monitoring@cdw.ca>
To:
CC:
X-Priority: 3
Date: Tue, 10 May 2022 19:46:07 +0000
Message-Id: <20220510194607.0A32B226F7D@sc-sl02-lab01.localhost>

Severity: MAJOR
First Occurred: 2022-05-09 11:48:18 UTC
Last Occurred: 2022-05-10 19:44:22 UTC
Occurrences: 954
Source: Dynamic
Organization: ScienceLogic Org
Device: sc-sl01-db01

Message: Load average alert, (Load-15) state: (True) is running above the threshold of (None)

Sent by Automation Action: Send Email External

View this event at: http://em7.mydomain.com/em7/index.em7?exec=events&q_type=aid&q_arg=3988100&q_sev=1&q_sort=0&q_oper=0

--0A32B226F7D.1652211971/sc-sl02-lab01.localhost--
*** HEADER EXTRACTED active/3DE91226F77 ***
*** MESSAGE FILE END active/3DE91226F77 ***
[root@sc-sl02-lab01 ~]# sudo postcat -qhbe 14CBC226F76
*** ENVELOPE RECORDS active/14CBC226F76 ***
message_size:            2962             220               1               0            2962
message_arrival_time: Tue May 10 19:46:10 2022
create_time: Tue May 10 19:46:10 2022
named_attribute: log_message_origin=local
named_attribute: trace_flags=0
sender:
original_recipient: dev.ms.monitoring@cdw.ca
recipient: dev.ms.monitoring@cdw.ca
*** MESSAGE CONTENTS active/14CBC226F76 ***
Received: by sc-sl02-lab01.localhost (Postfix)
        id 14CBC226F76; Tue, 10 May 2022 19:46:10 +0000 (UTC)
Date: Tue, 10 May 2022 19:46:10 +0000 (UTC)
From: MAILER-DAEMON@localhost.localhost (Mail Delivery System)
Subject: Undelivered Mail Returned to Sender
To: dev.ms.monitoring@cdw.ca
Auto-Submitted: auto-replied
MIME-Version: 1.0
Content-Type: multipart/report; report-type=delivery-status;
        boundary="000EC226F79.1652211970/sc-sl02-lab01.localhost"
Message-Id: <20220510194610.14CBC226F76@sc-sl02-lab01.localhost>

This is a MIME-encapsulated message.

--000EC226F79.1652211970/sc-sl02-lab01.localhost
Content-Description: Notification
Content-Type: text/plain; charset=us-ascii

This is the mail system at host sc-sl02-lab01.localhost.

I'm sorry to have to inform you that your message could not
be delivered to one or more recipients. It's attached below.

For further assistance, please send mail to postmaster.

If you do so, please include this problem report. You can
delete your own text from the attached returned message.

                   The mail system

<minh.tang@cdw.ca>: host
    authnz.prod-c15a-awsuse.proofpoint.com[205.220.189.192] said: 530 5.7.0
    Authentication required (in reply to MAIL FROM command)

--000EC226F79.1652211970/sc-sl02-lab01.localhost
Content-Description: Delivery report
Content-Type: message/delivery-status

Reporting-MTA: dns; sc-sl02-lab01.localhost
X-Postfix-Queue-ID: 000EC226F79
X-Postfix-Sender: rfc822; dev.ms.monitoring@cdw.ca
Arrival-Date: Tue, 10 May 2022 19:46:06 +0000 (UTC)

Final-Recipient: rfc822; minh.tang@cdw.ca
Original-Recipient: rfc822;minh.tang@cdw.ca
Action: failed
Status: 5.7.0
Remote-MTA: dns; authnz.prod-c15a-awsuse.proofpoint.com
Diagnostic-Code: smtp; 530 5.7.0 Authentication required

--000EC226F79.1652211970/sc-sl02-lab01.localhost
Content-Description: Undelivered Message
Content-Type: message/rfc822

Return-Path: <dev.ms.monitoring@cdw.ca>
Received: from [172.16.0.1] (localhost [IPv6:::1])
        by sc-sl02-lab01.localhost (Postfix) with ESMTP id 000EC226F79
        for <minh.tang@cdw.ca>; Tue, 10 May 2022 19:46:06 +0000 (UTC)
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: 7bit
Subject: MAJOR Event: Device Service Risk is High: 75
From: EM7 LAB Event Notifier<dev.ms.monitoring@cdw.ca>
To:
CC:
X-Priority: 3
Date: Tue, 10 May 2022 19:46:06 +0000
Message-Id: <20220510194607.000EC226F79@sc-sl02-lab01.localhost>

Severity: MAJOR
First Occurred: 2022-05-09 01:00:16 UTC
Last Occurred: 2022-05-10 19:45:18 UTC
Occurrences: 172
Source: Internal
Organization: System
Device: test device service

Message: Device Service Risk is High: 75

Sent by Automation Action: Send Email External

View this event at: http://em7.mydomain.com/em7/index.em7?exec=events&q_type=aid&q_arg=3987958&q_sev=1&q_sort=0&q_oper=0

--000EC226F79.1652211970/sc-sl02-lab01.localhost--
*** HEADER EXTRACTED active/14CBC226F76 ***
*** MESSAGE FILE END active/14CBC226F76 ***
Adam
  • 11
  • 2
  • Please add your postfix configuration as recommended in the tag, and an example of how the message appears in the queue, both might contain helpful clues. (use `postqueue -p` to list, use `postcat -qhbe QID` to review a single entry, and get more context in logs to distinguish the sender just sending the message multiple times from a malfunction on your end). – anx May 03 '22 at 04:42
  • 1
    Other than the odd domains I don't see anything immediately obvious in your config. Where are you getting that *"It appears that"* idea from. Please share more log context and a sample message as it appears in the queue, there may actually be a clue as to what exactly postfix is doing. – anx May 11 '22 at 14:53
  • Please see the edited post that includes the `master.cf` file. The `main.cf` file is the postfix configuration. I also included the `postqueue -p` and `postcat -qhbe` commands. – Adam May 11 '22 at 14:53
  • add grep's with mail ID (e.g. `grep 0D65814D mail.log` to enhance the log excerpt in the question) – Nikita Kipriyanov May 11 '22 at 14:55
  • 1
    What's the 10.2.253.96? – Esa Jokinen May 11 '22 at 15:00
  • That is the relay for the test email I was using on my end `mailsac.com`. – Adam May 11 '22 at 15:06
  • 1
    Unrelated, but you should probably fix that `localhost` bit. Names clearly belonging to locally-administered naming schemes/roots? A-OK. But receiving mail from `localhost.localhost` containing little information which originator/relay is associated with which org/branch/room/machine? Very annoying to anyone diagnosing mail issues in the future! – anx May 11 '22 at 15:27
  • The best is to set real `myhostname` and leave `myorigin=$myhostname` (the default). – Nikita Kipriyanov May 12 '22 at 09:25

1 Answers1

0

authnz.prod-c15a-awsuse.proofpoint.com[205.220.189.150] said: 530 5.7.0 Authentication required (in reply to MAIL FROM command)

That sounds a lot like you are not authenticating to the relay you have configured.

relayhost = authnz.proofpoint.com:587
smtp_sasl_auth_enable = yes
smtp_sasl_password_maps = hash:/etc/postfix/smtp_password

Check the contents of /etc/postfix/smtp_password. Specifically, postfix instruct you to match the format between relayhost value and map lookup key.

If you specify a non-default TCP Port (such as ":submission" or ":587") in the relayhost destination, then you must use the same form in the smtp_sasl_password_maps file.

If this turns out to indeed be a problem with that password map, don't forget to update the indexed cache by issuing postmap /etc/postfix/smtp_password - and consider what should happen to the yet-to-be-delivered messages in your queue, you may want to update the affected recipients and senders through some other route than delivering (possibly a lot) non-delivery notifications.

anx
  • 6,875
  • 4
  • 22
  • 45