A script to troubleshoot issues with Exchange ActiveSync

[The_Exchange_Team]

You can download the script, which has been attached to this blog post.

The Exchange support team relatively frequently receives cases where mobile devices using Exchange ActiveSync (EAS) protocol send too many requests to Exchange server resulting in a situation where server runs out of resources, effectively causing a ‘denial of service’ (DOS) attack. The worst outcome of such a situation is that the server also becomes unavailable to other users who may not be using EAS protocol to connect. We have documented this issue with possible mitigations in the following KnowledgeBase article:

2469722 Unable to connect using Exchange ActiveSync due to Exchange resource consumption

A recent example of this issue was Apple iOS 4.0 devices retrying a full sync every 30 seconds (see TS3398). Another example could be some devices that do not understand how to handle a ‘mailbox full’ response from the Exchange server, resulting in several tries to reconnect. This can cause such devices to attempt to connect & sync with the mailbox more than 60 times in a minute, killing battery life on the device and causing performance issues on server.

Managing mobile devices & balancing available server resources among different types of clients can be a daunting challenge for IT administrators. Trying to track down which devices are causing resource depletion issues on Exchange 2010/2007 Client Access server (CAS) or Exchange 2003 Front-end (FE) server is not an easy task. As referenced in the article above, you can use Log Parser to extract useful statistics from IIS logs (see note below), but most administrators do not have the time & expertise to draft queries to extract such information from lengthy logs.

The purpose of this post is to introduce everyone in Exchange community to a new PowerShell script that can be utilized to identify devices causing resource depletion issue, help in spotting performance trends and automatically generate reports for continuous monitoring. Using this script you can easily & quickly drill into your users' EAS activity, which can be a major task when faced with IIS logs that can get up to several gigabytes in size. The script makes it easier to identify users with multiple EAS devices. You can use it as a tool to establish a baseline during periods of normal EAS activity and then use that for comparison and reporting when things sway in other directions. It also provides an auto-monitoring feature which you can use to receive e-mail notifications.

Note: The script works with IIS logs on Exchange 2010, Exchange 2007 and Exchange 2003 servers.
All communication between mobile devices using EAS protocol and Microsoft Exchange is logged in IIS Logs on CAS/FE servers in W3C format. The default W3C fields enabled for logging do vary between IIS 6.0 and 7.0/7.5 (IIS 7.0 has the same fields as 7.5). This script works against both versions.

IIS Logs

Because EAS uses HTTP, all EAS requests are logged in IIS logs, which is enabled by default. Sometimes administrators may disable IIS logging to save space on servers. You must check whether logging is enabled or not and find the location of log files by following these steps:

IIS 7

1. In IIS Manager, expand the server name i.e. ExchangeServer (Contoso\Administrator)
2. In the Features View, double click Logging in the IIS section.

IIS 6

1. In IIS Manager, right click the web site name (for most it should be Default Web Site) and choose Properties
2. Click on the Web Site tab.

What are mobile devices responsible for in communications with the server?

Before we delve into the specifics of the script, let's review some important requirements for mobile devices that use EAS to communicate with Microsoft Exchange.

• When a mobile device is returned an unexpected response from server, it's up to the device to handle the response and retry appropriately at a reasonable interval. Additionally, devices are responsible for handling timeouts that happen outside of IIS, which may be caused by network latency.
• With each request a device sends to IIS/Exchange, it should also report the User-Agent.

What will you see when you use this script?

The script utilizes Microsoft Log Parser 2.2 to parse IIS logs and generate results. It creates different SQL queries for Log Parser based on the switches (see table below) you use. A previous blog post Exchange 2003 - Active Sync reporting talking about Log Parser that touches on similar points. The information in that post still applies to Exchange 2010 & 2007. Since that blog post, additional commands were added to EAS protocol), which are also utilized by this new script while processing the logs.

Here's a list of the EAS commands that the script will report in results:

