Mailscanner generated duplicate message

[Cedric Devillers]

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

-- 
AmsterGroup
145 rue Barastraat B -1070 Brussels
T +32(0)2 556 28 11  
F +32(0)2 556 28 10
www.amstergroup.com