I’m trying to understand how exactly an email is processed by Postfix – and some of the finer details of SMTP mail transactions. My short-term goal is to debug a proprietary (binary, closed source) SMTP client but I first thought I’d examine what happens in a successful SMTP transaction.
I plan on blocking outgoing SMTP (port 25) at our LAN firewall so I configured Postfix as an internal mail server to accept mails from (primitive) local client software which can only send email via non-authenticated SMTP (over Port 25).
I turned on debugging of the Postfix smtpd
process by appending the -v
verbose flag in master.cf
as described in Troubleshooting with Postfix Logs. I then sent an email from my own workstation using Cygwin Mutt with sSMTP (a minimal implementation of sendmail
).
The Postfix logs show that after the RCPT TO:
line was successfully processed and the recipient address was acceptable, Postfix’s smtpd
assigned the transaction a Queue ID and responded to the SMTP client (sSMTP) with a 250 OK
.
However, instead of issuing a DATA
command, the SMTP client issued a RSET
to reset / abort the current mail transaction and Postfix replied with a 250 OK
.
I did some research on what this command command does and unsurprisingly, the Simple Mail Transfer Protocol, RFC 2821 provided the most comprehensive information:
This command specifies that the current mail transaction will be aborted. Any stored sender, recipients, and mail data MUST be discarded, and all buffers and state tables cleared. The receiver MUST send a "250 OK" reply to a RSET command with no arguments. A reset command may be issued by the client at any time. It is effectively equivalent to a NOOP (i.e., if has no effect) if issued immediately after EHLO, before EHLO is issued in the session, after an end-of-data indicator has been sent and acknowledged, or immediately before a QUIT. An SMTP server MUST NOT close the connection as the result of receiving a RSET; that action is reserved for QUIT (see section 4.1.1.10).
Since EHLO implies some additional processing and response by the server, RSET will normally be more efficient than reissuing that command, even though the formal semantics are the same.
There are circumstances, contrary to the intent of this specification, in which an SMTP server may receive an indication that the underlying TCP connection has been closed or reset. To preserve the robustness of the mail system, SMTP servers SHOULD be prepared for this condition and SHOULD treat it as if a QUIT had been received before the connection disappeared.
All of the above happened within the space of a second so there shouldn’t be any issues with time-outs.
In the next second, the client sent another RSET
but the client then waited a whole 10s before restarting with MAIL FROM:
, RCPT TO:
but this time it follows through and issues the DATA
command and the transaction completes (all within the same second according to the logs).
Essentially, I’m wondering why a SMTP client would interrupt its own transaction by issuing RSET
commands instead of a DATA
command.
Notes:
I can edit the question to include extract from the mail log file but with the
-v
debugging, they’re very verbose and I don’t want to overwhelm people with a firehose of irrelevant data.I searched the sSMTP source code but I didn’t find any mention of
RSET
.
TLDR
I had been wondering why an SMTP client would interrupt its own transaction by issuing RSET commands instead of the DATA command. The short answer is that it wouldn’t; this is a symptom of SMTP connections being intercepted by anti-virus software.
Client Logging
I enabled the Debug option in the configuration for sSMTP but it took some time for me to figure out how to install and configure syslog in Cygwin so that messages from Cygwin processes are logged to
/var/log/messages
instead of the Windows event viewer.However, it only logged the first
MAIL FROM:
andRCPT TO:
commands; there was no indication that these commands were sent more than once – or thatsSMTP
ever sent anRSET
command.As mentioned in my question, I had checked the sSMTP source code but there's no code to send an
RSET
command.Symantec Interception of SMTP traffic
User masegaloeh suggested that anti-virus software may be modifying the SMTP packets – and he was right: I temporarily disabled Symantec Endpoint Protection on my computer and the SMTP transactions proceeded as normal.
After re-enabling Symantec Endpoint Protection, I monitored TCP connections using the TCPView utility from Windows Sysinternals and I could see that the Symantec
ccSvcHst.exe
process was proxying all TCP traffic whose destination port is 25.I telnetted to Port 25 on the mail server (netcat wouldn’t work properly, possibly due to Symantec interception) to send a test mail using by manually entering SMTP commands. At the same time, I had another terminal window open with an SSH connection to the mail host while running
sudo tail -F /var/log/maillog
to simultaneously monitor what the SMTP server was seeing.The interception carried out by the Symantec proxy is subtle. From the mail client’s perspective, there’s very little indication that it’s not talking directly to the SMTP server. Most of the commands are passed through to the mail server as they were sent and the responses are what you’d expect. It wasn’t until I entered the
DATA
command, that the Symantec proxy started to change things: it responded with:This seems normal but in reality, the response from my Postfix server should have been
Also: it didn’t actually pass the
DATA
command on to Postfix until after I had completed the message body and followed it with aQUIT
.Note: while I was typing the contents of the test message, the Symantec proxy kept its connection to the Postfix server alive by issuing
NOOP
commands.Dealing with buggy SMTP clients
I mentioned in my question that my eventual goal was to troubleshoot a proprietary (binary, closed source) mail client used by my organisation. I discovered that this client is really buggy: it sends an invalid
HELO
command (without any hostname) and then simply gives up and QUITs after it’s politely informed by the SMTP server that its syntax is wrong – even though I had configured Postfix to not require aHELO
(valid or otherwise).I resolved this issue by installing a new server with CentOS 7 which comes with a Postfix version recent enough so that I can disable postfix HELO checks completely (similar to how MS Exchange simply ignores invalid HELO commands).
General use of RSET
I had also been wondering about the general usage of
RSET
in SMTP transactions and I found the following in the original RFC 821 for SMTP:RSET
would be used if it turned out that the recipient email address was for a non-existent user. The following SMTP transaction is an example of an Aborted SMTP Transaction Scenario.Re-use of SMTP connections
SMTP clients can use the same SMTP connection to send multiple messages to the same destination. This feature is termed SMTP connection caching by Postfix. When using this performance feature, Postfix sends an
RSET
before eachMAIL FROM
command to verify that the SMTP connection is still usable (see Postfix Connection Cache).