Mailscanner generated duplicate message

[Glenn Steen]

On 08/02/2008, Cedric Devillers <cde at alunys.com> wrote:
> Julian Field wrote:
> >
> >
> > 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
> >
>
> Hi Julian
>
> The problem is that when sending many messages from the mailscanner host
> (here via the sendmail command) and that this host is marked not to be
> scanned by mailscanner (via a ruleset for "Scan Messages"), some mails
> are duplicated by mailscanner.
>
> The ruleset in question is :
> From:   127.0.0.1       no
>
> It seems that when the server is under high load and/or the message sent
> is bigger, then the probability to have duplicates (sometimes 4 or 5 by
> messages) is higher. Note that this is only based on my impressions
> while trying to reproduce the problem :)
>
> I think the problem may be that in this particular case (locally sent
> messages, not to be scanned by mailscanner), the file locking is
> defective and multiple childs are reading the same postfix queue file.
> Note that i was not able to reproduce the problem with "Scan Messages =
> yes".
>
> You can have a look at this log extract that show duplicates for the ID
> 11D67CE47AC :
>
> Feb  8 19:44:21 mail postfix/pickup[20676]: 11D67CE47AC: uid=48
> from=<noreply at inforum.be>
> Feb  8 19:44:21 mail postfix/cleanup[20678]: 11D67CE47AC: hold: header
> Received: by mail.inforum.be (Postfix, from userid 48)??id 11D67CE47AC;
>  Fri,  8 Feb 2008 19:44:20 +0100 (CET) from local; from=<noreply at inforum.be>
> Feb  8 19:44:21 mail postfix/cleanup[20678]: 11D67CE47AC:
> message-id=<20080208184421.11D67CE47AC at mail.inforum.be>
> Feb  8 19:44:21 mail MailScanner[16229]: Requeue: 5B8AECE47A2.4FC7C to
> 08006CE47AB
> Feb  8 19:44:21 mail MailScanner[16229]: Requeue: 342ACCE47B0.545F4 to
> E8253CE47A2
> Feb  8 19:44:21 mail postfix/qmgr[19269]: 8382ECE473F:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail postfix/qmgr[19269]: E8253CE47A2:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail postfix/qmgr[19269]: 08006CE47AB:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail postfix/qmgr[19269]: 995D8CE47A5:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail MailScanner[16229]: Unscanned: Delivered 5 messages
> Feb  8 19:44:21 mail MailScanner[16229]: Virus and Content Scanning:
> Starting
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> 8F1BFCE47AC.62C1B to SQL
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> C4702CE473F.14646 to SQL
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> 05006CE47AB.74D14 to SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 8F1BFCE47AC.62C1B: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> 5B8AECE47A2.4FC7C to SQL
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> 342ACCE47B0.545F4 to SQL
> Feb  8 19:44:21 mail MailScanner[16596]: C4702CE473F.14646: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 05006CE47AB.74D14: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 5B8AECE47A2.4FC7C: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 342ACCE47B0.545F4: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16264]: New Batch: Forwarding 1
> unscanned messages, 23120 bytes
> Feb  8 19:44:21 mail postfix/pickup[20676]: 5B439CE47AF: uid=48
> from=<noreply at inforum.be>
> Feb  8 19:44:21 mail postfix/cleanup[20717]: 5B439CE47AF: hold: header
> Received: by mail.inforum.be (Postfix, from userid 48)??id 5B439CE47AF;
>  Fri,  8 Feb 2008 19:44:21 +0100 (CET) from local; from=<noreply at inforum.be>
> Feb  8 19:44:21 mail postfix/cleanup[20717]: 5B439CE47AF:
> message-id=<20080208184421.5B439CE47AF at mail.inforum.be>
> Feb  8 19:44:21 mail MailScanner[16264]: Requeue: 11D67CE47AC.DC14A to
> B0A22CE47B7
> Feb  8 19:44:21 mail MailScanner[16264]: Unscanned: Delivered 1 messages
> Feb  8 19:44:21 mail MailScanner[16264]: Virus and Content Scanning:
> Starting
> Feb  8 19:44:21 mail MailScanner[16229]: New Batch: Forwarding 1
> unscanned messages, 0 bytes
> Feb  8 19:44:21 mail postfix/qmgr[19269]: B0A22CE47B7:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail MailScanner[16229]: Requeue: 11D67CE47AC.3898C to
> 084DCCE47BA
> Feb  8 19:44:21 mail postfix/qmgr[19269]: 084DCCE47BA:
> from=<noreply at inforum.be>, size=22977, nrcpt=1 (queue active)
> Feb  8 19:44:21 mail MailScanner[16229]: Unscanned: Delivered 1 messages
> Feb  8 19:44:21 mail MailScanner[16229]: Virus and Content Scanning:
> Starting
> Feb  8 19:44:21 mail MailScanner[16264]: Logging message
> 11D67CE47AC.DC14A to SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 11D67CE47AC.DC14A: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail MailScanner[16229]: Logging message
> 11D67CE47AC.3898C to SQL
> Feb  8 19:44:21 mail MailScanner[16596]: 11D67CE47AC.3898C: Logged to
> MailWatch SQL
> Feb  8 19:44:21 mail postfix/smtp[20778]: 9EDC5CE47B2:
> to=<cde at alunys.com>, relay=mail.alunys.com[212.35.119.247], delay=2,
> status=sent (250 O
>
Thanks Cedric, this, and the child thing suggested by alex,
corroborate the theory of what is going bad, limiting what need be
scrutinized.... which is a good thing:-). Still,I've been looking and
can't for the life of me see where it goes haywire....:-/
Hopefully Jules (or Phil... or me a bit more sober...:-) will find something.

Cheers
-- 
-- Glenn
email: glenn < dot > steen < at > gmail < dot > com
work: glenn < dot > steen < at > ap1 < dot > se