Mailscanner generated duplicate message

[Glenn Steen]

On 08/02/2008, Julian Field <MailScanner at ecs.soton.ac.uk> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
>
>
> Glenn Steen wrote:
> > On 08/02/2008, Glenn Steen <glenn.steen at gmail.com> wrote:
> >
> >> On 08/02/2008, Glenn Steen <glenn.steen at gmail.com> wrote:
> >>
> >>> On 07/02/2008, Cedric Devillers <cde at alunys.com> wrote:
> >>>
> >>>> Hello,
> >>>>
> >>>> I'm trying to revive this thread from the last month because we are
> >>>> observing the exact same behavior on one of our servers.
> >>>>
> >>> Thanks for doing that, and for providing some more info.
> >>>
> >>>
> >>>> So to remember the facts :
> >>>>
> >>>> - We are using mailscanner with postfix, and duplicated messages are
> >>>> generated by mailscanner.
> >>>>
> >>>> - This system is the only one where we are observing this behavior. It
> >>>> have a little particularity : it mainly act as a mail relay, but
> >>>> sometimes many mails are generated by the server itself (a script) and
> >>>> injected in postfix queues via sendmail command. We can always reproduce
> >>>> some duplicated messages with this script.
> >>>>
> >>>> - MailScanner is configured (by ruleset) to bypass scanning for thoses
> >>>> messages, but they are still entering the mailscanner logic (postix ->
> >>>> hold queue -> mailscanner (no scan) -> active queue).
> >>>>
> >>> What does the ruleset look like? I'm sure it doesn't matter, but ...
> >>> just out of curiosity:-)...
> >>>
> >>>
> >>>> - Mailwatch is running on this server, and for each duplicates we see
> >>>> entries with null size body (2, 3, 4, sometimes 5) then at last a final
> >>>> entry with the full body. Note that the recipient see the full body on
> >>>> every duplicate.
> >>>>
> >>>> It looks like a locking problem, because all duplicates are with the
> >>>> same postfix queue ID and different entropy part (ID.xxxx, ID.yyyy,
> >>>> ID.zzzz, etc). Can it be possible that a mailscanner child "fail" to
> >>>> lock some queue file when message is marked not to be scanned by
> >>>> mailscanner ?
> >>>>
> >>> Yes, this seems plausible... Could you provide some log examples? Just
> >>> to see that it really is separate children reading the same queue
> >>> file...
> >>>
> >>>
> >>>
> >>>> I will not be very helpfull to debug perl code, but i can provide any
> >>>> needed logs to help finding the origin of the problem.
> >>>>
> >>> I'll see what I can do, but... I think this isn't "my" code snippets,
> >>> but a thing that might have been present for a while... And I have a
> >>> serious lack of time to spend on this ATM (worse than last time,
> >>> before Xmas)... So no promises:-).
> >>>
> >>>
> >>>> This is really a serious problem in this particular installation. But i
> >>>> must say that we have dozens of other servers that are running
> >>>> mailscanner/postfix, and we are very happy about thems :)
> >>>>
> >>> Does it help if you DO scan with MS, but skip things at the next
> >>> level, for example:
> >>> Scan Messages = yes
> >>> Use SpamAssassin = no
> >>> Dangerous Content Scanning = no
> >>> ... and possibly a few more (do them with a ruleset, of course:-)?
> >>>
> >>>
> >> BTW, do you have any milters enabled in Postfix? What version of Postfix?
> >>
> >> Cheers
> >>
> >
> > I think we need Jules on this one, not only feeble lil' me:-).
> > AFAICS, the locking/unlocking is handled _exactly_ the same regardless
> > of the scanmail setting... But then, this is a rather complex bit of
> > code, where the "execution path" isn't always as straightforward as it
> > seems... Jules, could you spare a moment or two? Just to look at what
> > could possibly be wrong with the message->scanmail = 0 scenario?
> >
> >
> Can you *briefly* explain what the problem is, what the symptoms are and
> where you think the problem might lie? This is a very long thread.... :-)
>
> Jules
>
In short:
When using Postfix and setting Scan Messages = no (with a rulset, for
some....), duplicates are "generated" by several MailScanner children
picking up and delivering the same message. It seems to be something
to do with timing, since not all generate this behavior, but rather
under heavy load (as in situations where some form of mailing list or
bulk mailer (presumably a legit newsletter) send large amounts of
messages at once).
Indications (so far) that it really is several children is that the
log entries (the few we've seen) have been during the same few
seconds, the "base queue ID" is the same, the entropy bits have
differed, as has the PIDs.
So far we've only seen reports of this for Postfix, which is why I've
looked through my changes for p record handling (again)... AFAICS,
those couldn't possibly have anything to do with this, since they
behave exactly the same regardless of whether scanmail is set to 1 or
0... Which would lead to duplicates in the normal case too, if that
was at the heart of it.

Hope that was short enough...:-)

Cheers (yeah, still tipsy...:-)
-- 
-- Glenn
email: glenn < dot > steen < at > gmail < dot > com
work: glenn < dot > steen < at > ap1 < dot > se