Problem with specific mail

[Mark Martinec]

Marc,

> >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>

That's the final outcome. We already know we had a failure earlier.

The interesting Postfix log entries would be a 'connect from localhost'
at 10:42:37 or very close to that, and then the following long entries
of the same process ID as the 'smtpd' service which accepted the connection.

> 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>

Yes. There should be a corresponding message from a Postfix smtpd
service, at least a 'connect from localhost'. That would be a
back-end MTA, and following that same PID would show what happened
next at the Postfix side.

> 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?

Means feeding mail contents from amavisd back to a Postfix smtpd service
was stuck. Amavisd had more data to send, but Postfix would not read
it from a socket, or the TCP session was blocked.

Is there any firewall or a packet filter inbetween?

> 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.

Yes, these are just consequences of a timeout, 16 minutes later.

> looks to me like a amavis problem?!

Maybe, although I'm not aware of any problem in amavisd that would
manifest itself like this.

If you have a sample mail that can reproduce the problem (the message
could be collected from a Postfix queue with a 'postcat' command),
a packet capture of a back-end session may reveal more.

  Mark