double messages?

Jay Kusler kusler at NSCL.MSU.EDU
Wed Jun 11 21:27:35 IST 2003

On Wed, 11 Jun 2003 16:03:57 +0100, Spicer, Kevin <Kevin.Spicer at BMRB.CO.UK>

>> I upgraded to Postfix 2.0.11 yesterday to see if that would
>> fix things, but
>> no luck.  These second (empty) messages still happen.  I've
>> had 2 today, out
>> of about 20 emails.  Any hints on where I could look?
>Probably way off base but...

>I had a similar problem months ago - but with sendmail.  Turned out our
>exchange server was set to make ETRN requests to our Mailscanner box.
>Julian has since modified the sendmail startup scripts to defend against
>this, but I don't know whether it might affect other mailers.  Probably not
>your problem but something to rule out at least!

Thanks Kevin.  I don't think that's the problem here: one box does everything.

This is the sequence of events I'm seeing.  I guess, if I'm right,
that the real question is 'why does that second MailScanner instance
start up 1 second after the other one?'.

I tried upping the Queue Scan Interval to 20 seconds hoping that
would help, but it doesn't seem to.  I have not tried cutting Max
Children back to 1, but perhaps that's next: somewhat of a waste on a
dual-cpu box.  Perhaps there is a lock not getting set, or some race
condition with locking?

I'm at a loss what to look at next.

Thanks for your help,

Jay Kusler


Annotated /var/log/syslog follows:

Connect to the mail server (jade) smtpd and stick the incoming message
into /var/spool/ rather than deliver it
Jun 11 15:20:22 jade postfix/smtpd[13517]: [ID 197553] disconnect
Jun 11 15:20:22 jade postfix/qmgr[4999]: [ID 197553] AF3D0F3:
from=<fordtimo at>, size=1167, nrcpt=1 (queue active)
Jun 11 15:20:22 jade postfix/qmgr[4999]: [ID 197553] AF3D0F3:
to=<kusler at>, relay=none, delay=0, status=deferred (deferred

MailScanner (pid 5146) starts up and scans /var/spool/
and finds the message to me
Jun 11 15:20:26 MailScanner[5146]: New Batch: Scanning 1
messages, 1505 bytes
Jun 11 15:20:26 MailScanner[5146]: Virus and Content
Scanning: Starting

Here is the funky part: another MailScanner process (pid 5095) starts up
and tries to process the same mail message
Jun 11 15:20:27 MailScanner[5095]: New Batch: Scanning 1
messages, 1505 bytes

The first MailScanner process declares all to be well, and (presumably)
puts the uninfected message into /var/spool/postfix/incoming
Jun 11 15:20:27 MailScanner[5146]: Uninfected: Delivered 1

The qmgr notices the message and hands it off to procmail to actually
Jun 11 15:20:27 jade postfix/qmgr[5040]: [ID 197553] 09432938B:
from=<fordtimo at>, size=1261, nrcpt=2 (queue active)

Meanwhile the second MailScanner instance (pid 5095) scans the same
message, which for some reason is nothing but a header with no body
and puts it also into /var/spool/postfix/incoming where qmgr finds it
and also hands it off to procmail for delivery
11 15:20:27 MailScanner[5095]: Virus and Content Scanning:
Jun 11 15:20:28 MailScanner[5095]: Uninfected: Delivered 1
Jun 11 15:20:28 jade postfix/qmgr[5040]: [ID 197553] A167D9380:
from=<fordtimo at>, size=1111, nrcpt=2 (queue active)

Finally, both messages are delivered, 7 seconds apart.
Jun 11 15:20:29 jade postfix/local[16398]: [ID 197553] 09432938B:
to=<kusler at>, relay=local, delay=7, status=sent
Jun 11 15:20:36 jade postfix/local[17949]: [ID 197553] A167D9380:
to=<kusler at>, relay=local, delay=14, status=sent

More information about the MailScanner mailing list