Questions[send](server)

I added two emails of our new members to a mailing list on our Debian/postfix machine (used just to send emails to our members). They complained about receiving hundreds of emails from our machine, and unfortunately it is true, I found another two users with different domain (we have ~10k members total without problems).

This is what I found in mail.log:

  1: Feb 23 06:25:24 m2 postfix/smtp[26117]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=71848, delays=71222/0.03/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
 15: Feb 23 06:30:23 m2 postfix/smtp[26224]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=77167, delays=76542/0.04/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
 53: Feb 23 06:50:24 m2 postfix/smtp[26943]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=76640, delays=76014/0.01/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
170: Feb 23 07:25:24 m2 postfix/smtp[27635]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=81552, delays=80927/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
244: Feb 23 07:45:23 m2 postfix/smtp[28025]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=76648, delays=76022/0.04/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
250: Feb 23 07:50:23 m2 postfix/smtp[28165]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=81967, delays=81342/0.01/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
306: Feb 23 08:10:24 m2 postfix/smtp[28558]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=81440, delays=80814/0.01/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
431: Feb 23 08:45:23 m2 postfix/smtp[29315]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=86352, delays=85726/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
467: Feb 23 09:05:23 m2 postfix/smtp[29745]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=81448, delays=80822/0.01/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
484: Feb 23 09:10:23 m2 postfix/smtp[29830]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=86768, delays=86142/0.01/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
553: Feb 23 09:30:24 m2 postfix/smtp[30267]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=86240, delays=85614/0.03/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
672: Feb 23 10:05:25 m2 postfix/smtp[30949]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=91154, delays=90527/0.02/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
731: Feb 23 10:25:24 m2 postfix/smtp[31385]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=86248, delays=85622/0.01/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
746: Feb 23 10:30:24 m2 postfix/smtp[31493]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=91568, delays=90943/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
817: Feb 23 10:50:24 m2 postfix/smtp[31933]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=91040, delays=90413/0.03/25/601, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
927: Feb 23 11:25:24 m2 postfix/smtp[32608]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=95953, delays=95327/0.01/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
997: Feb 23 11:45:23 m2 postfix/smtp[533]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=91048, delays=90422/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
1009: Feb 23 11:50:24 m2 postfix/smtp[675]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=96368, delays=95743/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
1080: Feb 23 12:10:23 m2 postfix/smtp[1086]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=95839, delays=95213/0.01/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
1177: Feb 23 12:45:24 m2 postfix/smtp[1790]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=100753, delays=100127/0.01/26/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
1229: Feb 23 13:05:24 m2 postfix/smtp[2209]: 38F5020EB4: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=95848, delays=95222/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
1251: Feb 23 13:10:24 m2 postfix/smtp[2302]: 3595420E53: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=101168, delays=100543/0.05/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)
1330: Feb 23 13:30:24 m2 postfix/smtp[2717]: C02C420E63: to=<[email protected]>, relay=mail.mailserver2.com[5.6.7.8]:25, delay=100640, delays=100014/0.04/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver2.com[5.6.7.8] timed out while sending end of data -- message may be sent more than once)
1410: Feb 23 14:05:23 m2 postfix/smtp[3399]: A1F4C20E26: to=<[email protected]>, relay=mail.mailserver1.com[1.2.3.4]:25, delay=105552, delays=104927/0.02/25/600, dsn=4.4.2, status=deferred (conversation with mail.mailserver1.com[1.2.3.4] timed out while sending end of data -- message may be sent more than once)

The server is re-sending the emails in an endless loop, spamming users every 1,5 hour, probably until maximal_queue_lifetime is reached. This is of course a huge problem for us, so I have a few questions here:

1, I don't think it is our postfix's problem, it is just 4 users (2 mailservers) of 10k. Anyway, has anyone seen this and is it possible to fix it? All I could find is info about old/bad cisco routers on recipients side, MTU problem and Packet fragmentation/FW problem somewhere on the way. I know this is probably a problem on the recipient server, but it is not under our possession, so no fixes are possible there.

2, Postfix knows the message is sent more than once, it even writes it in the log. How can I force postfix to not spam mailboxes and whenever it knows the message may be sent more then once, just consider it delivered and/or remove it from the queue. Just these, not all deferred. I don't care if some other emails would not be delivered because of this.

