double messages?

[Jay Kusler]

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

>>
>> 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/postfix.in/deferred rather than deliver it
----------------------------------------------------------------------
Jun 11 15:20:22 jade postfix/smtpd[13517]: [ID 197553 mail.info] disconnect
from sys10.mail.msu.edu[35.9.75.110]
Jun 11 15:20:22 jade postfix/qmgr[4999]: [ID 197553 mail.info] AF3D0F3:
from=<fordtimo at msu.edu>, size=1167, nrcpt=1 (queue active)
Jun 11 15:20:22 jade postfix/qmgr[4999]: [ID 197553 mail.info] AF3D0F3:
to=<kusler at nscl.msu.edu>, relay=none, delay=0, status=deferred (deferred
transport)

MailScanner (pid 5146) starts up and scans /var/spool/postfix.in/deferred
and finds the message to me
----------------------------------------------------------------------
Jun 11 15:20:26 jade.nscl.msu.edu MailScanner[5146]: New Batch: Scanning 1
messages, 1505 bytes
Jun 11 15:20:26 jade.nscl.msu.edu 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 jade.nscl.msu.edu 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 jade.nscl.msu.edu MailScanner[5146]: Uninfected: Delivered 1
messages

The qmgr notices the message and hands it off to procmail to actually
deliver
-----------------------------------------------------------------------
Jun 11 15:20:27 jade postfix/qmgr[5040]: [ID 197553 mail.info] 09432938B:
from=<fordtimo at msu.edu>, 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 jade.nscl.msu.edu MailScanner[5095]: Virus and Content Scanning:
Starting
Jun 11 15:20:28 jade.nscl.msu.edu MailScanner[5095]: Uninfected: Delivered 1
messages
Jun 11 15:20:28 jade postfix/qmgr[5040]: [ID 197553 mail.info] A167D9380:
from=<fordtimo at msu.edu>, 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 mail.info] 09432938B:
to=<kusler at nscl.msu.edu>, relay=local, delay=7, status=sent
("|/usr/nsclsbin/procmail")
Jun 11 15:20:36 jade postfix/local[17949]: [ID 197553 mail.info] A167D9380:
to=<kusler at nscl.msu.edu>, relay=local, delay=14, status=sent
("|/usr/nsclsbin/procmail")