Sync, SendMail, SmartForward, SmartReply, GetAttachment, GetHierarchy, CreateCollection, DeleteCollection, MoveCollection, FolderSync, FolderCreate, FolderDelete, FolderUpdate, MoveItems, GetItemEstimate, MeetingResponse, Search, Settings, Ping, ItemOperations, Provision, ResolveRecipients, ValidateCert

For more details about each EAS command, see ActiveSync HTTP Protocol Specification on MSDN.

In addition to these commands, the following parameters are also logged by the script.

1. User
2. User Name
3. Device Type
4. Device ID
5. User-Agent
6. sc-bytes: This is only available if you have enabled this tag in IIS logging.
7. cs-bytes:This is only available if you have enabled this tag in IIS logging.
8. time-taken (in milliseconds): This is only available if you have enabled this tag in IIS logging.
9. Total number of requests or requests by Device ID
10. Total number of all 4xx status codes
11. Total number of all 5xx status codes (for more info, see KB: 318380 for IIS 6.0 & KB: 943891)
12. 409 status codes: 409 (Conflict) - A collection cannot be made at the Request-URI until one or more intermediate collections have been created. The server MUST NOT create those intermediate collections automatically (Ref: RFC 4918)
13. 500 status codes: After device sends OPTIONS command, it’s possible to get a 500 response back from server with ‘MissingCscCacheEntry’ error. This can happen as a result of an issue with the affinity where you have an Internet-facing CAS array proxying a request to an Internal CAS array. When the Internet-facing array sends the request to the Internal array, a CAS server will answer with the first 401. In the next communication, the request is handled by a different CAS server in the Internal array. Resolving the affinity issue with the Internal CAS array is the solution.
14. 503 status codes: The server is currently unable to handle the request due to a temporary overloading or maintenance of the server. The implication is that this is a temporary condition which will be alleviated after some delay. If known, the length of the delay MAY be indicated in a Retry-After header. If no Retry-After is given, the client SHOULD handle the response as it would for a 500 response.

    Note: The existence of the 503 status code does not imply that a server must use it when becoming overloaded. Some servers may wish to simply refuse the connection. (Ref: RFC 2616)

15. 507 status codes: The 507 (Insufficient Storage) status code means the method could not be performed on the resource because the server is unable to store the representation needed to successfully complete the request. This condition is considered to be temporary. If the request that received this status code was the result of a user action, the request MUST NOT be repeated until it is requested by a separate user action. (Ref: RFC 4918)
16. 451 status codes: Exchange 2007/2010 returns an HTTP 451 response to an EAS client when it determines that the device should be using a ‘better’ CAS for EAS connectivity. The logic used to determine ‘better’ CAS is based on Active Directory sites and whether a CAS is considered ‘Internet-facing’. If the ExternalUrl property on the Microsoft-Server-ActiveSync virtual directory is specified, then that CAS is considered to be Internet-Facing for EAS connectivity. (Ref: TechNet articles Exchange ActiveSync Returned an HTTP 451 Error and Understanding Proxying and Redirection)
17. TooManyJobsQueued errors: For more info on ‘TooManyJobsQueued’ please refer to KB: 2469722 referenced above
18. OverBudget: A budget is the amount of access that a user or application may have for a specific setting. A budget represents how many connections a user may have or how much activity a user may be permitted for each one-minute period. (Ref: TechNet article)
19. Following subset of Common Status Codes:

    InvalidContent, ServerError, ServerErrorRetryLater, MailboxQuotaExceeded, DeviceIsBlockedForThisUser, AccessDenied, SyncStateNotFound, DeviceNotFullyProvisionable, DeviceNotProvisioned, ItemNotFound, UserDisabledForSync

What can you do with this script?

You can process logs using this script to retrieve the following details:

1. Hits by user/Device ID (users/devices with maximum number of requests sent to server)
2. Hits per hour/day (helps in determining the frequency of requests sent by user/device, time value is entered in seconds)
3. Hits by device with specified threshold limit (here you can specify a limit for hits/requests, i.e. all users who are sending 1000 requests per hour/day, etc.)
4. CSV export of results
5. HTML report of results
6. E-mail reports for monitoring (CSV/HTML formats)

