Monday, 20 May 2013

Troubleshooting Email Delivery with Exchange Server Protocol Logging_Exchange 2007/2010

Protocol logs capture the SMTP communications that occur between servers. The information that is written to the protocol log files looks very similar to what you see when you are using Telnet to make an SMTP connection.


Example of a protocol logging log file

This information is invaluable in troubleshooting scenarios, because it captures events that occur during message delivery that may not appear in other logs on the server.

For example, many administrators are used to looking in message tracking logs when they troubleshoot email delivery. But message tracking logs only record events for messages once they are in the transport pipeline. If a message is never sent/received because the SMTP connection itself is rejected, the message tracking log will show no useful troubleshooting information.

There are two parts to the configuration of protocol logging in Exchange Server, and they are basically the same across Exchange 2007, Exchange 2010, and Exchange 2013.

Configuring Protocol Logging on Transport Servers

The first is the per-server settings, configured on Hub Transport and Edge Transport servers for Exchange 2007/2010, or either Client Access or Mailbox servers in Exchange 2013.
Protocol log paths can be set in the Exchange Management Console in the properties of the server.



However, most of the other useful settings can only be configured in the Exchange Management Shell.
You can use Get-TransportServer to view existing settings.

[PS] C:\>Get-TransportServer ho-ex2010-mb1 | select *protocollog*

IntraOrgConnectorProtocolLoggingLevel : None
ReceiveProtocolLogMaxAge              : 30.00:00:00
ReceiveProtocolLogMaxDirectorySize    : 250 MB (262,144,000 bytes)
ReceiveProtocolLogMaxFileSize         : 10 MB (10,485,760 bytes)
ReceiveProtocolLogPath                : C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs\ProtocolLog\
                                        SmtpReceive
SendProtocolLogMaxAge                 : 30.00:00:00
SendProtocolLogMaxDirectorySize       : 250 MB (262,144,000 bytes)
SendProtocolLogMaxFileSize            : 10 MB (10,485,760 bytes)
SendProtocolLogPath                   : C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs\ProtocolLog\
                                        SmtpSend
Note: I’ve left out the HTTP protocol log settings from the above output since they are not relevant to this article.

You’ll notice that send and receive logs have their own settings, allowing you to keep those log files in separate paths and use different retention periods to suit the specific server’s role.

The default settings on a server are fine for low volumes of email traffic. The 30 days retention is useful in theory but the max directory size of 250mb will mean that high volumes of email traffic will probably result in far less than 30 days of log files retained (250mb would cover a few hours of traffic on one of my servers at the moment).

So think of the max directory size as a safety net for your log retention to make sure that logs don’t fill up the disk on the server. My experience these days is that Transport servers tend to have plenty of free disk space so I like to set the max log directory to something generous like 4GB for both send and receive.

Set-TransportServer ho-ex2010-mb1 -SendProtocolLogMaxDirectorySize 4GB -ReceiveProtocolLogMaxDirectorySize 4GB

If you have any concerns about storing logs on the C: drive, either for performance or free space reasons, you can use the protocol log path settings to move the log directory to a different disk.

Configuring Protocol Logging on Connectors

The second part of the configuration is the per-connector settings. Even though protocol logging is enabled by default on Transport servers, it is not enabled by default on any send or receive connectors.

One approach is to enable protocol logging on every connector in your organization. However some administrators will prefer to enable it only as needed.
I recommend that you enable protocol logging on any of the following:
  • Send/receive connectors on any servers involved in internet email flow
  • Receive connectors on any servers that act as SMTP relays for internal devices and applications
Those recommendations are based
 on my experience that most SMTP troubleshooting cases are for situations where email is not delivering to/from the internet, or from internal devices and applications that relay through your Exchange servers.
I’ll give you two real world examples of those situations:
  1. Outbound emails to specific domains are queuing on your Edge Transport servers. Protocol logging is how you can discover what reason the recipient’s email server is giving for rejecting the connection from your server.
  2. You’ve added an IP address of an internal server to your relay connector. Protocol logging is how you can ensure that the correct receive connector on your Hub Transport server is processing the connections from that internal server.
You can see all of your receive connector protocol logging settings using the Get-ReceiveConnector cmdlet.

[PS] C:\>Get-ReceiveConnector | select server,name,*protocollogginglevel | sort server | ft -auto

Server        Name                  ProtocolLoggingLevel
------        ----                  --------------------
BR-EX2010-MB  Client BR-EX2010-MB                   None
BR-EX2010-MB  Default BR-EX2010-MB                  None
HO-EX2007-MB1 Client HO-EX2007-MB1                  None
HO-EX2007-MB1 Default HO-EX2007-MB1                 None
HO-EX2010-MB1 Relay                              Verbose
HO-EX2010-MB1 Client HO-EX2010-MB1                  None
HO-EX2010-MB1 Default HO-EX2010-MB1              Verbose
HO-EX2010-MB2 Default HO-EX2010-MB2              Verbose
HO-EX2010-MB2 Client HO-EX2010-MB2                  None
The setting is also visible in the properties of a receive connector.


Protocol logging on a receive connector
Send connectors also have their own protocol logging level, visible when you run Get-SendConnector (you’ll notice there is no “server” for a send connector).

[PS] C:\>Get-SendConnector | select name,*protocollogginglevel | ft -auto

Name                              ProtocolLoggingLevel
----                              --------------------
EdgeSync - HeadOffice to Internet              Verbose
EdgeSync - Inbound to HeadOffice                  None
Again, you will also find the setting in the properties of the send connector.


Protocol logging level on a send connector

Using Protocol Logging Data

Once you have protocol logging enabled there are a few ways you can put it to good use.
The first is in specific troubleshooting cases. Protocol logs are quite readable so all you need to do is open them in Notepad or a similar text editor and look at the data.
However, finding what you’re looking for can be a challenge if you’ve got a lot of log files.


Lots of logs files…
You can often narrow down the file you’re looking for because they are named according to date. But if there are multiple files for a given day you can search for strings in the files.
You can use PowerShell to search for string matches in the log files. In this example Get-Childitem returns the list of log files in the current directory, and I’m piping those into Select-String to look for “microsoft.com”.

PS > Get-ChildItem | Select-String -Pattern "microsoft.com"

RECV20120806-1.LOG:11:2012-08-06T00:30:07.127Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,5,10.1.3.6:25,114.42.130.106:19992,,
RECV20120806-1.LOG:14:2012-08-06T00:30:07.284Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,8,10.1.3.6:25,114.42.130.106:19992,,

The lines with the pattern matches as well as the file name itself (eg RECV20120806-1.LOG) are displayed in the results.

You also get the remote IP address (eg 114.42.130.106) returned, so you can perform a further search to see the entire SMTP conversation that occurred with that host.

PS > Get-ChildItem | Select-String -Pattern "114.42.130.106"

RECV20120806-1.LOG:6:2012-08-06T00:30:06.768Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411D
A334E41E,0,10.1.3.6:25,114.42.130.106:19992,+,,
RECV20120806-1.LOG:7:2012-08-06T00:30:06.768Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411D
A334E41E,1,10.1.3.6:25,114.42.130.106:19992,*,SMTPSubmit SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender Accept
RoutingHeaders,Set Session Permissions
RECV20120806-1.LOG:8:2012-08-06T00:30:06.768Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411D
A334E41E,2,10.1.3.6:25,114.42.130.106:19992,>,"220 HO-EX2010-EDGE.exchangeserverpro.net Microsoft ESMTP MAIL Service re
ady at Mon, 6 Aug 2012 10:30:05 +1000",
RECV20120806-1.LOG:9:2012-08-06T00:30:06.956Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411D
A334E41E,3,10.1.3.6:25,114.42.130.106:19992,,250 HO-EX2010-EDGE.exchangeserverpro.net Hello [114.42.130.106],
RECV20120806-1.LOG:11:2012-08-06T00:30:07.127Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,5,10.1.3.6:25,114.42.130.106:19992,,
RECV20120806-1.LOG:12:2012-08-06T00:30:07.127Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,6,10.1.3.6:25,114.42.130.106:19992,*,08CF411DA334E41E;2012-08-06T00:30:06.768Z;1,receiving message
RECV20120806-1.LOG:13:2012-08-06T00:30:07.127Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,7,10.1.3.6:25,114.42.130.106:19992,>,250 2.1.0 Sender OK,
RECV20120806-1.LOG:14:2012-08-06T00:30:07.284Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,8,10.1.3.6:25,114.42.130.106:19992,,
RECV20120806-1.LOG:15:2012-08-06T00:30:07.284Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,9,10.1.3.6:25,114.42.130.106:19992,*,Tarpit for '0.00:00:05',
RECV20120806-1.LOG:16:2012-08-06T00:30:12.299Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,10,10.1.3.6:25,114.42.130.106:19992,>,550 5.7.1 Unable to relay,
RECV20120806-1.LOG:17:2012-08-06T00:30:12.471Z,HO-EX2010-EDGE\Default internal receive connector HO-EX2010-EDGE,08CF411
DA334E41E,11,10.1.3.6:25,114.42.130.106:19992,-,,Remote

Those results can be a bit ugly though. Sometimes its easier to output them to a file for reading.

PS > $results = Get-ChildItem | Select-String -Pattern "114.42.130.106"
PS > $results | select line | Export-Csv -NoTypeInformation results.csv


Protocol logs were useful when I was troubleshooting the case of the Hub Transport server load imbalance.
Protocol logs can also be used for general reporting and monitoring of your servers. I’ve published some tutorials that show how to use Log Parser to extract useful insights from protocol logs.

Summary

As you can see, protocol logging is quite useful. I do recommend you check your protocol log configurations and enable them on the most important send and receive connectors so that when problems happen you have this valuable log data available to assist you with troubleshooting.

No comments:

Post a Comment