Jason Slaughter

Rock the CAS box!

Exchange ActiveSync Mailbox Logging

Exchange ActiveSync Mailbox Logging

  • Comments 20
  • Likes

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 under Options -> Phone -> Mobile Phones.

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:

Get-ActiveSyncDeviceStatistics -Mailbox alias -GetMailboxLog:$true -NotificationEmailAddress 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-2013, 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 have truncated tags.  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, 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.

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. 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.



Figure 1: OWA / ECP EAS Logs

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’re troubleshooting some specific issue you likely already know which folder this is.

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

Comments
  • Jason - any thoughts on how to clean out or roll a Mailbox log for a given Exchange account after ActiveSyncDebugLogging has been set to true?  I was hopeful that toggling the value from true, back to false, then to true again would zero the log out.  No luck as far as I can see.

  • There is no graceful method to do this.  The quickest way for a per-person deletion of these logs would be to use MFCMAPI (technet.microsoft.com/.../bb508857.aspx) and delete the messages from the EAS device's folder in the mailbox.

    Make sure the MAPI profile is not in cached mode, and look for the folder off the "Root Container" named AirSync deviceType_deviceId.  Double-click that folder and just delete all the messages in there.  Those messages each represent a Request/Response pair.

  • Hi Jason, I work on an IT Helpdesk and have a user with a Samsung Galaxy S2 using Android 4.0.4. She can sync her e-mail just fine, however whenever she wants to view her Exchange Calendar she gets a "Connection Error (Exchangeaccount)". I added an appointment to her Exchange calendar and it doesn't sync to her Outlook on her Desktop. Apparently she has already taken the phone to US Cellular about this issue to get the phone factory reset and that hasn't helped. We also removed, and re-added the account, accepted the Security Settings and the email still syncs fine but not the Calendar. I turned on logging in OWA for a few days and have a 4MB EASMailboxLog_joans_SAMSUNGSCHR760_SAMSUNG3A0000030DD1F7E.txt file, what would be your suggestion to analyze this log file, I searched for MS-ASCAL and didnt find anything, I also searched for "Calendar" and am trying to figure out this XML. Any suggestions or websites you can point me in the direction in? Thanks for the article!

  • Oh yea, and if she hooks up her phone to her desktop via USB then she can sync her Outlook Calendar then! Not sure what she is using to accomplish this, I had stopped by her office on Friday and discovered she could sync her Exchange Calendar fine only if she had it hooked up to her Desktop via USB, I should have asked her what APP, setting she has active to accomplish that.

  • I'm not sure how she's connecting now, but it sounds like some form of desktop sync.  Desktop sync is not going to be using EAS.

    As for the issue at hand, look for Server IDs that start with 1.  Generally the Calendar folder will be Server ID 1 because it's the first folder alphabetically.  If you don't see <Ping>s or <Sync>s with a <CollectionId>1</CollectionId> then we're not seeing a request for that folder.

    I may need to add more request examples to this post, but for now you should review the Direct Push feature (technet.microsoft.com/.../aa997252(v=exchg.141).aspx).  That will go over what commands the device should be sending to actually sync down data.

    Lastly, you mention the meeting doesn't show up in Outlook on her desktop.  Does it appear in OWA?  If not, then you may have a different issue altogether, and at that point you'll likely need to open a support case with us.

  • Great article!

  • Great. A goldmine of information for our Blackberry 10 devices. Elsa Braun, Milwaukee

  • Hi Jason, I have a question about the anatomy of a log line for EAS itself. Its for the Cmd=Sync, specifically I cant figure out what the following are in the logline below:
    Log=V140_Fc1_Fid:5_Ty:Em_Filt5_St:S_Sk:846468582_Sst55_SsCmt55_Srv:1a0c0d0s0e0r0A0sd_BR1_BPR0_LdapC2_LdapL16_Hb900_Mbx

    Most I have been able to address but what specifically are these in the above?
    _Sst55
    _SsCmt55
    _BR1
    _BPR0
    _LdapC2
    _LdapL16
    _Hb900

    Any help or links you can provide would be highly appreciated.
    Thanks

    Penny

  • Jason, thanks for the info, however, for Exchange 2007 the info is not clear to me. For Ex2007 does that mean I only have to enable it on the server via web.config file and I don't have to enable per user? Or do I have to enable both per user and each cas server? Is there a separate log file created or is the data appended to the IIS log. How big do these files get? Thanks

  • @Joe: I went back and clarified in the blog that in Exchange 2007 it is per-server. The per-user ability is not present in Exchange 2007, so yes, you have to enable that across all CAS the user in question could connect to. Generally I use WiFi and a local connection when I'm investigating if possible.

    ---

    @PWendt: Most of the protocol log information can be found here: http://technet.microsoft.com/en-us/library/bb201675

    ---

    The below items will cover the rest:
    ---
    Sst55 -> The SyncState size is 55KB,
    SsCmt55 -> The SyncState size that has been committed to the mailbox is 55KB,
    BR1 -> The body of the message has been requested (0=False, 1=True),
    BPR0 -> The body part requested. I think this has to do with MIME parts,
    LdapC2 -> The request took 2 ldap calls,
    LdapL16 -> The ldap latency averaged 16ms

  • Jason - Great article! One question I have is for 2007, we enable across each cas, but then can we toggle per user on and off?

    Thanks

  • @Tom - Nope, enable per CAS in 2007, and it'll be enabled for everyone who hits that CAS -- no per-user logging in 2007. That also means if an EAS device hits one CAS for one request, and another for the next -- you'll only log on the CAS that gets the request. So make sure it's enabled across the board if you're using NLB and don't have affinity configured correctly.

Your comment has been posted.   Close
Thank you, your comment requires moderation so it may take a while to appear.   Close
Leave a Comment