[Mailman-Users] stuck bounce-events write

[Richard Haas]

On Tue, Nov 22, 2011 at 2:54 AM, Mark Sapiro <mark at msapiro.net> wrote:

> Richard Haas wrote:
> >
> >Last week, we ran into a rather odd event (first time we've seen it in a
> >decade or so of Mailman ops), where a bounced message kept writing to its
> >/var/mailman/data/bounce-events-PID.pck file, until it filled the disk
> [...]
> >The first bounce seemed normal:
> >
> >Delivery failed for the following reason:
> >Server entsrmbx01.teledyne.com[74.201.16.49] failed with: 550 #5.1.0
> >Address rejected <someone>@teledyne.com
> >This has been a permanent failure.  No further delivery attempts will be
> >made.
> >
> >
> >... and then the first bounce was written to the
> >/var/mailman/data/bounce-events pck file at:
> >
> >Received from localhost (localhost [127.0.0.1])
> >       by [myserver] (Postfix) with ESMTP id 3272D601E21
> >       for <[somelist]-news-bounces at myserver>; Wed, 16 Nov 2011 16:41:55
> >-0500 (EST)
> >
> >
> >... but was written another 5000 times with it's PDF attachment.
> >
> >... at 17:43 local, the disk filled with:
> >
> >Nov 16 17:43:13 [hostname] postfix/smtpd[27239]: NOQUEUE: reject: MAIL
> from
> >localhost[127.0.0.1]: 452 4.3.1 Insufficient system storage; proto=ESMTP
> >helo=<localhost>
> >Nov 16 17:43:13 [hostname] postfix/smtpd[27239]: warning: not enough free
> >space in mail queue: 36216832 bytes < 1.5*message size limit
>
>
> So is it Postfix that is repeatedly delivering this bounce message to
> Mailman, and Mailman is just trying to deal with it? If so, the
> underlying issue is with Postfix, not Mailman.
>
>
There's nothing in mail.log for 127.0.0.1 deliveries related to this list,
during the timeframe, except clean passes through amavis. Certainly no 5000
redeliveries.

There is normal traffic sending the message outbound to the 130 or so list
members, with about 20 bounces.

The original address that led to the bounce was accepted outbound for
delivery, and then came back about 17 seconds later, after remote
translation of

<someoneelse>@someresearch.com to <someone>@telecdyne.com

... but cam back only once at:

Nov 16 16:41:55 myhost amavis[26807]: (26807-14) Passed CLEAN,
[66.18.18.67] [66.18.18.67] <> -> <mylist-news-bounces at my.org>, Message-ID:
<20111116214143.10704.6534 at hm-mx2b.solinus.com>, mail_id: PvH5EnpUQiLg,
Hits: -, size: 7808036, queued_as: 3272D601E21, 677 ms

... which was when the first bounce was written to the bounce-events file.

Anyhow, it doesn't look like Postfix processed the bounce 5000 times, and
was repeatedly handing it back to BounceRunner.


> >Oddly, the bounce-events file's last write was considerably earlier:
> >
> >-rw-rw-r-- 1 mailman mailman 37867700224 2011-11-16 16:52
> >bounce-events-01556.pck
>
>
> This is an orphaned bounce-events file that was left behind when
> BounceRunner PID 1556 died - see below.
>
>
> >The only questionable log entries I can find after/around the message
> >posting is for an abort of the Archrunner and Bouncerunner before the disk
> >filled:
> >
> >Nov 16 17:06:08 2011 (1533) Master qrunner detected subprocess exit
> >(pid: 1555, sig: 9, sts: None, class: ArchRunner, slice: 1/1) [restarting]
> >Nov 16 17:06:14 2011 (27568) ArchRunner qrunner started.
> >Nov 16 17:06:18 2011 (1533) Master qrunner detected subprocess exit
> >(pid: 1556, sig: 9, sts: None, class: BounceRunner, slice: 1/1)
> [restarting]
> >Nov 16 17:06:20 2011 (27573) BounceRunner qrunner started.
>
>
> BounceRunner PID 1556 died at 17:06 possibly while processing the
> bounces in qfiles/bounces or while processing the bounce-events file.
> This is within the normal 15 minute window for processing
> bounce-events.
>
> Where there any error log entries associated with the deaths of
> BounceRunner or ArchRunner?
>
>
No, other than the sig 9(s) above, there's nothing in the qrunner logs
since 6:33 that morning, and afterwards (18:43) when admins did a halt on
mailman and postfix before moving the 37 GB bounce-events-01556.pck file to
another filesystem.


>
> >Since the [somelist]-news list in question doesn't have archiving enabled
> >(never has), so I the ArchRunner restart. There were no other qrunner
> >restarts since 6:33 that morning, and the only later ones were when admin
> >staff went in to clear things up.
> >
> >So chronologically:
> >
> >- 16:41 first bounce occurs and is written to bounce-events by PID 1556
> >- 16:52 PID 1556 makes (according to the file system) its last write to
> >bounce-events-1556.pck
> >- 17:02 ArchRunner and BounceRunner get restart signals, PID 27573 is the
> >new BounceRunner
> >- 17:43 the disk fills to the point postfix starts complaining
> >
> >
> >... that doesn't add up unless one presumes PID 1556 hung around and kept
> >writing bounce-events-1556.pck from 17:02 to 17:43 (and probably beyond).
>
>
> PID 1556 was gone at 17:06:18. It is not clear whether the repeated
> bounce events were due to BounceRunner in some kind of loop or
> BounceRunner actually receiving bounces from Postfix.
>
>
Since there's nothing to indicate postfix was repeatedly passing the
bounce, I think we're stuck looking at the BounceRunner.


> Are there Postfix log entries for the delivery of 5000 bounces to
> Mailman? If so, it would seem Postfix is the culprit. If not, then it
> would seem to be BounceRunner. I don't have a clue as to why
> BounceRunner would do this.
>
>
Well, that's where we were as well -- no explanation. Something works
flawlessly for 10 years, then goes wacky one time.

One admin here posited that there was a disk write error on the physical
hardware used by the virtualized host, which caused a reattempt for the
write ... unfortunately, there are no log entries for the OS for disk
errors, or in the hypervisor to support that theory either. :-/ So we're
back to gremlins.

Thanks for the consultation -- we're are least sure that we hadn't
overlooked something obvious. That helps.

Great software, this Mailman thing ... its quality makes our service
possible. Thanks again.

... now if pipermail could assemble the individual HTML links for each
message in the archives dynamically from the mbox files, keeping just the
topmost month/quarter/year links on disk, instead of using all that disk
space for individual article links to files so rarely accessed -- life
would be perfect.  But that's not a Mailman issue. ;-)


Richard
rhaas at rhaas.us