9

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:

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

  2. I searched the sSMTP source code but I didn’t find any mention of RSET.

Anthony Geoghegan
  • 2,800
  • 1
  • 23
  • 34

1 Answers1

14

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: and RCPT TO: commands; there was no indication that these commands were sent more than once – or that sSMTP ever sent an RSET 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:

354 Please start mail input.

This seems normal but in reality, the response from my Postfix server should have been

354 End data with <CR><LF>.<CR><LF>

Also: it didn’t actually pass the DATA command on to Postfix until after I had completed the message body and followed it with a QUIT.

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 a HELO (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:

This command specifies that the current mail transaction is to be aborted. Any stored sender, recipients, and mail data must be discarded, and all buffers and state tables cleared. The receiver must send an OK reply.

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.

R: 220 MIT-Multics.ARPA Simple Mail Transfer Service Ready
S: HELO ISI-VAXA.ARPA
R: 250 MIT-Multics.ARPA

S: MAIL FROM:<Smith@ISI-VAXA.ARPA>
R: 250 OK

S: RCPT TO:<Jones@MIT-Multics.ARPA>
R: 250 OK

S: RCPT TO:<Green@MIT-Multics.ARPA>
R: 550 No such user here

S: RSET
R: 250 OK

S: QUIT
R: 221 MIT-Multics.ARPA Service closing transmission channel

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 each MAIL FROM command to verify that the SMTP connection is still usable (see Postfix Connection Cache).

Anthony Geoghegan
  • 2,800
  • 1
  • 23
  • 34
  • Regarding the general usage of `RSET`, Postfix will send it when pushing multiple emails over the same connection to confirm that it's still usable: http://www.postfix.org/CONNECTION_CACHE_README.html – André Paramés Apr 18 '18 at 12:53
  • 1
    @AndréParamés Thanks for that info; I've incorporated it into my answer. – Anthony Geoghegan Apr 18 '18 at 13:51