Mailscanner generated duplicate message.

[Mark Sapiro]

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?

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan