Mailscanner generated duplicate message
Julian Field
MailScanner at ecs.soton.ac.uk
Wed Feb 13 22:54:19 GMT 2008
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
I have just release a new beta 4.67.4 to attempt to fix this problem.
It's very awkward to find, as it only occurs on busy systems. I have
found a possible reason and have fixed that.
Please can you give this new version a try and let me know if it helps
solve the duplication problem at all.
Thanks folks!
Jules.
Glenn Steen wrote:
> 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
>
Jules
- --
Julian Field MEng CITP CEng
www.MailScanner.info
Buy the MailScanner book at www.MailScanner.info/store
MailScanner customisation, or any advanced system administration help?
Contact me at Jules at Jules.FM
PGP footprint: EE81 D763 3DB0 0BFD E1DC 7222 11F6 5947 1415 B654
PGP public key: http://www.jules.fm/julesfm.asc
-----BEGIN PGP SIGNATURE-----
Version: PGP Desktop 9.8.0 (Build 2158)
Comment: Use Thunderbird Enigmail to verify this message
Charset: ISO-8859-1
wj8DBQFHs3UoEfZZRxQVtlQRAlg/AJ0cUHoD3g+yvdoDdCtvLjbAU5z/9wCeJ1aE
3zdYbrt+f44K0D/wPXq6l08=
=Rdy4
-----END PGP SIGNATURE-----
--
This message has been scanned for viruses and
dangerous content by MailScanner, and is
believed to be clean.
More information about the MailScanner
mailing list