EWS Managed API is lying to me!

I have been working with Exchange Web Services(EWS) for a long time and this is the first time I saw that the EWS was lying to me! The code was executing a FindItem call on a list of folders and all of a sudden it threw the following error: “Error occurred: The request failed. The remote server returned an error: (401) Unauthorized”.

Why would that happen? If it was an authentication problem then why did my previous call work? The first step was to check the IIS Logs on the CAS server and below is what we find:

 7/11/2012  10.171.230.40    POST /EWS/Exchange.asmx    SoapAction=FindItem 443    ExchangeServicesClient/14.03.0067.001    200     63025
7/11/2012  10.171.230.40    POST /EWS/Exchange.asmx    SoapAction=FindItem 443    ExchangeServicesClient/14.03.0067.001    200     21809
7/11/2012  10.171.230.40    POST /EWS/Exchange.asmx    SoapAction=FindItem 443    ExchangeServicesClient/14.03.0067.001    302     196752
7/11/2012  10.171.230.40    POST /EWS/Exchange.asmx    SoapAction=FindItem 443    ExchangeServicesClient/14.03.0067.001    302     196643

I chose to show only the relevant columns above. I you notice the highlighted values, the 302 is the HTTP Status code which means that the object has been temporarily moved. The last column is the time taken in milliseconds to execute the FindItem request. In the above case it was more than 3 minutes which is not good and means we have a LOTS of scope to optimize the code.

But, why do I get the 302? I turned my attention to the Event Logs on the CAS box and I did not have to search too much. Below is what I saw:

 Log Name:      Application
Source:        ASP.NET 2.0.50727.0
Date:          7/11/2012 12:58:05 PM
Event ID:      1309
Task Category: Web Event
Level:         Warning
Keywords:      Classic
User:          N/A
Computer:      myserver.contoso.com
Description:
Event code: 3001 
Event message: The request has been aborted. 
Event time: 7/11/2012 12:58:05 PM 
Event time (UTC): 7/11/2012 4:58:05 PM 
Event ID: 38a627eada914200923e244e9c83f7c8 
Event sequence: 6230694 
Event occurrence: 37 
Event detail code: 0 
 
Application information: 
    Application domain: /LM/W3SVC/1/ROOT/EWS-1-129851299999841294 
    Trust level: Full 
    Application Virtual Path: /EWS 
    Application Path: C:\Program Files\Microsoft\Exchange Server\ClientAccess\exchweb\EWS\ 
    Machine name: myserver
 
Process information: 
    Process ID: 1152 
    Process name: w3wp.exe 
    Account name: NT AUTHORITY\SYSTEM 
 
Exception information: 
    Exception type: HttpException 
    Exception message: Request timed out. 
 
Request information: 
    Request URL: https://myserver.contoso.com:443/EWS/Exchange.asmx 
    Request path: /EWS/Exchange.asmx 
    User host address: 10.171.230.40 
    User: DOMAIN\Username 
    Is authenticated: True 
    Authentication Type: Negotiate 
    Thread account name: NT AUTHORITY\SYSTEM 
 
Thread information: 
    Thread ID: 26 
    Thread account name: NT AUTHORITY\SYSTEM 
    Is impersonating: False 
    Stack trace: 

Now the picture is clearer! Since the request was running for more that 110 seconds which is default timeout in ASP.NET 2.0, the request was being aborted, which resulted in a 302 in the IIS logs. Now why did EWS Managed API return 401, frankly I did not bother to find!

To validate the cause we went ahead and increased the executionTimeout from 110 to 240 in the Web.Config for EWS and then we did not see the issue any more. This was done for TESTING only and is definitely not recommended.

There are two possible solutions to this issue:

1) Optimize your code and use filters and paging while doing FindItems (Recommended).

2) Increase the executionTimeout setting in the Web.Config(Not Recommended – can be tried only If optimization does not work ).

Enjoy!