Monday, August 8, 2016

Exchange 2010 (SP3) - Message Tracking - 01

From time to time, I have to track a message to determine if it was delivered and if not, where it may have been blocked. In most situations, this process goes beyond the scope of Exchange and requires that we take into account perimeter devices (such as Barracuda or Ironport) and even online mail hygiene systems like Exchange Online Protection.

In one of the more common Exchange configurations, two multi-role servers configured as a Database Availability Group (or DAG), I have observed certain behavior that I wanted to verify by sending and resending a message in various scenarios, for example :
  • Send to external recipient
  • Receive from external sender
  • Send to internal recipient
  • Receive from internal sender.
Before I begin, however, I'm allowing myself a brief review of message tracking and protocol logs. Not having analyzed some of these types of logs for a while, I wanted to take another look at some of the basic concepts. My review is not necessarily complete, so feel free to consult other sources if necessary, and official Microsoft documentation in particular.

Note: since this blog post was becoming longer and longer, and since the analysis of the protocol logs related to my test message run the risk of being long and perhaps confusing as well, I've decided to look at the message tracking logs only in this first post and reserve the exam of the protocol logs to the following post. However, I will present the protocol logs (location, status) in this first post.


***

Where do we look when tracking a message ?

There are two types of logs we can examine : message tracking logs and protocol logs:
  • Message tracking - fairly readable.
  • Protocol (SMTP) - can provide very verbose details on connections established with remote SMTP servers but can be difficult to interpret.

The message tracking logs are stored here (by default):

C:\Program Files\Microsoft\Exchange Server\v14\TransportRoles\Logs\MessageTracking

We can use two tools in the Exchange 2010 "Toolbox" to track messages: "Message Tracking" (with a web interface) and "Tracking Log Explorer" with a MMC interface. I will use the latter.


As we shall see later, we can also view the content of the message tracking logs with PowerShell.

These are the default message tracking settings (click to enlarge):


For example, the maximum age for message tracking logs is 30 days. Older log files are deleted.

Message tracking is enabled by default. We can disable message tracking with this cmdlet:

Set-MailboxServer EX13-2 -MessageTrackingLogEnabled $false

Message tracking is a feature on Exchange servers holding either the Mailbox or Hub Transport role (or the less frequently used Edge Transport role).

If the server is only a Hub Transport server, we could use this cmdlet to disable message tracking:

Set-TransportServer EX13-2 -MessageTrackingLogEnabled $false

If both roles are present, we can use either cmdlet.

In any case, there is only one set of logs.

For those allergic to the command line, we can enable and disable message tracking here as well:




The "protocol" logs (in our case, SMTP protocol logs) are stored in the following location (we have a glimpse of this path in the last screenshot):

C:\Program Files\Microsoft\Exchange Server\v14\TransportRoles\Logs\ProtocolLog

There are three subfolders at this location: SmtpReceive and SmtpSend (plus a HTTPClient folder that does not play a role in mail transport). The logs are stored in these subfolders in the form of text files (just like the message tracking logs).

Unlike message tracking, SMTP protocol logging is not enabled by default. If we forget to enable it, we will not have much to work with. Moreover, SMTP protocol logging is not per server but rather per connecter; receive connector or send connector that is. We could enable protocol logging for receive connectors but not send connectors, or only certain receive connctors.

We can enable logging for a send connector with the following cmdlet (replace the send connector name with the name of your send connector(s)):

Set-SendConnector MYNET-SendConn-1 -ProtocolLoggingLevel Verbose

We can disable logging with this cmdlet:

Set-SendConnector MYNET-SendConn-1 -ProtocolLoggingLevel None

Note: "None" and "Verbose" are the only choices here. "None" is the default value.

Once again, if we prefer the EMC, we can enable/disable logging here:


The procedure would be the same for other send connectors or for receive connectors.


***


This is my configuration for our experiments in message tracking...

We have two Exchange servers: EX13-1 and EX13-2.
  • Each has the following roles: Client Access, Hub Transport, Mailbox.
  • A DAG has been configured.
  • EX13-1 is currently the PAM and holds the "active" copy of the sole mailbox database: DB01

Here's proof:

[PS] C:\>Get-MailboxDatabase | Get-MailboxDatabaseCopyStatus | fl Name,Status

Name   : DB1\EX13-1
Status : Mounted

Name   : DB1\EX13-2
Status : Healthy

[PS] C:\>Get-DatabaseAvailabilityGroup -s | fl Name,Servers,OperationalServers,PrimaryActiveManager

Name                     : DAG1
Servers                   : {EX13-2, EX13-1}
OperationalServers   : {EX13-1, EX13-2}
PrimaryActiveManager : EX13-1


What happens when... we send a message to an external recipient (at Gmail for example)?


Message Tracking logs

For the first experiment, our test user Alan Reid sends a message to a Gmail user. Alan Reid's mailbox is on EX13-1 (DB01). He accesses his mailbox Via Outlook. We are not using Exchange cached mode so the mailbox is being accessed directly (no OST files).

I begin the message tracking on EX13-1 with the following parameters so all operations (SUBMIT, RECEIVE, SEND, etc.) are captured:



I will use the PS equivalent (visible at the bottom of the sceenshot above) to display the details of each operation.

Note: I will also edit addresses for privacy and "snip" some of the output for concision and readability (especially when the values for the parameter in question is null).

On EX13-1, the only operation recorded is a SUBMIT event (other than a NOTIFYMAPI entry with essentially no data).

Here are the details of the SUBMIT event (with, once again, some edits):

Get-Messagetrackinglog -Start "7/18/2016 11:00:00 AM" -End "7/18/2016 12:05:00 PM" | fl

Timestamp               : 7/18/2016 11:57:15 AM
ClientIp                    : fe80::a179:11fd:2f31:9329%16
ClientHostname       : EX13-1
ServerIp                    :
ServerHostname       : EX13-2
ConnectorId              :
Source                      : STOREDRIVER
EventId                     : SUBMIT
InternalMessageId    :
MessageId               : <5386E0BEF5FB[...]15075DC27@EX13-1.mynet.lan>
Recipients                : {}
RecipientStatus       : {}
MessageSubject       : OutBound-001
Sender                     : Alan.Reid@mitserv.net
ReturnPath              :
MessageInfo             : 2016-07-18T15:57:14.276Z;LSRV=EX13-1.mynet.lan:TOTAL=1


It looks like the STOREDRIVER on EX13-1 submits the message to EX13-2, the other server of the pair:
  • ClientHostname = EX13-1
  • ServerHostname = EX13-2

I also noted that for the protocol logs (SmtpSend and SmtpReceive), there is no file for the current date (2016-7-18)  on EX13-1.

So, apparently, EX13-1 has submitted the message to EX13-2 and we have to consult the message tracking logs (and possibly the protocol logs) on EX13-2 to follow  our outbound email.

This is what we have on EX13-2 :



We can see the details better with the format-list option (fl) :

Get-messagetrackinglog -Start "7/18/2016 11:00:00 AM" -End "7/18/2016 12:05:00 PM" | fl

RECEIVE


The RECEIVE entry on EX13-2 seems to correspond with the SUBMIT entry on EX13-1 : in both cases, EX13-1 is the "client" (ClientHostName) and EX13-2 is the "server" (ServerHostName).

Some more parameters now have values, notably "Recipients" and "Returnpath".

Now that EX13-2 has the message "Outbound-001", what does it do with the message?


TRANSFER



At this point, EX13-2 is peforming ROUTING and content conversion. It determines the IP address of what is (at first glance) the recipient's mail server and the IP address of this server.

In fact, "smtp-auth.no-ip.com" is a "smart host" through which messages traverse before reaching the ultimate destination, in this case Gmail.

A send connector has been selected, the message appears to have been queued ("as 054E2400836") and the recipient status is Ok. It seems like the message has been sent.

In any case, this is the last event recorded in Message Tracking :

SEND



Note: the Gmail recipient did indeed receive the message.


Protocol logs (to be continued...)

I entitled this blog post "Message Tracking" even though I'm examining not only the "message tracking" logs but also protocol logs. These can be useful if we track, for example, an outgoing message that apparently cannot reach the target mail server, or a message that an external remote server cannot send to our organization. If, for some reason, the servers cannot "talk" to each other in general, then it is clear that specific messages will not be delivered. If the servers can communicate, we can at least rule out a general communication failure as the cause of the problem.

 As I studied the protocol log file associated with the message sent above, I was reminded that it is not only challenging to read the logs but also present them. For this reason, I have decided to divide the analysis of this first (outbound) message into two parts: "Message Tracking" per se, that we have examined in this blog post, and the "dissection" of a send protocol log that will be the subject of my next blog post.

No comments:

Post a Comment