Home / server / Questions / 1054959
In Process
xtc
Asked: 2021-02-25 16:39:00 +0800 CST

postfix repeatedly sending emails - message may be sent more than once

  • 772

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

postfix send

1 Answers

  1. 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 [email protected]:

          postqueue -j | jq '
              # See JSON OBJECT FORMAT section in the postqueue(1) manpage
              select(.recipients[0].address == "[email protected]")
              | 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 == "[email protected]" && $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.

    • 0