SMTP protocol logging on Exchange: reading send and receive logs to debug connections

Message tracking tells you what Exchange did with a message; SMTP protocol logs show what was said on the wire. When a device can't relay or TLS quietly fails, the answer is usually a few lines in a protocol log. In this post I'll show how to enable logging where you need it, where the files live and how to read a session to spot TLS, authentication and relay failures.

How protocol logging works#

• Logging is switched on per connector with ProtocolLoggingLevel (Verbose or None). Out of the box only two connectors log: the Default Frontend <ServerName> Receive connector and the hidden Send connector of the Front End Transport service.
• Exchange also uses implicit, invisible intra-organization Send connectors for hops between servers and services; those are controlled at the service level.
• Location, maximum age and folder size are set per transport service. All Receive connectors in a service write to the same files (Send connectors likewise), and circular logging removes the oldest files.
• Each line holds date-time (UTC), connector-id, session-id, sequence-number, local-endpoint, remote-endpoint, event, data and context. The event is + connect, - disconnect, > sent by this server, < received from the other side and * information.

Default folders, under %ExchangeInstallPath%TransportRoles\Logs\:

File names follow RECVyyyyMMddhh-nnnn.log and SENDyyyyMMddhh-nnnn.log, with the hour in UTC.

Step-by-step#

1. Find the connector that handles the conversation#

Get-ReceiveConnector -Server EX01 | Format-Table Name, TransportRole, Bindings, RemoteIPRanges, ProtocolLoggingLevel -AutoSize
Get-SendConnector | Format-Table Name, AddressSpaces, SmartHosts, ProtocolLoggingLevel -AutoSize

For inbound sessions, match the sender's IP and the port to Bindings and RemoteIPRanges; when several connectors listen on the same IP and port, the most specific matching range wins. TransportRole tells you the folder: FrontendTransport logs under FrontEnd, HubTransport under Hub. Outbound, the Send connector with the most specific matching address space is used.

2. Turn on verbose logging#

Set-ReceiveConnector "EX01\Relay - Scanners" -ProtocolLoggingLevel Verbose
Set-SendConnector "Internet via Smart Host" -ProtocolLoggingLevel Verbose
# Server-to-server hops inside the organization (Transport service)
Set-TransportService EX01 -IntraOrgConnectorProtocolLoggingLevel Verbose

# Check folders and limits
Get-FrontendTransportService EX01 | Format-List ReceiveProtocolLog*, SendProtocolLog*
Get-TransportService EX01 | Format-List ReceiveProtocolLog*, SendProtocolLog*

Allow a few minutes for the change to be picked up, then reproduce the problem. On a busy server, raise ReceiveProtocolLogMaxAge or ReceiveProtocolLogMaxDirectorySize (and the Send equivalents) if files are recycled before you can read them.

3. Pull one session out of the file#

Sessions are interleaved, so parse the file and filter by remote IP, then by session:

$dir = Join-Path $env:ExchangeInstallPath "TransportRoles\Logs\FrontEnd\ProtocolLog\SmtpReceive"
$file = Get-ChildItem $dir -Filter "RECV*.log" | Sort-Object LastWriteTime | Select-Object -Last 1
$fields = 'date-time','connector-id','session-id','sequence-number','local-endpoint','remote-endpoint','event','data','context'
$rows = Get-Content $file.FullName | Where-Object { $_ -notlike '#*' } | ConvertFrom-Csv -Header $fields

$rows | Where-Object { $_.'remote-endpoint' -like '192.168.10.50:*' } |
  Group-Object 'session-id' | Select-Object -Last 1 -ExpandProperty Group |
  Format-Table 'sequence-number', event, data, context -Wrap

4. Read the session#

A healthy anonymous relay session looks like this (trimmed to sequence, event, data and context):

0   +
1   *   SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAnySender ...   Set Session Permissions
2   >   220 mail.contoso.com Microsoft ESMTP MAIL Service ready at ...
3   <   EHLO scanner01.contoso.com
4   >   250  mail.contoso.com Hello [192.168.10.50] SIZE ... PIPELINING DSN ENHANCEDSTATUSCODES STARTTLS ...
5   <   STARTTLS
6   >   220 2.0.0 SMTP server ready
7   *   TLS protocol SP_PROT_TLS1_2_SERVER negotiation succeeded using bulk encryption algorithm ...
...
12  <   MAIL FROM:<scanner@contoso.com>
13  >   250 2.1.0 Sender OK
14  <   RCPT TO:<anna@fabrikam.com>
15  >   250 2.1.5 Recipient OK
16  <   DATA
17  >   354 Start mail input; end with <CRLF>.<CRLF>
18  >   250 2.6.0 <...> [InternalId=...] Queued mail for delivery
19  <   QUIT
20  >   221 2.0.0 Service closing transmission channel
21  -

• Set Session Permissions lists what the session may do. Without SMTPAcceptAnyRecipient, an anonymous sender can't relay to external domains.
• STARTTLS in the EHLO response means the connector has a usable certificate; the TLS line that follows shows the protocol version and ciphers negotiated.
• 250 2.6.0 … Queued mail for delivery means Exchange accepted the message; from there, follow it with message tracking.

5. Spot TLS, authentication and relay failures#

Verify#

• New entries appear after the change: Get-ChildItem $dir | Sort-Object LastWriteTime | Select-Object -Last 3 Name, LastWriteTime, Length.
• A test from the real device or application produces a session that runs from STARTTLS and a successful TLS line through 250 2.6.0 ... Queued mail for delivery to 221 2.0.0 Service closing transmission channel.
• The RECEIVE event for that message in message tracking shows the connector you expect in ConnectorId.

Tips & gotchas#

• Internet mail on port 25 is logged by the Front End Transport service. Its proxied hop to the Transport service appears in the Front End SmtpSend log, which is on by default.
• The connector-id column is the quickest proof of which connector answered a device, the root cause of most 530 and 550 relay problems.
• Times are UTC; convert before comparing with user reports.
• Protocol logs contain addresses, host names and IPs; redact them before sharing.
• When you're done, set -ProtocolLoggingLevel None on connectors you enabled only for troubleshooting, unless you want the history.

References#

• Protocol logging in Exchange Server
• TLS negotiation failed with error NoCredentials if messages to external domains are deferred
• Can't send or receive email when using TLS 1.1 or TLS 1.0