Re: [AMaViS-user] Connection with amavisd-new lost - causing duplicate emails

Achton,

> I'm currently experiencing problems with my private mailserver. The
> symptoms are duplicate emails (or 3x or 4x) showing up in my inbox, same
> timestamp and all. The first mail will be received by postfix, but upon
> submitting it to Amavis, the connection is lost. ...

> PIII 550MHz, 256MB RAM
> * Debian GNU/Linux ("testing")
> * postfix, amavisd-new, SA, ClamAV, courier (POP/IMAP/maildrop)

> I've also noted in my mail logs that the SA check grabs 96-98% of the
> processing time with amavis, but I am not sure if this is of any interest.

SA is CPU intensive, although 16 seconds in on the high side.
Still, for a small host like yours it is not be unreasonable
if an occasional spam check takes that long.

> * postfix master.cf:
> - smtp_data_done_timeout=380000

Good, so smtp_data_done_timeout was not exceeded.
The SMTP connection got broken for some other reason,
not by a Postfix timeout.

> - $child_timeout=8*60
> - $sa_timeout = 120;

Ok.

> Apr 5 03:33:49 localhost amavis[9201]: (09201-10) TIMING [total 17017
> ms] - SMTP EHLO: 4 (0%), SMTP pre-MAIL: 1 (0%), SMTP pre-DATA-flush: 6
> (0%), SMTP DATA: 76 (0%), body hash: 1 (0%), mime_decode: 68 (0%),
> get-file-type: 210 (1%), get-file-type: 33 (0%), decompose_part: 3 (0%),
> decompose_part: 0 (0%), parts: 0 (0%), AV-scan-1: 50 (0%), SA msg read:
> 5 (0%), SA parse: 8 (0%), SA check: 16297 (96%), fwd-connect: 60 (0%),
> fwd-mail-from: 3 (0%), fwd-rcpt-to: 19 (0%), write-header: 8 (0%),
> fwd-data: 2 (0%), fwd-data-end: 50 (0%), fwd-rundown: 3 (0%),
> unlink-2-files: 10 (0%), rundown: 100 (1%)
> Apr 5 03:33:49 localhost amavis[9201]: (09201-10) tempdir being
> removed: /var/lib/amavis/amavis-20050405T011109-09201

Although it took SA 16 seconds to process the mail, it seems
it did process it and on the amavisd side all appears normal.

> Apr 5 03:33:51 localhost postfix/smtp[10025]: 5CEBC1369B:
> to=<achton@netherclift.net>, relay=127.0.0.1[127.0.0.1], delay=19,
> status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending
> end of data -- message may be sent more than once)

Instead of a SMTP status response, Postfix saw a disconnect
from amavisd, and it was not due to a timeout.

> Apr 5 03:58:29 localhost amavis[9973]: (09973-04) TIMING [total 18845 ms]

> Apr 5 03:58:29 localhost postfix/smtp[10109]: 5CEBC1369B:
> to=<achton@netherclift.net>, relay=127.0.0.1[127.0.0.1], delay=1497,
> status=sent (250 2.6.0 Ok, id=09973-04, from MTA: 250 Ok: queued as
> 51ED313786)

On the next attempt, SA took 18 seconds, but nevertheless this time
the mail was properly confirmed, Postfix did receive the SMTP reply.

Which version of Perl and which version of SA?
Make sure this is not Perl 5.8.0 or SA 3.0.0.

You may want to confirm with a tcpdump on the loopback interface
that a TCP disconnect (packet with a RST flag) really occurs out of the blue.

It is possibly caused by some external SA test like Razor
or pyzor or dcc, which may be closing STDIN.

Search for "client broke the connection without a QUIT"
on the amavisd-new web page. The cause is possibly the same.
If it is indeed an inappropriate close that is causing the disconnect,
a strace output may be able to pinpoint the culprit.

Mark


-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/...fo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/