Exchange ActiveSync Mailbox Logging

Applies to: Exchange 2007, 2010, 2013, 2016, Office 365

Exchange ActiveSync (EAS) mailbox logs are protocol-level logs that show the traffic between Exchange and the EAS device.  This is assuming of course, that the device actually connects, gets past IIS, and into Exchange code.  When troubleshooting EAS issues, this is often the most useful piece of information.  Gathering these logs can be quick if you use PowerShell to do so, versus gathering them via ECP.

PowerShell Method

Enable the logging on the affected mailbox:

Set-CASMailbox alias -ActiveSyncDebugLogging:$true

Note: Get-CASMailbox will not show whether ActiveSyncDebugLogging is on or off unless you add the  -ActiveSyncDebugLogging parameter.

Reproduce whatever issue you're dealing with, then gather the logs:

Exchange 2007/2010

Get-ActiveSyncDeviceStatistics -Mailbox alias -GetMailboxLog:$true -NotificationEmailAddress yourEmailAddress@contoso.com

Exchange 2013+

Get-MobileDeviceStatistics -Mailbox alias -GetMailboxLog:$true -NotificationEmailAddresses yourEmailAddress@contoso.com

This will output the log to the screen (in 2010 and above), and email a copy of it to your email.  Easy!

Note that these cmdlets will work in all versions of Exchange from 2007-2016, however in 2013 we've deprecated Get-ActiveSyncDeviceStatistics in favor of Get-MobileDeviceStatistics, and in 2007 the cmdlets don't actually do anything (see the Exchange 2007 note below).  The cmdlet is otherwise the same.

By default, these logs will contain tags that are truncated -- the data for most tags is removed, and replaced with a tag attribute indicating how many bytes the data contains.  For example, the subject of an email may look like this:

<Subject xmlns="Email:" bytes="19"/>

...instead of this:

<Subject xmlns="Email:">This is the subject</Subject>

If the actual data is required, then enable verbose logging on each CAS the request may hit.  To do so, open the x:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\Sync\web.config file (replacing V14 with V15 in 2013+), and find this tag:

<add key="EnableMailboxLoggingVerboseMode" value="false"></add>

Change that value to true.  Note that this setting is per-CAS and not per-user, so the verbosity will be dependent on which CAS the device hits.  No restart is required of IIS or the application pool.  Also note that Office 365 does not allow verbose logging, so you're stuck with using Fiddler (with the EAS Inspector for Fiddler) or working with the truncated data.

Exchange 2007

In Exchange 2007, the EAS logs are enabled per-server.  To enable EAS logging, open the x:\Program Files\Microsoft\Exchange Server\ClientAccess\Sync\web.config file, and find this tag:

<add key="MailboxLoggingEnabled" value="false"></add>

Change that value to true.  Note that this setting is also per-CAS, so the traffic will only be logged if the device hits a CAS with this enabled.  Other than this setting, the rest of the steps are the same as Exchange 2010-current.

OWA / ECP Method

This method allows end-users to easily gather their own logs through OWA -> ECP.  Simply log into ECP and go to Options -> Phone -> Mobile Phones/Devices.  This slab contains a list of the EAS devices for the mailbox, and users can enable logging and retrieve it from here. The log will be sent to the user’s mailbox.

[caption id="attachment_205" align="alignnone" width="437"]Mobile devices slab in Exchange 2013 Mobile devices slab in Exchange 2013[/caption]

 

[caption id="attachment_215" align="alignnone" width="412"]Mobile devices slab in Office 365 Mobile devices slab in Office 365[/caption]

 

In any of the versions, select the device you want logging for, and click the "Start Logging" icon (highlighted in yellow).  After enabling the logging, reproduce the behavior and then click "Retrieve Log" which will be the same button.

Whether you use PowerShell or ECP to enable logging, the log is sent to you in an email message that has the log attached.  After 72 hours this logging is automatically disabled, so keep that in mind if you're trying to capture logs over a long period of time.  These logs are not intended to stay enabled very long.

The Exchange ActiveSync Protocol