Prerequisites:

Please make sure you have the following installed on your machine before using this script:

• Log Parser 2.2.
• Windows PowerShell 2.0 (installed by default on Windows 7 & Windows 2008 R2)

Script Parameters

Parameter	Required	Type	Description
ActiveSyncOutputFolder	Required	System.String	CSV and HTML output directory
ActiveSyncOutputPrefix	Optional	System.String	Prefixes string to the output file name
CreateZip	Optional	System.Management. Automation.SwitchParameter	Creates a ZIP file. Can only be used with SendHTMLReport
CreateZipSize	Optional	System.In32	Threshold file size. The Default is 2MB. Once this has been exceeded the file will be compressed. Requires SendHTMLReport and CreateZip to be true
Date	Optional	System.String	Specify a date to parse on. Enter date in the format: MM-DD-YYYY
DeviceId	Optional	System.String	Active Sync Device ID to parse on
DisableColumnDetect	Optional	System.Management. Automation.SwitchParameter	Disables the ability to add additional columns to the report that users may have enabled, Example: time-taken Note: If you are running against multiple files that may have different W3C headers this switch should be used.
Help	Optional	System.Management. Automation.SwitchParameter	Outputs switch descriptions
ReportBySeconds	Optional	System.Int32	Generates the report bases in the value entered in seconds
Hourly	Optional	System.Management. Automation.SwitchParameter	Generates the report on a per hourly basis
HTMLReport	Optional	System.Management. Automation.SwitchParameter	Creates an HTML Report
HTMLCSVHeaders	Optional	System.String	IIS CSV Headers to Export on in the –HTMLReport. Defaults: "DeviceID,Hits,Ping,Sync,FolderSync,DeviceType,User-Agent"
IISLogs	Required	System.Array	IIS Log Directory. Example.- IISLogs D:\Server,'D:\Server 2'
LogParserExec	Required	System.String	Path to LogParser.exe
MinimumHits	Optional	System.Int32	Minimum Hit Threshold value where the report will generate on CSV and HTML
SendEmailReport	Optional	System.Management. Automation.SwitchParameter	Enable Email reporting
SMTPRecipient	Optional	System.String	SMTP Recipient
SMTPSender	Optional	System.String	SMTP Sender
SMTPServer	Optional	System.String	SMTP Server
TopHits	Optional	System.Int32	Top Hits to return. Example: TopHits 50, This cannot be used with Hourly or ReportBySeconds

How do you use the script?

Below are some examples (with commands) on how you can use the script and why you might use them.

Hits greater than 1000

The following command will parse all the IIS Logs in the folder W3SVC1 and only report the hits by users & devices that are greater than 1000.

.\ActiveSyncReport.ps1 -IISLog "C:\inetpub\logs\LogFiles\W3SVC1" -LogparserExec “C:\Program Files (x86)\Log Parser 2.2\LogParser.exe” -ActiveSyncOutputFolder c:\EASReports -MinimumHits 1000

[In above command, script ‘ActiveSyncReport.ps1’ is located at the root of C drive, -IISLog switch specifies the default location of IIS logs, -LogparserExec switch points to the location of Log Parser executable application file, -ActiveSyncOutputFolder switch provides the location where output or result file needs to be saved, MinimumHits with a value of ‘1000’ is the script parameter explained in the above table]

Output:

Usually if a device is sending over 1000 requests per day, we consider this ‘high usage’. If the hits (requests) are above 1500, there could be an issue on the device or environment. In that case, the device & its user’s activity should be further investigated.

As a real world example, in one case we noticed there were several users who were hitting their Exchange server via EAS a lot (~25K hits, 1K hits per hour) resulting in depletion of resources on the server. Upon further investigation we saw that all of those users’ requests were resulting in a 507 error on mailbox servers on the back-end. Talking to those EAS users we discovered that during that time period they were hitting their mailbox size limits (25 MB) & were trying to delete mail from different folders to get under the size limit. In such situations, you may also see HTTP 503 (‘TooManyJobsQueued’) responses in IIS logs for EAS requests as described in KB: 2469722

Isolating a specific device ID

Here the following command will parse all the IIS Logs in the folder C:\IISLogs and will look for the Device ID xxxxxx and display its hourly statistics.

.\ActiveSyncReport.ps1 -IISLog " C:\inetpub\logs\LogFiles\W3SVC1" -LogparserExec “C:\Program Files (x86)\Log Parser 2.2\LogParser.exe” -ActiveSyncOutputFolder c:\EASReports –DeviceID xxxxxx -Hourly

Output:

With the above information you can pick a user/device and see the hourly trends. This can help identify if it’s a user action or a programmatic one.

As a real world example, in one case we had to find out which devices were modifying calendar items. So we looked at the user/device activity and sorted that by different commands they were sending to the server. After that we just concentrated on which users/devices were sending ‘MeetingResponse’ command and its frequency, time period & further related details. That helped us narrowing the issue to related users and their calendar specific activity to better address the underlying calendaring issue.

Another device related command & error to look for is ‘Options’ command and if it does not succeed for a device then the HTTP 409 error code is returned in IIS log.

Isolating a single day

The following command will parse only the files that match the date 12-24-2011 in the folder W3SVC1 and will only report the hits greater than 1000.

.\ActiveSyncReport.ps1 -IISLog "C:\inetpub\logs\LogFiles\W3SVC1" -LogparserExec “C:\Program Files (x86)\Log Parser 2.2\LogParser.exe” -ActiveSyncOutputFolder c:\EASReports -MinimumHits 1000 –Date 12-24-2011

Output:

With the above information you can identify users sending high number of requests. Also, within the columns, you can see what kind of commands those users are sending. This helps in coming up with more directed & efficient troubleshooting techniques.

What Should You Look For?

When analyzing IIS logs with the help of script, you should look for one specific command being sent over and over again. The frequency of particular commands being sent is important, any command failing frequently is also very important & one should further look into that. We should also look & compare the wait times between the executions of certain commands. Generally, commands taking longer time to execute or resulting in delayed response from server will be suspicious & should be further investigated. Keep in mind though, the Ping command is an exception as it takes longer to execute and you will see it frequently in the log as well, which is expected.

If you notice continuous failures to connect for a device with an error code of 403 that could mean that the device is not enabled for EAS based access. Sometimes mobile device users complain of connectivity issues not realizing that they’re actually not entering their credentials correctly (understandably it’s easy to make such mistakes on mobile devices). When looking thru logs, you can focus on that user & may find that user’s device is failing after issuing the ‘Provision’ command.

Creating Reports for Monitoring

You may want to create a report or generate an e-mail with such reports and details of user activity.

The following command will parse all the IIS Logs in the folder W3SVC1 and will only report the hits greater than 1000. Additionally it will create an HTML report of the results.

.\ActiveSyncReport.ps1 -IISLog "C:\inetpub\logs\LogFiles\W3SVC1" -LogparserExec “C:\Program Files (x86)\Log Parser 2.2\LogParser.exe” -ActiveSyncOutputFolder c:\EASReports -MinimumHits 1000 -HTMLReport

The following command will parse all the files in the folders C:\Server1_Logs and D:\Server2_Logs and will also email the generated report to ‘user@contoso.com’.

.\ActiveSyncReport.ps1 -IISLog "C:\Server1_Logs",”D:\Server2_Logs” -LogparserExec “C:\Program Files (x86)\Log Parser 2.2\LogParser.exe” -ActiveSyncOutputFolder c:\EASReports -SendEmailReport -SMTPRecipient user@contoso.com –SMTPSender user2@contoso.com -SMTPServer mail.contoso.com

We sincerely hope our readers find this script useful. Please do let us know how these scripts made your lives easier and what else can we do to further enhance it.

Konstantin Papadakis and Brian Drepaul

Special Thanks to:
M. Amir Haque, Will Duff, Steve Swift, Angelique Conde, Kary Wall, Chris Lineback & Mike Lagase

ActiveSyncReport.zip