Saturday, August 20, 2016

Exchange 2010 (SP3) - Message Tracking - 02

This post continues the previous post in which we examined message tracking logs to follow the path of an outbound message sent to a Gmail recipient.

As we discussed in the previous post, when we send a message to an external recipient, there should be a SEND entry in the logs that indicates the message was sent:

Note: this screenshot is the same as the one used in the previous blog post.

If we need more details about the transaction between our Exchange server and the remote mail server (or "smart host" in the case of an external relay server situated between our server and the final recipient), we can consult the Exchange "protocol logs", in this case the SMTP protocol.

Even for what I will call a "basic" transaction, or session, the output in the protocol log is quite verbose. If TLS encryption is negociated, the content of the logs is even more plentiful.

I will opt to show screenshots of one of the sessions that took place when I sent a test message to Gmail, concentrating on these "basic" operations, and excluding the TLS negociation.

I will then analyze  the elements of each sequence of the session. The objective is to recognize what happens when this all works so we can compare that to the output of a failed communication between mail servers.


This is what a single session will look like in the protocol log:


I need to clarify some points before moving forward:
  • The most observant may remark that the dates do not coincide with the dates in the previous blog post. For some reason, I ended up using logs from a different date. That does not change anything fundamentally as for the analysis of the log.
  • I have changed the external recipient address for confidentiality.
  • I have "snipped" the section pertaining to TLS negociation for both simplicity and concision.
  • Although the external recipient is a Gmail user, the external mail server referenced in the logs is in fact a "smart host" through which my outbound messages are relayed.
  • A single protocol log file normally contains numerous SMTP sessions distinguished by the "session-id". 

The log is organized in columns (or "fields") separated by commas (we could open the log file in Excel for a better view). At the top of each column is a header that is more or less descriptive of the column's function (line 5 in the first of the two screenshots above):

#Fields: date-time,connector-id,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context

Let's dissect the first couple lines. What I will call the "first" line is the sixth line from the top of the log and has the "sequence-number" of 0 (zero). As we will see, each step of the communication between the two servers is designated by a number (starting with 0, not 1). If another message had been sent, the sequence would start all over again at zero. And as we mentioned before, each inter-server communication, or "session", has its own "session-id" that identifies it from the others in a log file that could include hundreds of sessions.



This is the date and time of the event, measured to fractions of a second (.389) and expressed in UTC (Z = Zulu or "Zulu Time").



This is the name of the send connector, in my case: MYNET-SendConn-1.



The session ID distinguishes the events related to the sending of "message A" from events related to "message B" and "message C" and so forth. 



A sequence number marks each step of the sending of the email.


There is no local endpoint in first line. In following lines, it will be the IP address of the local Exchange server ( in my case). 


This is the IP address of the remote mail server or smart host (note the port 25 - SMTP). In my case, it is, in fact, a relay (No-IP).



Please see the paragraph below (protocol logging event values). In this case, the " * " designates an informational event (no data has been transfered in either direction).


,, (none)

No data has been transfered so far.


attempting to connect

This is almost self-explanatory : my server is "attempting to connect" to the remote mail server (or smart host).

Protocol logging event values

For the event field, these are the possible values:

  • +   Connect
  • -   Disconnect
  • >   Send
  • <   Receive
  • *   Information

For additional information, please consult this MSDN document:

If we look at the two screenshots above, we can see that there are 55 operations that take place during this single session, some send, some receive, and so forth. Even if we exclude the SSL entries, that is quite a lot of data to analyze. Therefore, I will limit myself to the next line.

Since most of the first fields do not change (except for the fractions of second for date and time), I'll start with the session-id to underline that fact that it does not change but that the following field, the sequence-number does change.



This number will remain the same for the entire session.



Remember: we start with 0.


This was not present in the first sequence (0). It is the IP address of the sending server plus a randomly selected port. Note that, while the port of the destination host will always be 25 (barring some exceptional reconfiguration), the port used by the sending server can be something else. I would have thought this port would have been in the 49152–65535 "ephemeral" port range but apparently it can be selected in the registered port range (1024 - 49151).


This remains the same.



According to the list above, this is a "connection" event.

data and context

Both these fields are blank on the second line (of the session).


Below is another perspective of the session. I've copied only the event, data and context fields (columns) so we can concentrate on the "conversation" between the two end-points. Note that, for the most part, the context field is not populated, the first line, with the value "attempting to connect" being an exception:

*,,attempting to connect
<,220 ESMTP ready,
<,250-SIZE 36700160,

Note : at this point, probably because of the SSL negociation which we have omitted in our analysis, the first steps above are repeated, but this time (apparently) within the protected SSL connection:

<,250-SIZE 36700160,
<,334 <authentication information>,
>,<Binary Data>,
<,334 <authentication information>,
>,<Binary Data>,
<,235 2.0.0 OK,
*,44,sending message
>,MAIL FROM:<> SIZE=6147,
>,RCPT TO:<>,
<,250 2.1.0 Ok,
<,250 2.1.5 Ok,
<,354 End data with <CR><LF>.<CR><LF>,
<,250 2.0.0 Ok: queued as 1E53E4005DE,
<,221 2.0.0 Bye,

I will not analyze each step but will point out that all the 2xx SMTP codes (220, 250, 221) indicate that the operation was a "complete success". 3xx codes (334, 354) indicate success as well but more information is expected. 4xx codes indicate a temporary or "transient" failure (example: maximum number of recpients reached - for a single operation, but the server can try again later) and 5xx codes indicate permanent errors (example: incorrect address - the message will never arrive unless the sender corrects the address).


In the context of message tracking and troubleshooting, I wanted to examine the SMTP connection process between two mail servers, without necessarily dissecting each and every step in detail, so I would have a "good copy" to which I could refer when attempting to resolve a failed connection.

Like many administrators, I often juggle several projects both at work and outside of work and the time I can dedicate to the analysis of a particular operation is not unlimited. Therefore, I opted not to analyze in greater detail each of the steps presented in the previous section.

However, for those that would like more information on the SMTP protocol, you could (besides performing your own searches) consult the following documents:

How IT Works: How Simple is SMTP? (Technet)

Simple Mail Transfer Protocol (Wikipedia)

TurboSMTP - good summary of codes

SMTP - Enhanced Status Codes Registry (IANA)

SMTP - extremely detailed IETF document

No comments:

Post a Comment