The Exchange ActiveSync protocol is well documented, yet can be difficult to read and understand.  It’s broken up into numerous specifications, which are all listed in the Exchange Server Protocol Docs.

The main specifications you’ll likely use on a regular basis are for the contact, calendar, and commands.  All the docs for ActiveSync start with MS-AS, such as MS-ASCNTC (Contact Class), MS-ASCAL (Calendar Class), and MS-ASCMD (Command Reference).

Understanding these logs may require extensive protocol review, but some will be fairly straightforward.  SendMail for example will send an email, with tags such as <Subject> etc.

Sample Log

Here is a snippet from a sample log showing the MeetingResponse command.  For this sample, the EAS command MeetingResponse should be reviewed.  The full command reference can be found in the MS-ASCMD reference under Messages -> Message Syntax -> Commands.

 -----------------
 Log Entry: 325
-----------------

RequestTime : 
02/28/2013 17:23:23

ServerName : 
CONTOSO-E2K10

AssemblyVersion : 
14.02.0247.001

Identifier : 
114A6C98

RequestHeader : 
POST /Microsoft-Server-ActiveSync/default.eas?User=user@contoso.com&DeviceId=DMPFXZABDFHW&DeviceType=WindowsMail&Cmd=MeetingResponse HTTP/1.1
Connection: keep-alive
Content-Length: 29
Content-Type: application/vnd.ms-sync.wbxml
Accept: */*
Accept-Encoding: gzip, deflate
Accept-Language: en-us
Authorization: ********
Host: mail.contoso.com
User-Agent: Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.2; Win64; x64; Trident/6.0)
X-MS-PolicyKey: 196647767
MS-ASProtocolVersion: 14.2


RequestBody : 
<?xml version="1.0" encoding="utf-8" ?>
<MeetingResponse xmlns="MeetingResponse:">
    <Request>
        <UserResponse>1</UserResponse>
        <CollectionId>1</CollectionId>
        <RequestId>1:653</RequestId>
    </Request>
</MeetingResponse>

AccessState : 
Allowed

AccessStateReason : 
Global

ResponseHeader : 
HTTP/1.1 200 OK
MS-Server-ActiveSync: 14.2


ResponseBody : 
<?xml version="1.0" encoding="utf-8" ?>
<MeetingResponse xmlns="MeetingResponse:">
    <Result>
        <RequestId>1:653</RequestId>
        <Status>1</Status>
        <CalId>1:654</CalId>
    </Result>
</MeetingResponse>

ResponseTime : 
02/28/2013 17:23:23

Log Breakdown

Let's break down the log starting from the top.

Log Entry This is a sequential entry number, starting at 0.
RequestTime This is the time the request entered Exchange code, and is in the server’s time zone.
ServerName This is the CAS that is ultimately processing the request.
AssemblyVersion The version of the AirSync assembly that the AirSyncHandler in IIS calls into. Specifically, x:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\Sync\Bin\AirFilter.dll
Identifier A unique hexadecimal number identifying the specific request/response pair.
RequestHeader This is the full HTTP header with redacted auth. This will show if the connection is being proxied, etc.
RequestBody This is the decoded WBXML sent from the EAS device. Consider this the raw request from the client.
LogicalRequest The parsed, complete XML request. This includes some optional elements that are not required, and show the default or implied settings.
AccessState The access state for this specific device. Allowed, Blocked, etc.
AccessStateReason The reason for the access state above. Global, Individual, etc.
ResponseHeader The HTTP header sent by Exchange. This is pre-IIS, and IIS may add its own headers before sending the set to the client.
ResponseBody The XML response to be sent to the device. This will be compressed into WBXML before hitting IIS.
ResponseTime The time the response exited Exchange code and was sent to IIS.

 

I’m going to jump down to the RequestBody, since the RequestHeader is mostly just HTTP information – the HTTP verb used, the user-agent, etc. The only lines that are normally important here are the X-MS-PolicyKey and User-Agent headers. Most everything else is going to be edge-case.

The RequestBody:

 RequestBody : 
<?xml version="1.0" encoding="utf-8" ?>
<MeetingResponse xmlns="MeetingResponse:">
    <Request>
        <UserResponse>1</UserResponse>
        <CollectionId>1</CollectionId>
        <RequestId>1:653</RequestId>
    </Request>
</MeetingResponse>

Ignore <?xml>, that's the XML header.  The next tag is <MeetingResponse xmlns="MeetingResponse:">, which we'll cross-reference with the protocol.  This is where I find many people hit a wall.

Note: You can mostly ignore the xmlns.  The xmlns is the XML namespace, which at a high level specifies the specific type of MeetingResponse, and is defined in the schema , which is also in the protocol documentation.

Start at the MeetingResponse command itself. From there, we’ll drill down into the element we care about.

MeetingResponse -> MeetingResponse element -> Request element. Notice there is the Request and the Response. Now we see the “meat” of the request. The Child elements column here lists the elements with the data we care about based on the request we see in the log. UserResponse, CollectionId, and RequestId are all here.

UserResponse – 3 possible values, indicating whether the meeting is being accepted, tentatively accepted, or declined. This request has a UserResponse of 1, meaning the meeting request was Accepted.

CollectionId – String value specifying the folder that contains the meeting request. This value is obtained from a previous FolderSync (or FolderCreate) command response. If you miss those commands, you’ll have to make assumptions on what folder it’s referencing, but if you have access to the mailbox you can determine the mapping through a process detailed in a blog posting by Jim Martin.

The first FolderSync for the device will pull a folder list that is alphabetized, and the CollectionId is sequential. So for example, in a new mailbox, Calendar would be CollectionId 1, Contacts would be CollectionId 2, and so on.

If the folders change after the FolderSync, the change to the FolderHierarchy is sent to the device, but the CollectionId just increments the number. So the newest folder gets the largest number. If the device partnership is reset, then the newest folder gets a CollectionId that is in the proper alphabetical order.

RequestId – String value specifying the server ID of the meeting request message item. Notice the format here is colon-separated. FolderId:ItemId:AttachmentId. In this case the CollectionId is 1, so the RequestId is 1:653.

The ItemId here acts much like the CollectionId above. The number increments in the partnership, but on a new sync, the items will all be in sequential order. Unlike the FolderHierarchy, these items are not alphabetized, but in chronological order. The first item in the box (oldest) will be ItemId 1.

Note: ServerId, RequestId, and CalendarId (CalId in the log) are all specifying the server ID of the items.  For some commands such as Sync, FolderSync, etc you'll see ServerId instead of the latter two, and its meaning may differ depending on its context.

See [MS-ASCMD] 2.2.3.151 ServerId for more details.

The server will process the request, and send the response as shown in the ResponseBody:

 ResponseBody : 
<?xml version="1.0" encoding="utf-8" ?>
<MeetingResponse xmlns="MeetingResponse:">
    <Result>
        <RequestId>1:653</RequestId>
        <Status>1</Status>
        <CalId>1:654</CalId>
    </Result>
</MeetingResponse>

Most of the outlining structure is the same, so start with the RequestId here. Starting at the MeetingResponse command again, drill down to MeetingResponse -> MeetingResponse element -> Result element. Now we see the RequestId, Status, and CalendarId sections.

RequestId – String value specifying the server ID of the meeting request message item. The Id is 1:653, corresponding to the RequestId in the request.

Status – 4 possible values, indicating the success or failure of the MeetingResponse command. In this example the status is a 1, meaning the request was successful.

CalendarId – String value specifying the server ID of the calendar item (instead of the message object associated with the calendar item). If the meeting request is accepted, the server ID of the calendar item is returned, and is the new server ID. If you were to follow the conversation you’d see the server delete the old ID (1:653) and send down the updated 1:654 item.

Every request command and response is analyzed in a similar manner. Cross-reference the XML with the protocol docs, and use the view on the device and OWA/Outlook to visually see what’s going on. You can also mix this with message tracking logs, IIS logs, and other tools and data that we’ll delve into later.

Jason Slaughter