Problem with specific mail

[Mark Martinec]

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