AW: Problem with specific mail

[Grooz, Marc (regio iT)]

Hi Mark,

>Try to find corresponding Postfix log entries matching the back-end SMTP session which opened at around 10:43:37, and see how it looked from the MTA side.

There are so many log entries, I only found this:

Aug 20 10:44:17 postfix/smtpd[778]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<maila> to=<mailb> proto=ESMTP helo=<mta>

>Do you have further filters (like a milter) attached to the resubmission service?
No.

The last Message from the back-end SMTP is:

Aug 20 10:42:37 srvspam-v01 amavis[17227]: (17227-16) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>

And then Amavis starts with these Messages (16x):

Aug 20 10:43:37 srvspam-v01 amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, no progress, last event (select) 60.057 s ago

What they mean?

And after that:

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) mail_via_smtp: session failed: Error reading from socket: Connection timed out at /usr/sbin/amavisd line 6814, <GEN30> line 14854.

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) (!)mail_via_smtp: NOTICE: aborting SMTP session, Error reading from socket: Connection timed out at /usr/sbin/amavisd line 6814, <GEN30> line 14854.

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) Amavis::Out::SMTP::Session close, already disconnected

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) rw_loop read: got eof

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) (!!)TROUBLE in check_mail: forwarding FAILED: Error writing to socket: Broken pipe at /usr/sbin/amavisd line 6843, <GEN30> line 14854.

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) sending SMTP response: "451 4.5.0 Error in processing, id=17227-16, forwarding FAILED: Error writing to socket: Broken pipe at /usr/sbin/amavisd line 6843, <GEN30> line 14854."

Aug 20 10:59:32 srvspam-v01 amavis[17227]: (17227-16) (!)PRESERVING EVIDENCE in /var/spool/amavis/tmp/amavis-20120820T103803-17227-DhmH8v_X

looks to me like a amavis problem?!

Thanks

Marc
Mit freundlichen Grüßen

Marc Grooz


-----Ursprüngliche Nachricht-----
Von: amavis-users-bounces+marc.grooz=regioit.de at amavis.org [mailto:amavis-users-bounces+marc.grooz=regioit.de at amavis.org] Im Auftrag von Mark Martinec
Gesendet: Montag, 20. August 2012 16:39
An: amavis-users at amavis.org
Betreff: Re: Problem with specific mail

Marc,

> One Email won't go thru my amavis-proxy.
> I am using amavis 2.7.0-20.6.1 from Suse 12.1.

> Aug 20 10:42:37 amavis[17227]: (17227-16)
>   p002 1/2 Content-Type: application/x-zip-compressed,
>   size: 582346 B, name: name.zip
> Aug 20 10:42:37 amavis[17227]: (17227-16)
>   (!)Exceeded storage quota 5242880 bytes by do_unzip;
>   last chunk 330619 bytes
> Aug 20 10:42:37 amavis[17227]: (17227-16)
>   Decoding of p002 (Zip archive data, at least v2.0 to extract
>   Zip archive data, at least v2.0 to extract) failed, leaving it unpacked:
>   Exceeded storage quota 5242880 bytes by do_unzip; last chunk 330619 
> bytes Aug 20 10:42:37 amavis[17227]: (17227-16)
>   NOTICE: Virus scanning skipped: Exceeded storage quota 5242880 bytes
>   by do_unzip; last chunk 330619 bytes

The above means the 0.5 MB zip part uncompresses to more than 5 MB.
This may be perfectly reasonable, consider increasing $MAX_EXPANSION_QUOTA which seems to be the limiting factor here, e.g to 1 GB:

  $MAX_EXPANSION_QUOTA = 1024*1024*1024;  # bytes

> Aug 20 10:43:37 amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, 
> no progress, last event (select) 60.057 s ago Aug 20 10:44:37 
> amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, no progress, 
> last event (select) 60.060 s ago Aug 20 10:45:37 amavis[17227]: 
> (17227-16) (!)rw_loop: leaving rw loop, no progress, last event 
> (select) 60.062 s ago Aug 20 10:46:37 amavis[17227]: (17227-16) 
> (!)rw_loop: leaving rw loop, no progress, last event (select) 60.062 s 
> ago Aug 20 10:47:38 amavis[17227]: (17227-16) (!)rw_loop: leaving rw 
> loop, no progress, last event (select) 60.061 s ago Aug 20 10:48:38 
> amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, no progress, 
> last event (select) 60.060 s ago Aug 20 10:49:38 amavis[17227]: 
> (17227-16) (!)rw_loop: leaving rw loop, no progress, last event 
> (select) 60.061 s ago Aug 20 10:50:38 amavis[17227]: (17227-16) 
> (!)rw_loop: leaving rw loop, no progress, last event (select) 60.057 s 
> ago Aug 20 10:51:38 amavis[17227]: (17227-16) (!)rw_loop: leaving rw 
> loop, no progress, last event (select) 60.061 s ago Aug 20 10:52:38 
> amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, no progress, 
> last event (select) 60.061 s ago Aug 20 10:53:38 amavis[17227]: 
> (17227-16) (!)rw_loop: leaving rw loop, no progress, last event 
> (select) 60.061 s ago Aug 20 10:54:38 amavis[17227]: (17227-16) 
> (!)rw_loop: leaving rw loop, no progress, last event (select) 60.057 s 
> ago Aug 20 10:55:38 amavis[17227]: (17227-16) (!)rw_loop: leaving rw 
> loop, no progress, last event (select) 60.061 s ago Aug 20 10:56:38 
> amavis[17227]: (17227-16) (!)rw_loop: leaving rw loop, no progress, 
> last event (select) 60.029 s ago Aug 20 10:57:38 amavis[17227]: 
> (17227-16) (!)rw_loop: leaving rw loop, no progress, last event 
> (select) 60.060 s ago Aug 20 10:58:38 amavis[17227]: (17227-16) 
> (!)rw_loop: leaving rw loop, no progress, last event (select) 60.061 s 
> ago Aug 20 10:59:32 amavis[17227]: (17227-16) mail_via_smtp: session 
> failed: Error reading from socket: Connection timed out at
/usr/sbin/amavisd line 6814, <GEN30> line 14854.
> Aug 20 10:59:32 amavis[17227]: (17227-16) (!)mail_via_smtp: NOTICE: 
> aborting SMTP session, Error reading from socket: Connection
timed out at /usr/sbin/amavisd line 6814, <GEN30> line 14854.
> Aug 20 10:59:32 amavis[17227]: (17227-16) (!!)TROUBLE in check_mail: 
> forwarding FAILED: Error writing to socket: Broken pipe at
/usr/sbin/amavisd line 6843, <GEN30> line 14854.
[...]
> Aug 20 10:59:32 amavis[17227]: (17227-16) size: 802612, TIMING [total 
> 1016411 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0,
SMTP pre-MAIL: 2 (0%)0, SMTP pre-DATA-flush: 4 (0%)0, SMTP DATA: 1505 (0%)0, check_init: 1 (0%)0, digest_hdr: 1 (0%)0,
digest_body_dkim: 6 (0%)0, mime_decode: 50 (0%)0, get-file-type2: 34 (0%)0, decompose_part: 30 (0%)0, parts_decode: 0 (0%)0,
check_header: 1 (0%)0, decide_mail_destiny: 7 (0%)0, notif-quar: 1 (0%)0, fwd-connect: 12 (0%)0, fwd-xforward: 2 (0%)0, fwd-mail-
pip: 4 (0%)0, fwd-rcpt-pip: 0 (0%)0, fwd-data-chkpnt: 0 (0%)0, write-header: 1 (0%)0, SMTP pre-response: 1014744 (100%)100, SMTP
response: 0 (0%)100, rundown: 1 (0%)100

There is the real problem here. When amavisd is trying to feed the message back to an MTA, the initial SMTP handshake (greeting, MAIL FROM, RCPT TO) seems to have succeeded, but the actual transfer of mail contents is stuck for 16 minutes, after which a timeout is declared.

Try to find corresponding Postfix log entries matching the back-end SMTP session which opened at around 10:43:37, and see how it looked from the MTA side.
Do you have further filters (like a milter) attached to the resubmission service?

  Mark