Under The Hood: Exchange ActiveSync Mailbox Log Analysis
Published Oct 04 2013 09:06 AM 72.1K Views

Note: Part 2 of this series can be found here.

One of best troubleshooting tools for Exchange ActiveSync (EAS) is mailbox logging. This logging allows us to see the incoming request sent by the device and the outgoing response from the Exchange server. Exchange ActiveSync Mailbox Logging provides the steps for enabling ActiveSync mailbox logging and breaks down the components of the log. Here we're going to use one of these logs to analyze how a mobile device running an EAS client (for e.g. a Windows Phone) initializes a profile with Exchange and a few standard commands.

Provision

A device must be provisioned before it can synchronize with Exchange. The device sends the Provision command with the device settings contained within the request. The server response includes the security settings based on the ActiveSync mailbox policy associated with the mailbox. It is important to note now that there are two status codes for most ActiveSync requests. The HttpStatus code only provides the IIS response to the request, and a 200 response does not mean the request was successful. The second status code is for the ActiveSync command and varies depending on the command sent by the device. A status code of 1 is most commonly a success.

image

The following example shows the request and response from a Provision command:

image

image

The device sends another Provision command to complete the provisioning process.This request includes the policy key from the previous response. The following example shows the second Provision command sending the PolicyKey.

image

For more detailed analysis of EAS provisioning process & Policies, see Provisioning, Policies, Remote Wipe, and ABQ in Exchange ActiveSync on The Exchange Dev Blog.

FolderSync

Once the device is provisioned, it will send a FolderSync command to obtain the folder hierarchy of the mailbox. If you capture this FolderSync request in the ActiveSync mailbox log, you will have the folder name that correlates to the CollectionId values in future ActiveSync requests. Alternatively, see ActiveSync - Mapping a Collection ID to a Mailbox Folder to determine which folder the CollectionId represents. The following example shows the response from a FolderSync request:

image

Sync

After the EAS client has obtained the folder hierarchy of the mailbox from Exchange, it can begin to populate folders on the device . Windows Phone leverages a hanging Sync request to retrieve data from these folder. We should however expect the first Sync request by this device to have an immediate response with new items for one or more folders. It is also important to notice the SyncKey sent by the device in this first request is 0. This is because the folders (have just been created on the device and) currently have no synchronization state. The response for each Sync request will include a new SyncKey value that the subsequent Sync request should send. The following example shows the request and response for a Sync command:

image

image

We will typically either see no status code or a status code of 1 in the response for a Sync request. Any other status code would require further investigation by reviewing the protocol document. A status code of 1 represents a successful Sync request and no status code simply means there were no changes within the heartbeat interval for the request.

Typically you will see items being added to the device in the Sync response. You can see detailed information including the sender and subject if verbose logging has been enabled on the CAS servers. The following example shows a response sending a new item to the Inbox:

image

ItemOperations

There are several uses for the ItemOperations command and one of the most common requests is for downloading an attachment onto the device. The request will contain the FileReference value for the attachment which can be seen in the Sync response if available. The following examples show two responses for the ItemOperations command. We can see the first response is a success and the server sending the attachment. However the second response throws an exception and has a different status code. Lookup this status code in the protocol documentfor more information on the exception.

image

image

Were you able to determine the issue? The exception within the ActiveSync mailbox log for this example does provide enough detail to know the attachment was too large. It is very important to know how to use the protocol document to look up status codes for the various ActiveSync commands.

Calendaring

Now that we have covered the most common command that will be found in the ActiveSync mailbox log (that is the Sync command), it is now time to dig a little bit deeper. One of the most common issues with ActiveSync devices is calendaring. Most ActiveSync users rely on their mobile device to have accurate calendar information so they do not miss an appointment. Calendar items can be added to a mailbox as either an appointment created by the mailbox or a meeting request sent by either the mailbox owner or another organizer.

We are going to review the life of an appointment as we find it within the ActiveSync mailbox log. This appointment will start as a meeting request sent by an organizer within the organization. The following example shows a Sync response where this appointment is first added to the device:

image

image

