[Mailman-Users] spam coming through a moderated list after a shunt

[Mark Sapiro]

On 11/22/15 10:22 AM, Fil wrote:

> (sorry for the initial message with wrong subject line)

Copying my reply in the new subject thread ...


On 11/22/15 9:49 AM, Fil wrote:
> Hello,
>
> a spam went through a moderated list today, and the story is weird. Here's
> what I understand/ (mailman version 2.1.20)


Is there a question in this or is it just an informational report?


> First, the message was received and rejected by the list moderators
>
> logs/vette.log:Nov 22 14:56:45 2015 (10257) Message rejected, msgid: <
> 20151122135632.C128E412040 at mst135.mdreg-mstnew.qlc.co.in>


This is not a moderator reject. This message was logged by
IncomingRunner after some handler in the pipeline raised
Errors.RejectMessage. This could have happened for example because it
was a non-member post and the list is configured to reject a non-member
post.

In 2.1.20, there should be another 3 lines in this log message giving
the list name, the handler and  the reject reason.


> Then, the (rejected!) message was sent to the list members;
>
>
> logs/post.log:Nov 22 17:05:41 2015 (15369) post to spip-ann from
> mails at clovertourism.com, size=4374, message-id=<
> 20151122135632.C128E412040 at mst135.mdreg-mstnew.qlc.co.in>, success
> logs/smtp.log:Nov 22 17:05:41 2015 (15369) <
> 20151122135632.C128E412040 at mst135.mdreg-mstnew.qlc.co.in> smtp to spip-ann
> for 2880 recips, completed in 2.228 seconds
>
>
> The "reason" why this went through at 17+ is that I have a cron job that
> tries to unshunt messages each day at that hour. So the (discarded then
> shunted) message was unshunt and sent to the list.
>
> logs/error.log:Nov 22 14:56:44 2015 (10257) IOError reading list
extension:
> [Errno 12] Cannot allocate memory:
> '/var/local/mailman/lists/spip-ann/extend.py'
> logs/error.log:Nov 22 14:56:45 2015 (10257) Uncaught runner exception:
> [Errno 12] Cannot allocate memory: '/var/local/mailman/qfiles/virgin'
> logs/error.log:Nov 22 14:56:45 2015 (10257) Traceback (most recent call
> last):
> logs/error.log:Nov 22 14:56:45 2015 (10257) SHUNTING:
> 1448200600.413774+c9883eaaeaec5a744cfe6a49237d51c2c0373b98>


So a handler said to reject the message. The reject was logged and then
the BounceMessage method was called to send a reject notice. The
BounceMessage method encountered the above exception when trying to
queue the reject notice in the virgin queue, and because of this
exception, the original message was shunted.

Unfortunately, when the message is shunted, the handler that rejected
the message has already been popped from the pipeline so the unshunted
message begins processing with the subsequent handler and is not rejected.

I have a few observations.

1) The skipping of the handler throwing the exception upon unshunting
seems to be a bug.

2) Rejecting rather than discarding unwanted posts produces backscatter
and is not a good idea in general.

3) Normally, I think it is rare that unshunting a shunted post without
analyzing and fixing the underlying exception will succeed. In any case,
blindly running unshunt via cron is probably not a good idea. Is there
some unusual situation that makes you want to do this?

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan