Mailscanner generated duplicate message.

[Glenn Steen]

On 23/12/2007, Mark Sapiro <mark at msapiro.net> wrote:
> Glenn Steen wrote:
>
> >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
>
> <snip>
> >>
> >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?
>
>
> Yes, I removed one entry from the above sequence having to do with an
> unrelated message
>
> Dec 21 04:03:50 sbh16 postfix/smtpd[3017]: disconnect from
> dsl-207-112-4-156.tor.primus.ca[207.112.4.156]
>
> The two prior entries for that message were
>
> Dec 21 04:03:47 sbh16 postfix/smtpd[3017]: connect from
> dsl-207-112-4-156.tor.primus.ca[207.112.4.156]
> Dec 21 04:03:49 sbh16 postfix/smtpd[3017]: NOQUEUE: reject: RCPT from
> dsl-207-112-4-156.tor.primus.ca[207.112.4.156]: 550 5.1.1
> <st at grizz.org>: Recipient address rejected: User unknown in virtual
> alias table; from=<honeymoonersd4 at collectablerecords.net>
> to=<st at grizz.org> proto=ESMTP helo=<dsl-207-112-4-156.tor.primus.ca>
>
Ok, not what I'd hoped for ....:-)

> >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)...?
>
>
> The previous introduction of a message from root was 24 hours earlier
>
> Dec 20 04:03:18 sbh16 postfix/cleanup[7992]: 463B46900A4: hold: header
> Received: by sbh16.songbird.com (Postfix, from userid 0)??id
> 463B46900A4; Thu, 20 Dec 2007 04:03:17 -0800 (PST) from local;
> from=<root at sbh16.songbird.com>.
>
Hm. Not good. The thing is that a message already picked up by one
child shouldn't be able to be processed by another... Might mean I
need to go over this (again) to see that any of the changes to support
the latest versions of PF hasn't broken the base assumptions. Sigh.
How often do you see this (needless to say, I've not seen this/had any
reports of duplicates from my rather picky users...), or is it this
one instance? One should be able to do some log massaging to find
this...

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