Mailscanner generated duplicate message.

[Glenn Steen]

On 23/12/2007, Mark Sapiro <mark at msapiro.net> wrote:
> CentOS 5
> Mailscanner 4.65.3
> Postfix 2.3.3
>
> This is a fairly new server install, running only a few weeks.
>
> Two days ago I received duplicate logwatch messages from the system.
> The duplication appears to be in Mailscanner. The headers of the two
> messages are identical and are:
>
> Return-Path: <root at sbh16.songbird.com>
> X-Original-To: root
> Delivered-To: root at sbh16.songbird.com
> Received: by sbh16.songbird.com (Postfix, from userid 0)
>         id 6325C6900A9; Fri, 21 Dec 2007 04:03:47 -0800 (PST)
> To: root at sbh16.songbird.com
> From: logwatch at sbh16.songbird.com
> Subject: Logwatch for sbh16.songbird.com (Linux)
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset="iso-8859-1"
> Message-Id: <20071221120349.6325C6900A9 at sbh16.songbird.com>
> Date: Fri, 21 Dec 2007 04:02:47 -0800 (PST)
>
>
> The relevant maillog entries are:
>
> Dec 21 04:03:49 sbh16 postfix/pickup[2954]: 6325C6900A9: uid=0
> from=<root>
> Dec 21 04:03:49 sbh16 postfix/cleanup[3448]: 6325C6900A9: hold: header
> Received:
>  by sbh16.songbird.com (Postfix, from userid 0)??id 6325C6900A9; Fri,
> 21 Dec 2007 04:03:47 -0800 (PST) from local;
> from=<root at sbh16.songbird.com>
> Dec 21 04:03:49 sbh16 postfix/cleanup[3448]: 6325C6900A9:
> message-id=<20071221120349.6325C6900A9 at sbh16.songbird.com>
> Dec 21 04:03:54 sbh16 MailScanner[2858]: New Batch: Scanning 1
> messages, 43244 bytes
> Dec 21 04:03:54 sbh16 MailScanner[2858]: Requeue: 6325C6900A9.B64EF to
> 7903D6900A4
> Dec 21 04:03:54 sbh16 postfix/qmgr[8765]: 7903D6900A4:
> from=<root at sbh16.songbird.com>,  size=43045, nrcpt=1 (queue active)
> Dec 21 04:03:54 sbh16 MailScanner[2858]: Unscanned: Delivered 1 messages
> Dec 21 04:03:54 sbh16 MailScanner[2858]: Virus and Content Scanning:
> Starting
> Dec 21 04:03:54 sbh16 MailScanner[2945]: New Batch: Scanning 1
> messages, 0 bytes
> Dec 21 04:03:56 sbh16 postfix/local[3483]: 7903D6900A4:
> to=<mark at sbh16.songbird.com>,  orig_to=<root>, relay=local, delay=70,
> delays=67/0.02/0/2.5, dsn=2.0.0, status=sent  (delivered to mailbox)
> Dec 21 04:03:57 sbh16 postfix/qmgr[8765]: 7903D6900A4: removed
> Dec 21 04:03:57 sbh16 MailScanner[2945]: Expired 2 records from the
> SpamAssassin cache
> Dec 21 04:03:57 sbh16 MailScanner[2945]: Requeue: 6325C6900A9.61B5E to
> 1E7946900A4
> Dec 21 04:03:57 sbh16 postfix/qmgr[8765]: 1E7946900A4:
> from=<root at sbh16.songbird.com>,  size=43045, nrcpt=1 (queue active)
> Dec 21 04:03:57 sbh16 MailScanner[2945]: Unscanned: Delivered 1 messages
> Dec 21 04:03:57 sbh16 MailScanner[2945]: Virus and Content Scanning:
> Starting
> Dec 21 04:03:57 sbh16 postfix/local[3483]: 1E7946900A4:
> to=<mark at sbh16.songbird.com>,  orig_to=<root>, relay=local, delay=71,
> delays=71/0/0/0.01, dsn=2.0.0, status=sent (delivered  to mailbox)
> Dec 21 04:03:57 sbh16 postfix/qmgr[8765]: 1E7946900A4: removed
>
>
> Note that the message was not actually scanned because
>
> Scan Messages = %rules-dir%/scan.messages.rules
>
> and the following is in %rules-dir%/scan.messages.rules
>
> From: 127.0.0.1 no
>
> It appears that the same incoming message was processed from the hold
> queue by two MailScanner children (pids 2858 and 2945).
>
> Perhaps I am missing some locking or other setting in my
> MailScanner.conf that is enabling a race condition.
>
> Can anyone help?
>
Um, I'm not entirely sure these are errors... Have you "massaged" the
logs in any way (excluding things you don't think relevant) in any
way?
Since PF can&will reuse queue IDs, that isn't much to go on... And one
wonders if there might've been a quick succession of
message-introduction (same message twice)...?

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