On Tue, Jan 21, 2014 at 01:05:40PM -0800, Todd Lyons wrote:
> 2014-01-10 21:53:45 SSL_write: (from
> mail-by2lp0241.outbound.protection.outlook.com
> (na01-by2-obe.outbound.protection.outlook.com) [207.46.163.241])
> syscall: Connection reset by peer
>
> If you look at the timestamps, the SSL_write message is logged at the
> end of the message, so I suspect this is just closing down the socket.
> But the message tends to indicate an disorderly shutdown. I've not
> captured a session yet to see if the remote is not sending QUIT, or if
> it is not waiting for the response to the QUIT.
>
> Anybody else seeing this?
This is certainly not surprising, SMTP clients typically don't hang
around to read the response to "QUIT" (and don't even always send
QUIT, but that is likely not important here). The typical sequence for
a client that does not PIPELINE ".\r\nQUIT\r\n" is:
C: .\r\n
S: 250 2.0.0 ... \r\n
C: QUIT\r\n
C: tear down TLS connection while racing against:
S: 221 2.0.0 Goodbye\r\n
S: tear down TLS connection...
So the server 221 reply will frequently find the client already
disconnected. While with PIPELINING:
C: .\r\nQUIT\r\n
S: 250 2.0.0 ... \r\n221 2.0.0 Goodbye\r\n
C: tear down TLS connection...
S: tear down TLS connection...
and the tear-down race is invisible. Microsoft's SMTP client
implementation must be one of those few that do not PIPELINE "."
and "QUIT". Why might this not have been noticed before? I am
guessing historically they did not implement outbound TLS, but
times have changed.
So why Postfix not complain about the Microsoft SMTP client:
Jan 21 16:14:32 amnesiac postfix/smtpd[20465]: connect
from na01-bl2-ndr.ptr.protection.outlook.com[157.55.133.97]
Jan 21 16:14:32 amnesiac postfix/smtpd[20465]: setting up TLS connection
from na01-bl2-ndr.ptr.protection.outlook.com[157.55.133.97]
Jan 21 16:14:32 amnesiac postfix/smtpd[20465]: Anonymous TLS connection
established from na01-bl2-ndr.ptr.protection.outlook.com[157.55.133.97]:
TLSv1 with cipher AES128-SHA (128/128 bits)
Jan 21 16:14:33 amnesiac postfix/smtpd[20465]: 0F0FF2AAB41:
client=na01-bl2-ndr.ptr.protection.outlook.com[157.55.133.97]
Jan 21 16:14:33 amnesiac postfix/smtpd[20465]: disconnect from
na01-bl2-ndr.ptr.protection.outlook.com[157.55.133.97]
The reason is that Postfix only explicitly flushes the QUIT response,
when there are other unsent pipelined SMTP replies in the output
buffer (generally a "." response). The explicit flush is subject
to error logging.
When on entry to the "QUIT" command state the output buffer is
empty, the QUIT reply is added to the output buffer, but not flushed.
The protocol engine terminates, and the buffer is closed by the
connection tear-down code. The connection tear-down code attempts
to flush the buffer (courtesy to the client) but if this fails
nothing is logged, because failure of tear-down is un-interesting.
All the important stuff is logged before then.
So if Exim wants to avoid spurious noise in the logs, it may be
necessary to adopt code similar to what Wietse added to Postfix
2.6 around the 5th of December 2008.
--
Viktor.