3, especially if (2) is not possible, is it possible to disable retries of deferred emails to a specific domain/mailserver?

Or is there any other thing to do to solve this?

thank you

Background

I've been the administrator since inception of this 24-ish year old site which hosts a lot of virtual domains, etc, and from the late '90s one important feature we had working was allowing IMAP clients to connect to both read and send from our mail server system. A key enabling feature was the pop-before-smtp option in Postfix.

The need for IMAP sends fell away with the financial crash of '08, but the need has come again, so, as administrator, I set about configuring the modern Postfix and Dovecot, of course on a modern Fedora Server (our long-chosen distribution) to do the job.

Configuring to have IMAP (IMAPS or POP3) reads was easy, but pop-before-smtp was neither rejected nor honored. Hmmm...

Configuring remote sends hasn't gone so well!

Troubles

As a guy with a long-grey-beard of experience, I did all the usual kinds of things looking for help, though I didn't do everything perfectly.

Along the way to this not-yet-solved problem, I figured out that THESE version(s) of Postfix and Dovecot don't work as advertised. In particular, we're running:

• Linux Fedora Server 5.7.16-200.fc32.x86_64
• postfix-3.5.4-2.fc32.x86_64
• dovecot-2.3.10.1-1.fc32.x86_64

With THIS set of versions, the settings for both Dovecot and Postfix didn't seem to honor the communication settings, shared by each, namely:

private/auth

Rather, things worked MUCH better, but still not fixed, with:

/var/spool/postfix/private/auth

When I say both, I mean the smtpd_sasl_path entry in Postfix's main.cf, and also Dovecot's /etc/dovecot/dovecot.d/10-master.conf file's entry for unix_listener, of course.

These entries point to a socket created by Dovecot, so Dovecot should be started first, though I haven't done any investigations into restart, or related issues. Simply, CONTRARY WITH OTHER DOCUMENTATION, THIS VERSION of Postfix WILL NOT receive inbound email if SASL auth is enabled and the smtpd_sasl_path doesn't already exist, as created by Dovecot.

I don't mean to overlook that several other Postfix parameters MUST be set for Postfix to receive emails under this scenario, such as smtpd_sasl_security_options and smtpd_sasl_tls_security_options. Without these, Postfix WILL NOT RECEIVE EMAILS if smtpd_sasl_auth_enable is set true.

To be completely clear, to cure this oversight, if you aren't able to receive email while trying to configure this, you simply MUST turn off Postfix's smtpd_sasl_auth_enable - that is, set it to false - or you will be unable to receive inbound emails, despite the available documentation's claims to the contrary. So, turn it off when you want to receive emails and back on again when you want to test.

However, even when you figure out how to get Dovecot to start enabling this service, as confirmed by the creation of /var/spool/postfix/private/auth, you can have smtpd_sasl_auth_enable set to true (along with other required sasl settings) and be able to receive emails, and still not be able to send via IMAP (imaps) clients.

As an aside I haven't taken the time to fully pursue, in my case, why or how the socket file created at /var/spool/postfix/private/auth was created as owned by root.root. After Postfix was up and receiving with sasl enabled, a chown postfix.postfix /var/spool/postfix/private/auth was required to fix that and I haven't taken the time to confirm this survives a reboot or even why it was wrong in the first place or if it fails if ownership is wrong! I'm just sharing my experience... ... It surely seems wrongly created to me.

YET, even in this instance, when Dovecot and Postfix agree on where and how to communicate via this socket file and email is received just fine, sends just do not work. That is, clients can connect and read their emails and do whatever else, but they cannot send, which all available documentation I've found so far leads one to believe the implementation of sasl done in this way is the key feature of the modern situation that permitted the deprecation and eventual removal of pop-before-smtp. What have I missed?

Before anyone asks, Postfix's /etc/postfix/master.cf's submission entry contains:

submission inet n       -       n       -       -       smtpd -o syslog_name=postfix/submission -o smtpd_tls_security_level=may -o smtpd_sasl_auth_enable=yes

(Perhaps there is an error there, but it's not clear to me.)

When trying to send, the /var/log/maillog presently (with the aforementioned configuration fully working) and persistently includes the following error for these remote-sending clients:

 400 4.5.2 Error: bad UTF-8 syntax

And, more rarely, this one:

 250-SMTPUTF8

I have never found any useful information about this error.

Any and all help appreciated.