tickets #51092
closedtemporarily undeliverable mails (status 4xx) cause mlmmj "bouncing messages" notification
100%
Description
My mailserver was broken for some hours while the RAID was recovering from a disk replacement (the full story was more interesting[tm], but is OT here). In this time, mail delivery attemps resulted in a 4xx tempfail (logs from anna.infra.o.o):
2019-05-05T00:16:00.470483+00:00 anna postfix/qmgr[12882]: CBAB721F5E:
from=<opensuse-de+bounces-105611-suse=cboltz.de@opensuse.org>, size=15507, nrcpt=1 (queue active)
2019-05-05T00:16:01.876935+00:00 anna postfix/smtp[30737]: CBAB721F5E:
host mail.cboltz.de[88.99.101.17] said: 451 4.3.5 <suse@cboltz.de>: Recipient address rejected: Server configuration problem (in reply to RCPT TO command)
2019-05-05T00:16:02.897444+00:00 anna postfix/smtp[30737]: CBAB721F5E:
to=<suse@cboltz.de>, relay=faulpelz.cboltz.de[88.99.101.17]:25, delay=10743, delays=10741/0.39/1/1, dsn=4.3.5, status=deferred (host faulpelz.cboltz.de[88.99.101.17] said:
451 4.3.5 <suse@cboltz.de>: Recipient address rejected: Server configuration problem (in reply to RCPT TO command))
Some hours later, my mailserver was back and the mail finally delivered.
Interestingly, I got a "bouncing messages" mail from mlmmj listing this mail as "bounced message" while it was "only" delayed.
It would be a good idea if mlmmj would only honor 5xx rejects, not 4xx tempfails.
An alternative might be to change delay_warning_time = 1h on anna to a higher value so that mlmmj doesn't get too many delay notifications.
Files
Updated by pjessen almost 5 years ago
mlmmj would only report "bouncing messages" if a message had actually bounced :-) While your mailserver was in trouble, any list messages would have been queueing on anna, maybe anna decided to bounce something? Your log snippet shows a message being deferred, not bounced.
An alternative might be to change delay_warning_time = 1h on anna to a higher value so that mlmmj doesn't get too many delay notifications.
anna is used for other relaying isn't it? "0h" would disable it. I don't think mlmmj cares about those notifications anyway.
Updated by pjessen almost 5 years ago
Since midnight, anna sent out 73 delay notificaitons - I see some for your address, some for others. mlmmj just ignores them.
Updated by cboltz almost 5 years ago
- File CBAB721F5E.log CBAB721F5E.log added
Since midnight, anna sent out 73 delay notificaitons - I see some for your address, some for others. mlmmj just ignores them.
I'm afraid reality disagrees ;-)
I got "Bouncing messages" notifications for several mailinglists, including one for opensuse-de 105611 which is the one from the log lines I quoted. The notification was sent at 2:00 CEST, and another one at 14:00 CEST (I'd guess the first notification was also delayed and caused another "delay warning" from anna to baloo). Needless to say that the notification says "Some messages to you could not be delivered. [...] Here is the list of the bounced messages:"
If you check the logs for CBAB721F5E, you'll see that it was delayed for hours (my mailserver was down/broken the whole night) with a 4xx tempfail, and then finally delivered after my server came back to work. You will not find a 5xx reject for it. (The grep result for CBAB721F5E and the delay warning F2F401F9C1 is attached.)
I can provide the mail numbers from the other mailinglists where I got mlmmj "Bouncing messages" notifications, but I'm quite sure the log lines for them will tell you the same story.
My guess is that:
- mlmmj sends the mail to anna, envelope sender opensuse-de+bounces-105611-suse=cboltz.de@opensuse.org
- anna gets a 4xx tempfail (or connection refused, which is also a tempfail)
- after an hour, anna sends a "delay warning" message to opensuse-de+bounces-105611-suse=cboltz.de@opensuse.org which gets routed to mlmmj
- mlmmj receives the "delay warning" mail at the bounce address and thinks it was bounced (actually I'd be surprised if mlmmj would parse the mail content)
- mlmmj sends out the "Bouncing messages" notification
Regarding change delay_warning_time - 0h (= disabling) doesn't sound like a good idea, but increasing it might be a good idea. The alternative is to let baloo send out the mails directly, but that's another can of worms ;-)
Updated by pjessen almost 5 years ago
cboltz wrote:
Since midnight, anna sent out 73 delay notificaitons - I see some for your address, some for others. mlmmj just ignores them.
I'm afraid reality disagrees ;-)
Hmm, they are processed by mlmmj-receive, but there are no log entries (mlmml.operation.log). Still, you're right, reality disagrees.
I guess I was too optimistic that mlmmj would understand :-(
My guess is that:
- mlmmj sends the mail to anna, envelope sender opensuse-de+bounces-105611-suse=cboltz.de@opensuse.org
- anna gets a 4xx tempfail (or connection refused, which is also a tempfail)
- after an hour, anna sends a "delay warning" message to opensuse-de+bounces-105611-suse=cboltz.de@opensuse.org which gets routed to mlmmj
- mlmmj receives the "delay warning" mail at the bounce address and thinks it was bounced (actually I'd be surprised if mlmmj would parse the mail content)
- mlmmj sends out the "Bouncing messages" notification
That is exactly what happens, yes.
Regarding
change delay_warning_time-0h(= disabling) doesn't sound like a good idea, but increasing it might be a good idea. The alternative is to let baloo send out the mails directly, but that's another can of worms ;-)
I wonder if there might be a way of disabling the delay warning selectively. Or throwing it way.
Updated by pjessen almost 5 years ago
pjessen wrote:
I wonder if there might be a way of disabling the delay warning selectively. Or throwing it way.
I'm trying out a header check on baloo - only logging a warning sofar:
/THIS IS A WARNING ONLY. YOU DO NOT NEED TO RESEND YOUR MESSAGE/ warn klop99
With this we could just discard those delay warnings. Of course, any posting actually containing that text would also be discarded.
Updated by pjessen almost 5 years ago
- Due date set to 2019-11-01
The header check went into /etc/postfix/mlmmj-killfile - I see no hits in the last month. I have changed the warning text to "progress.opensuse.org/issues/51092" and I'll add a cronjob to scan for such warnings once a month. The report will only go to my own address.
Updated by cboltz almost 5 years ago
I subscribed to opensuse-test@o.o as opensuse-test-blocked AT cboltz.de and adjusted my postfix config so that this address always says "450 intentionally delayed - poo#51092".
I also sent a mail to opensuse-test@o.o 5 minutes ago, so that you should see something[tm] in the log soon ;-)
(I'll disable the "450" tomorrow evening so that the mail can be delivered.)
BTW:
I'm trying out a header check on baloo - only logging a warning sofar:
/THIS IS A WARNING ONLY. YOU DO NOT NEED TO RESEND YOUR MESSAGE/ warn klop99
Should this really be a header check? The text looks more like text from the mail body...
Updated by cboltz almost 5 years ago
I removed the "450" blocking again, and as expected, I got "Bouncing messages from opensuse-test@opensuse.org" notifications - one with timestamp 2:00 CEST, one with timestamp 14:00 CEST.
First log entry for each envelope sender on my server (times are CEST, I removed my mail address for spam protection)
Jul 6 22:17:41 server postfix/smtpd[22497]: NOQUEUE: reject: RCPT from proxy-nue1.opensuse.org[195.135.221.145]: 450 4.7.1 <...>: Recipient address rejected: intentionally delayed - poo#51092; from=<opensuse-test+bounces-189-opensuse-test-blocked=cboltz.de@opensuse.org> [...]
Jul 7 02:00:04 server postfix/smtpd[24484]: NOQUEUE: reject: RCPT from proxy-nue1.opensuse.org[195.135.221.145]: 450 4.7.1 <...>: Recipient address rejected: intentionally delayed - poo#51092; from=<opensuse-test+bounces-probe-opensuse-test-blocked=cboltz.de@opensuse.org> [...]
Jul 7 14:00:04 server postfix/smtpd[17659]: NOQUEUE: reject: RCPT from proxy-nue1.opensuse.org[195.135.221.145]: 450 4.7.1 <...>: Recipient address rejected: intentionally delayed - poo#51092; from=<opensuse-test+bounces-probe-opensuse-test-blocked=cboltz.de@opensuse.org> [...]
The first one is the actual ML mail, the other two are the "Bouncing messages" notifications.
If you want to do more tests, I can switch on the "450" rejects for that address again.
Updated by pjessen almost 5 years ago
Should this really be a header check? The text looks more like text from the mail body...
No, it probably ought to be a body check, but we don't currently use any. I thought trying with the killfile was worth testing.
I'm moving the check to a body_check, still with a warning.
Updated by pjessen almost 5 years ago
cboltz wrote:
If you want to do more tests, I can switch on the "450" rejects for that address again.
Yes please switch it on again.
Updated by cboltz almost 5 years ago
pjessen wrote:
cboltz wrote:
If you want to do more tests, I can switch on the "450" rejects for that address again.
Yes please switch it on again.
Done, you'll get "450" rejects again.
Updated by cboltz over 4 years ago
FYI: delayed mails still cause "bouncing messages" warning mails, in my case for some opensuse-security-announce mails.
First delivery attempt: (mail-20190925.xz on anna)
2019-09-24T13:47:24.963808+00:00 anna postfix/smtp[5415]: DFA45226BA: to=<christianboltz@web.de>, relay=mx-ha02.web.de[212.227.17.8]:25, delay=0.05, delays=0.01/0/0.04/0, dsn=4.0.0, status=deferred (host mx-ha02.web.de[212.227.17.8] refused to talk to me: 421-web.de (mxweb113) Nemesis ESMTP Service not available 421-Service unavailable 421-Reject due to policy restrictions. 421 For explanation visit http://postmaster.web.de/error-messages??ip=195.135.221.145&c=irlims)
3 hours (and some delivery attempts) later, the mail was accepted by web.de:
2019-09-24T16:15:57.223381+00:00 anna postfix/smtp[19221]: DFA45226BA: to=<christianboltz@web.de>, relay=mx-ha03.web.de[212.227.15.17]:25, conn_use=7, delay=8912, delays=8911/1.3/0.01/0.05, dsn=2.0.0, status=sent (250 Requested mail action okay, completed: id=1MTh17-1icLdQ0ke5-00U5qP)
Updated by pjessen over 4 years ago
- Status changed from New to In Progress
Sorry, I forgot about this one - I don't think I ever got my own log analysis mail. The messages are clearly being found, I have updated the warning to a discard.
Updated by pjessen over 4 years ago
- Status changed from In Progress to Resolved
- % Done changed from 0 to 100
This is now working.