0

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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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=<mail4@domain2.com>, 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=<mail1@domain1.com>, 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=<mail3@domain2.com>, 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=<mail2@domain1.com>, 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

xtc
  • 19
  • 1
  • 6
  • It's a virtual certainty that these are not the only duplicate mails that people at those recipient domains receive. You may wish to alert the postmaster at those domains; it's quite possible that affected users would not have reported the problem to them. – Michael Hampton Feb 25 '21 at 01:10

2 Answers2

0

Regarding your second and third questions, I think you can adapt the following parameters, so that your maximal_queue_lifetime is let say 1 hour and withing this 1 hour, you can do 4 attempts(1 each 15 minutes). This should drastically reduce the amount of emails being sent.

maximal_queue_lifetime =
maximal_backoff_time = 
minimal_backoff_time =
queue_run_delay =

maximal_queue_lifetime (default: 5d)

Consider a message as undeliverable, when delivery fails with a temporary error, and the time in the queue has reached the maximal_queue_lifetime limit.

Time units: s (seconds), m (minutes), h (hours), d (days), w (weeks). The default time unit is d (days).

Specify 0 when mail delivery should be tried only once.

More info at: http://www.postfix.org/postconf.5.html

Another option would be to periodically delete the deferred queue using the postsuper command. You can configure this as a cronjob:

*/5 * * * * postsuper -d ALL deferred

You can check the postsuper man page here: http://www.postfix.org/postsuper.1.html

-d queue_id Delete one message with the named queue ID from the named mail queue(s) (default: hold, incoming, active and deferred).

          To  delete multiple files, specify the -d option multiple times,
          or specify a queue_id of -  to  read  queue  IDs  from  standard
          input.  For example, to delete all mail with exactly one recipi-
          ent user@example.com:

          postqueue -j | jq '
              # See JSON OBJECT FORMAT section in the postqueue(1) manpage
              select(.recipients[0].address == "user@example.com")
              | select(.recipients[1].address == null)
              | .queue_id
           ' | postsuper -d -

          Or the historical form:

          mailq | tail -n +2 | grep -v '^ *(' | awk  'BEGIN { RS = "" }
              # $7=sender, $8=recipient1, $9=recipient2
              { if ($8 == "user@example.com" && $9 == "")
                    print $1 }
           ' | tr -d '*!' | postsuper -d -

          Specify "-d ALL" to remove all messages;  for  example,  specify
          "-d  ALL deferred" to delete all mail in the deferred queue.  As
          a safety measure, the word ALL must be specified in upper  case.

Of course, 2) and 3) are just workaround and can and most probably would affect other users of your Postfix servers. There will be situations where mail is deferred for a good reason and should stay in the queue longer or it should not be deleted.

basekat
  • 456
  • 2
  • 5
  • thanks basekat. I want to avoid changing global parameters for queue & deferred emails if possible. It affects graylisting, various stupid limits for amount of emails etc, where it is good to keep mail in the queue, so I'd like to keep the queue alive if possible. And I definitely don't want to send the problem emails 4x either. – xtc Mar 01 '21 at 15:39
  • What I'd like to achieve - postfix knows what emails are being sent repeatedly, it even warns in the logs but still sends it - is there any way to delete these, not all deferred mail for whatever reason? I don't care if those emails would not be delivered at all after the first try. – xtc Mar 01 '21 at 15:44
0

I've seen the same problem and traced it to an overeager firewall that dropped the last few bytes of a connection if those bytes were sent immediately before closing the connection.

Postfix acting as an SMTP client sent CRLF.CRLF to end the message, and if SMTP pipelining was enabled, it also sent QUIT and waited for two command responses. The SMTP server processed the message, processed the QUIT, sent two command responses and immediately closed the connection. The firewall dropped the two command responses, so Postfix noticed only the connection being closed, and was legitimately uncertain about whether the message had been handed over correctly.

smtp_discard_ehlo_keywords = pipelining works around it by making Postfix delay after CRLF.CRLF. The response to QUIT is still lost, but that has no ill effects.

arnt
  • 121
  • 4