Here we can see the appointment has a unique ServerId value for this item on the device. We also know that the appointment is currently showing a status of tentative in the BusyStatus. This is the standard placeholder that Exchange creates in the calendar when a new meeting request is received. The following example shows the corresponding meeting request:

image

The complex part of this process begins when the user responds to the appointment on the device. This response results in several requests which include MeetingResponse, SendMail, MoveItems, and Sync commands. We are going to cover each of these steps to see how the commands impact the items on the device and within the mailbox.

image

The MeetingResponse command is in the first ActiveSync command sent by the device to accept, decline, or tentatively accept the meeting. This request does not sent the response to the organizer. The request includes the meeting request item within the Inbox the response is for while the response from the Exchange server also includes the appointment item. The following examples show the request and response for a MeetingResponse command:

image

The SendMail command is the response message sent back to the organizer. The following is an example of the request for a SendMail command:

image

The MoveItems command is sent by the device to move the meeting request item from the Inbox to the Deleted Items folder. The following example shows the request for a MoveItem command:

image

The Sync command is sent by the device to update the calendar item on the mailbox. This Sync request is sending a Change for the appointment to update this status from Tentative to Busy. The following example shows the request sending a change for the BusyStatus:

image

You may also notice another Sync command sent by the device and that the response includes an Add for the Sent Items folder. Here we are getting the meeting acceptance message from the Sent Items and adding in onto the device.

image

Meeting Updates

All that we just covered was the original meeting request being received by the device. That is the origin of the appointment for our example. Next we need to look at how this appointment changes as time moves forward. The next evolution in this appointment’s life is a when the organizer sends an update for a single instance of the series.

A change to a recurring appointment is called an exception and that is exactly what we will see in the ActiveSync mailbox log. The first part of the response shows us that we have a Change for an item and further down within that response we will see the exceptions. The following example shows our appointment receiving a change and the exception includes a new start time:

image

image

Wait. Our appointment has not stopped experiencing life changes. The organizer has decided to cancel an instance of this recurring appointment. The following example once again shows a change for our appointment but this time the exceptions have grown. This example was done intentionally so we can see how difficult it becomes to read these logs when an appointment has a large number of exceptions.

image

image

The good news is these exceptions are sent in the order in which they were made, so the last exception is the most recent. In our example above, the last exception shows this instance of the meeting has been canceled.

The focus has intentionally been on the Calendar item and its changes. However we cannot forget that with each change to the appointment the user also gets an updated meeting request. This means we will also see a Sync request that includes a response adding the meeting request to the Inbox. The following example shows the response adding the updated meeting request:

image

Just like the original meeting request for the series, the user has the ability to accept and decline the changes from the device. If you do not remember the process, don’t hesitate to jump back and take a second look. That is exactly what this article is intended to show.

SendMail

The last topic we are going to cover is sending a message from a Windows Phone device. There are two commands that we may see from an ActiveSync device when a user is sending a message. The Search command will be sent when a user types text into the To field and perform a search against the Global Address List. The following examples show a request and response for a Search command:

image

image

Then the device will send a SendMail command when the user hits the Send icon. Unless an error is encountered during this request there should be an empty response from the Exchange server. The following example shows a request for the SendMail command:

image

Conclusion

At this point you should have some understanding of how Exchange ActiveSync functions and what to look for in the ActiveSync mailbox log. Here are a few reminders:

  • Whenever the device initiates a new item or change, the request from the device will contain this data. Whenever the change is made on the mailbox, the response from the Exchange server will contain the data.
  • Windows Phone uses a hanging Sync command to wait for changes on the mailbox. This request contains a heartbeat interval which determines how long the server should wait before sending a response. A success will return a status code of 1 indicating there are changes. If there are no changes, then no status code is returned.
  • An updated meeting contains all of the exceptions for that appointment and the last exception is the most recent.
  • Accepting a meeting request on an EAS device is a complex process with multiple steps. It is recommended that you review this process if many users use their devices to accept meetings.
  • Current versions of Exchange require a minimum search length of four characters before Exchange will perform the query.
  • The SendMail command does not return a status code unless an error is encountered.

Jim Martin (EXCHANGE)

5 Comments
Version history
Last update:
‎Jul 01 2019 04:15 PM
Updated by: