Free/Busy troubleshooting

Article
01/04/2016

More about Free/Busy troubleshooting

The process, and how to check the logs

The purpose of this article is to help with Free/Busy troubleshooting, in case the steps from the guided walkthrough (https://support.microsoft.com/en-us/kb/2555008) did not help and you are somehow familiar with accessing IIS and Exchange logs. You can use the following steps to further investigate and get closer to the root cause of the issue.

This will not address any specific error due to the fact that there could be multiple reasons behind a F/B failure, however, most of the time, when we are talking about failed requests to on-premise mailboxes, the reasons behind the failures are caused by issues from the local organization.

So, this will mainly apply when free/busy information cannot be retrieved from an on-premise mailbox, however, the principles can be used in other scenarios.

To begin, first, you need to identify the error received by the requestor (user requesting FB information).

Checking the F/B error received in the client.

In order to do this, you need to connect to OWA (Outlook Web Access), using a browser of your preference and use the integrated debugging tools (most browsers have something similar, for example in Internet Explorer this feature can be accessed by pressing on F12 key).

The quickest way for this is to create a new appointment is to go in Scheduling Assistant, and before adding the on-premise user, enable Developer Tools (F12) in the browser, select Network tab and start the trace.

Now you can add the on-premise user, and wait for the error.

After the error is received (failure to get FB info), you can retrieve the error response code from the html response body of the GetUserAvailability request, like in the picture below.

The information in the response body should point you to where the error is generated, usually Autodiscover or EWS. In the above sample, the problem is with the Autodiscover access. What needs to be understood is that even if the Free/Busy, Autodiscover or EWS tests from https://testconnectivity.microsoft.com/ are successful, this does not mean that free/busy must work in a hybrid environment. This is because when performing FB requests, the authentication is done using WSSecurity and/or, recently and if enabled, using OAuth. Test Connectivity does not use any of those. It will only test if the endpoints are accessible authenticating with the entered credentials and test if FB information can be retrieved.

Now, if you have errors related to autodiscover, you can try to configure the TargerSharingEPR attribute in the requestor’s Organization Relationship configuration (in this case, in cloud) to point to the EWS URL (in this case, on-premise), this way autodiscover will be skipped and the requests will be sent directly to the ASUrl (Availability Service URL - EWS).

Below the command to do this:

Get-OrganizationRelationship | Set-OrganizationRelationship -TargetSharingEpr https://namespace.domain.tld/ews/exchange.asmx

The above command can be used if there is only one organization relationship, otherwise, you need to use the Set-OrganizationRelationship with the Identity parameter, containing the name of the relationship.

Note:

The same procedure to configure the TargetSharingEpr can be used when you create relationships between multiple organizations that have hybrid configurations. Because the availability requests cannot be proxied/redirected when the mailbox is located in the other organization than where the ASUrl is pointing, you need to decide to where you want to direct your requests (Cloud or OnPrem) and configure the TargetSharingEpr in order to bypass the Autodiscover response.

As we have the error and should know where the error is generated, we need to identify what causes the error. For this, you need to dive into the IIS and Exchange logs.

If the failure is related to Autodiscover, look for autodiscover errors in the IIS log, then in the Exchange log.

If the failure is related to the ASUrl and autodiscover passes, you should have a 200 http code on the autodiscover request in the IIS log (if the entry exists) and some different code (401, 500, 503, etc) in the EWS request.

In the following sections we'll see how this should be traced in the logs, depending on the authentication method used, infrastructure complexity and Exchange server versions, however, first we'll do a short recap on how F/B and Autodiscover works:

Some basics about how Autodiscover and F/B requests are processed

As there are multiple articles regarding connectivity that are quite elaborate, I will not do another one here as it is not the purpose of this article, but only mention a couple of things that I believe are worth to be reminded, and I will reference some of those articles, in case you need a reminder of the processes or just to have some clarification on those topics.

Here is an article explaining ‘Client Connectivity in an Exchange 2013 Coexistence Environment’ - https://blogs.technet.com/b/exchange/archive/2014/03/12/client-connectivity-in-an-exchange-2013-coexistence-environment.aspx

In the article there are some typical on-premise scenarios where Exchange 2007, 2010 and 2013 are present, how their virtual directories are (should) be configured, and most importantly, explains how the requests are passed from the client to CAS and Mailbox servers, based on how the environment is configured and where the mailbox is located. Based on this, you can identify on what servers you should look for the IIS/Exchange logs. The behavior is the same, regardless if DAuth (Federation using Microsoft Federation Gateway) or OAuth is used.

Next, in the following article is an explanation of how Cross Organization Availability using Federation Trust and Organization Relationship works, when there are 2003, 2007 and 2010 servers present: https://blogs.technet.com/b/exchange/archive/2011/06/28/cross-org-availability-using-federation-trust-and-organization-relationship.aspx

Now, as how and where the autodiscover and F/B requests are directed when sent to on-premise servers is clear (in case not, further below when we’ll look over the logs, it might get clearer), let’s go further and see some details about DAuth and OAuth.

DAuth:

Uses Microsoft Federation Gateway for Token generation
Organization Relationships:
Controls what companies you share information with
Allows for granular control of what features are available (free busy, mailtips)

OAuth:

Uses Auth Server in Azure AD (better resiliency and faster in forest communications)
IntraOrgConnectors / Configuration:
Controls what companies you can share information with
No granular control of feature-set (all or nothing)

When using OAuth, in a mixed deployment with Exchange 2013/2010 or Exchange 2013/2007, it is recommended that all the Internet-facing frontend servers for your on-premises organization are Client Access servers running Exchange 2013 with the latest SPs and updates.

All Exchange Web Services (EWS) requests originating from Office 365 and Exchange Online must connect to Exchange 2013 Client Access server(s) in your on-premises deployment.

Additionally, all EWS requests originating in your on-premises Exchange organizations for Exchange Online must be proxied through a Client Access server running Exchange 2013.

So, make sure that:

The frontend hybrid servers are Exchange 2013 with the latest SPs and updates
You have a unique external EWS URL for the Exchange 2013 server(s). The Office 365 tenant must connect to these servers in order for cloud-based requests for hybrid features to work correctly.
The servers have both the Mailbox and Client Access server roles
Any existing Exchange 2010/2007 Mailbox and Client Access servers have the latest Cumulative Update (CU) or Service Pack (SP) applied.

An AvailabilityAddressSpace must be configured, that points to the Exchange Web Services endpoint of your on-premises Exchange 2013 Client Access server(s). Usually, this is created when you run the HCW, however, if you’ve done some changes afterwards, it could be different, so you should check. This endpoint can be determined by running the following cmdlet on your on-premises Exchange Management Shell:

Get-WebServicesVirtualDirectory | FL AdminDisplayVersion,ExternalUrl

Note: If virtual directory information is returned from multiple servers, make sure you use the endpoint returned for an Exchange 2013 Client Access server. It will display 15.x (Build xxx.xx) for the AdminDisplayVersion parameter.

To configure the AvailabilityAddressSpace, use Exchange PowerShell and run the following cmdlet in your on-premises organization:

Add-AvailabilityAddressSpace -AccessMethod InternalProxy -ProxyUrl <your on-premises External Web Services URL> -ForestName <your Office 365 service target address> -UseServiceAccount $True

Having this said, there is an important thing that you must be aware of:

The order of checks and if OAuth is used or not:

1st we check to see if we can find the free busy locally

2nd (if the mailbox is not local) we check for an IOC (IntraOrganizationConnector)

3rd (if there is no IOC) we check for an Organization Relationship

4th we then check for an availability address space

If an IOC connector is found and enabled, the next checks will not be done, regardless if the OAuth request fails or not, or if you have a working Organization Relationship. There is no fall back done.

If the domain name for the user is listed in an IOC and the IOC is enabled, then yes, OAUTH will be used.

We will follow-up with a more elaborate article on troubleshooting OAuth configuration in the near future and update this article with the link to that. Now, let’s see the logs and try to follow the request as it is received by the CAS server.

IIS / Exchange logs used to identify Free/Busy requests

In order to better understand the following logs, here are the main properties of the environment used for this:

1 x Exchange 2013 CAS (EXCH2013) – this is the server where the public FQDN will point to (The Front End server if you wish…), 1 x Exchange 2013 MBX (EXCH2013MB), 1 x Exchange 2010 (all roles) (EXCH2010).

CloudUser@contoso.com – mailbox in O365

2010user@contoso.com and 2013user@contoso.com – mailboxes located on 2010 and 2013 servers

Below are the Virtual Directories configurations:

[PS] C:windowssystem32>Get-WebServicesVirtualDirectory |fl Server,*URL,*methods

Server : EXCH2010

InternalNLBBypassUrl : https://exch2010.contoso.com/ews/exchange.asmx

InternalUrl : https://exch2010.contoso.com/EWS/Exchange.asmx

ExternalUrl :

InternalAuthenticationMethods : {Ntlm, WindowsIntegrated, WSSecurity}

ExternalAuthenticationMethods : {Ntlm, WindowsIntegrated, WSSecurity}

Server : EXCH2013

InternalNLBBypassUrl :

InternalUrl : https://exch2013.contoso.com/EWS/Exchange.asmx

ExternalUrl : https://mail.contoso.com/ews/exchange.asmx

InternalAuthenticationMethods : {Ntlm, WindowsIntegrated, WSSecurity, OAuth}

ExternalAuthenticationMethods : {Ntlm, WindowsIntegrated, WSSecurity, OAuth}

[PS] C:windowssystem32>Get-AutodiscoverVirtualDirectory |fl server,*url,*hods

Server : EXCH2010

InternalUrl :

ExternalUrl :

InternalAuthenticationMethods : {Basic, Ntlm, WindowsIntegrated, WSSecurity}

ExternalAuthenticationMethods : {Basic, Ntlm, WindowsIntegrated, WSSecurity}

Server : EXCH2013

InternalUrl :

ExternalUrl :

InternalAuthenticationMethods : {Basic, Ntlm, WindowsIntegrated, WSSecurity, OAuth}

ExternalAuthenticationMethods : {Basic, Ntlm, WindowsIntegrated, WSSecurity, OAuth}

[PS] C:windowssystem32>Get-OutlookAnywhere |fl ServerName,*tname,*hod*

ServerName : EXCH2013

ExternalHostname : mail.contoso.com

InternalHostname : exch2013.contoso.com

ExternalClientAuthenticationMethod : Basic

InternalClientAuthenticationMethod : Ntlm

IISAuthenticationMethods : {Basic, Ntlm, Negotiate}

ServerName : EXCH2010

ExternalHostname : mail.contoso.com

InternalHostname :

ExternalClientAuthenticationMethod : Ntlm

InternalClientAuthenticationMethod : Ntlm

IISAuthenticationMethods : {Ntlm}

When you look for a log entry caused by a F/B request, in this case from Exchange Online, you need to look for ASAutoDiscover/CrossForest/EmailDomain for Autodiscover requests, and/or ASProxy/CrossForest/EmailDomain for EWS requests (the actual F/B call).

When the request is done using DAUTH, the IIS log entry looks like /autodiscover/autodiscover.svc/WSSecurity or /ews/exchange.asmx/WSSecurity (or similar), ending with WSSecurity.

When the request is done using OAuth, the entries will be like /autodiscover/autodiscover.svc or /ews/exchange.asmx. No WSSecurity!

The Exchange logs are usually located under the following paths, depending where the server was installed and if the paths were changed after installation:

C:Program FilesMicrosoftExchange ServerV14Logging for Exchange 2010

C:Program FilesMicrosoftExchange ServerV15LoggingHttpProxy - FrontEnd

C:Program FilesMicrosoftExchange ServerV15Logging - BackEnd

The subfolders, you should be interested in when troubleshooting availability issues are Autodiscover and EWS

And here are the actual logs, when a successful F/B request is done towards 2010 and 2013 mailboxes using both DAuth and OAuth. The response code is 200 for a successful request (some 401s are not necessarily a bad thing, if they are followed by a 200). The log entry date as well other relevant values were bolded or colored to be easier to identify the entry start or to follow the requests through the logs. The first request is the Autodiscover request, then, if the autodiscover was successful (or, if autodiscover was performed at all) the EWS request will follow. The autodiscover request is not always present (as we discussed previously), however, if both autodiscover and EWS requests are missing, something is wrong. So, when looking over the below logs, first you should follow the autodiscover entries, then the EWS ones. In a real scenario, if you see the expected EWS request present, then you could follow that directly. As we also seen in the above article ‘Client Connectivity in an Exchange 2013 Coexistence Environment’, autodiscover requests will (or, this will happen usually, as long there are more than one server in the environment) follow a different path.

Request from O365 using DAUTH to local mailbox:

2013 CAS - IIS log (this is the first place to look.):

2015-08-18 07:22:34 192.168.2.54 POST /autodiscover/autodiscover.svc/WSSecurity &CorrelationID=<empty>;&ClientId=FXJIEQ0ECEWJLSICTHA&cafeReqId=3065e411-79d2-4409-a1cf-5edd51ea3c79; 443 - 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 562

2015-08-18 07:22:36 192.168.2.54 POST /ews/2013user..contoso.com/exchange.asmx/WSSecurity &CorrelationID=<empty>;&ClientId=FNIFMXREWO9FQPJOJMA&cafeReqId=7d118c15-2050-446a-b9e2-5aad130589b5; 443 - 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 578

2015-08-18 07:22:40 192.168.2.54 POST /autodiscover/autodiscover.svc/WSSecurity &CorrelationID=<empty>;&ClientId=DVIDOBTMKYLWTXSVLMVQ&cafeReqId=318abd39-ad7e-4ad8-9b37-4d372a478969; 443 - 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 3187

2015-08-18 07:22:40 192.168.2.54 POST /ews/exchange.asmx/WSSecurity &CorrelationID=<empty>;&ClientId=DQXO0P9EFLPTFMNQ&cafeReqId=97c81648-5805-451b-8c85-4444e9a61593; 443 - 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 250

2013 CAS - Exchange HttpProxy – Autodiscover:

2015-08-18T07:22:34.720Z,3065e411-79d2-4409-a1cf-5edd51ea3c79,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc/WSSecurity,,,false,,contoso.com,Smtp~2013user@contoso.com,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2013mb.contoso.com,15.00.1104.000,IntraForest,AnchorMailboxHeader-SMTP,,,,9387,2105,1,,1,343,,0,5;,5,,0,5,,0,404,0,0,4,0,55,0,0,1,,0,403,0,56,343,347,348,404,,,,BeginRequest=2015-08-18T07:22:34.314Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1941996624;NewConnection=192.168.2.53&0;BeginGetRequestStream=2015-08-18T07:22:34.658Z;OnRequestStreamReady=2015-08-18T07:22:34.658Z;BeginGetResponse=2015-08-18T07:22:34.658Z;OnResponseReady=2015-08-18T07:22:34.720Z;EndGetResponse=2015-08-18T07:22:34.720Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T07:22:34.720Z;I32:ADS.C[DC]=1;F:ADS.AL[DC]=1.4897;I32:ATE.C[DC.contoso.com]=1;F:ATE.AL[DC.contoso.com]=0,

2015-08-18T07:22:40.752Z,318abd39-ad7e-4ad8-9b37-4d372a478969,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc/WSSecurity,,,false,,contoso.com,Smtp~2010user@contoso.com,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2010.contoso.com,14.03.0123.000,IntraForest,AnchorMailboxHeader-SMTP,,EXCH2010,94,9387,2163,1,,0,121,,0,1;,1,2;1;,3,4,,0,3042,0,0,3,0,2911,0,0,0,,0,3041,1,2916,128,131,131,3042,,,,BeginRequest=2015-08-18T07:22:37.705Z;CorrelationID=<empty>;ProxyState-Run=None;ServerLocatorCall=DM:76894869-7016-4bcc-b289-21c797b0b9eb~~contoso.com;DownLevelTargetHash=0/0/1;ClientAccessServer=EXCH2010.contoso.com;ResolveCasLatency=18;FEAuth=BEVersion-1937997947;ProxyToDownLevel=True;NewConnection=192.168.2.60&0;BeginGetRequestStream=2015-08-18T07:22:37.830Z;OnRequestStreamReady=2015-08-18T07:22:37.830Z;BeginGetResponse=2015-08-18T07:22:37.830Z;OnResponseReady=2015-08-18T07:22:40.736Z;EndGetResponse=2015-08-18T07:22:40.736Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T07:22:40.752Z;I32:ADS.C[DC]=8;F:ADS.AL[DC]=1.332662;I32:ADR.C[DC]=3;F:ADR.AL[DC]=1.1688;I32:ATE.C[DC.contoso.com]=10;F:ATE.AL[DC.contoso.com]=0,

2013 CAS - Exchange HttpProxy – EWS:

2015-08-18T07:22:36.033Z,7d118c15-2050-446a-b9e2-5aad130589b5,15,0,1104,2,1451abf2e5564582a9136a7269a96fc4,Ews,mail.contoso.com,/ews/2013user..contoso.com/exchange.asmx/WSSecurity,,,false,,contoso.com,Smtp~2013user@contoso.com,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2013mb.contoso.com,15.00.1104.000,IntraForest,ExplicitLogon-SMTP,,,,11241,2900,1,,8,0,,0,,0,,0,0,,0,581,0,0,4,0,567,0,0,1,,0,573,0,568,1,5,13,581,,,,BeginRequest=2015-08-18T07:22:35.455Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1941996624;NewConnection=192.168.2.53&0;BeginGetRequestStream=2015-08-18T07:22:35.470Z;OnRequestStreamReady=2015-08-18T07:22:35.470Z;BeginGetResponse=2015-08-18T07:22:35.470Z;OnResponseReady=2015-08-18T07:22:36.033Z;EndGetResponse=2015-08-18T07:22:36.033Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T07:22:36.033Z;S:ServiceCommonMetadata.Cookie=b81277cd1763434a92ea312ea0e7178f,

2015-08-18T07:22:41.142Z,97c81648-5805-451b-8c85-4444e9a61593,15,0,1104,2,f2832d5d5d1c444cb6ada7309af62f1d,Ews,mail.contoso.com,/ews/exchange.asmx/WSSecurity,,,false,,contoso.com,Smtp~2010user@contoso.com,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2010.contoso.com,14.03.0123.000,IntraForest,AnchorMailboxHeader-SMTP,,,,11205,3153,1,,0,0,,0,,0,,0,0,,0,244,0,0,3,0,238,0,0,0,,0,243,0,239,2,5,5,244,,,,BeginRequest=2015-08-18T07:22:40.892Z;CorrelationID=<empty>;ProxyState-Run=None;ServerLocatorRefresh=76894869-7016-4bcc-b289-21c797b0b9eb;RefreshingCacheEntry=CacheEntry(BackEndServer EXCH2010.contoso.com~1937997947|ResourceForest |LastRefreshTime 2015-08-18T07:12:09.5540489Z|IsSourceCachedData False);DownLevelTargetHash=0/0/1;ClientAccessServer=EXCH2010.contoso.com;ResolveCasLatency=0;FEAuth=BEVersion-1937997947;ProxyToDownLevel=True;NewConnection=192.168.2.60&0;BeginGetRequestStream=2015-08-18T07:22:40.892Z;OnRequestStreamReady=2015-08-18T07:22:40.892Z;BeginGetResponse=2015-08-18T07:22:40.908Z;NewConnection=192.168.2.60&0;OnResponseReady=2015-08-18T07:22:41.142Z;EndGetResponse=2015-08-18T07:22:41.142Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T07:22:41.142Z;S:ServiceCommonMetadata.Cookie=01ba785f583e4ca386834272d161c958,

MBX 2013 – IIS log:

2015-08-18 07:22:34 192.168.2.53 POST /autodiscover/autodiscover.svc/WSSecurity - 444 - 192.168.2.54 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 62

2015-08-18 07:22:35 192.168.2.53 POST /ews/exchange.asmx/WSSecurity - 444 - 192.168.2.54 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 593

MBX 2013 – Exchange Autodiscover log:

2015-08-18T07:22:34.481Z,3065e411-79d2-4409-a1cf-5edd51ea3c79,15,0,1104,2,,External,true,CloudUser@contoso.mail.onmicrosoft.com,,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013MB,EXCH2013.contoso.com,GetUserSettings,200,NoError,0,0,1,,,,,GlobalThrottlingPolicy_b1653804-e572-4ffd-8788-e7fe782aefb4,,,13,0,39,,5,8,54,ExchangePrincipal=2013user@contoso.com;SkipST=False;S:ServiceCommonMetadata.RequestSize=9387;S:WLM.Bal=299976.6;S:WLM.BT=Ews;S:BudgetMetadata.MaxConn=27;S:BudgetMetadata.MaxBurst=300000;S:BudgetMetadata.BeginBalance=300000;S:BudgetMetadata.Cutoff=3000000;S:BudgetMetadata.RechargeRate=900000;S:BudgetMetadata.IsServiceAct=False;S:BudgetMetadata.LiveTime=00:00:00;S:BudgetMetadata.EndBalance=299976.6;Dbl:WLM.TS=54;Dbl:BudgUse.T[]=31.2532997131348;I32:ADS.C[DC]=7;F:ADS.AL[DC]=1.828386;I32:ADR.C[DC]=2;F:ADR.AL[DC]=1.33165;I32:ATE.C[DC.contoso.com]=9;F:ATE.AL[DC.contoso.com]=1.777778,,ErrorMessage=No error.;,

MBX 2013 – Exchange EWS log:

2015-08-18T07:22:35.810Z,7d118c15-2050-446a-b9e2-5aad130589b5,15,0,1104,2,1451abf2e5564582a9136a7269a96fc4,External,true,CloudUser@contoso.mail.onmicrosoft.com,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,Target=None;Req=Exchange2012/Exchange2013;,192.168.2.56,EXCH2013MB,EXCH2013.contoso.com,GetCloudUservailability,200,11241,,,,,,b81277cd1763434a92ea312ea0e7178f,fdaf9e01-8e34-4aae-b142-48dce83174eb,PrimaryServer,LocalTask,0,0,0,0,0,0,1,0,0,,,,,,,,,0 Max,0 Max,,,,GlobalThrottlingPolicy_b1653804-e572-4ffd-8788-e7fe782aefb4,0.0359,[C],3,4,0,0,7,,331,62,,5,402,30,434,,,ADIdentityCache=Miss;WcfLatency=171.8812;MailboxTypeCacheSize=0;S:WLM.Cl=InternalMaintenance;S:AS.ExtC=0;S:ServiceTaskMetadata.ADCount=5;S:WLM.Type=Ews;S:ServiceTaskMetadata.ADLatency=8.36570024490356;S:WLM.Int=True;S:AS.PASQ1=0;S:ServiceTaskMetadata.RpcCount=0;S:WLM.SvcA=False;S:AS.PASQ2=0;S:ServiceTaskMetadata.RpcLatency=0;S:WLM.Bal=299753.5;S:AS.PASQT=0;S:ServiceTaskMetadata.WatsonReportCount=0;S:ServiceTaskMetadata.ServiceCommandBegin=402;S:AS.TimeInAS=30;S:AS.PEL=402;S:ServiceTaskMetadata.ServiceCommandEnd=433;S:ActivityStandardMetadata.Component=Ews;'S:AS.ReqStats=AddressCount=1;MessageId=urn:uuid:851fb4ea-9faa-4cb6-b7ef-304a0b397a03;Requester=CloudUser@contoso.mail.onmicrosoft.com;local=1;Threads.Worker.Available=397;Threads.Worker.InUse=0;Threads.IO.Available=400;Threads.IO.InUse=1;Target-e3d91eaa-d427-4d1c-b9e9-247cda0c21e9|QT-Local|Cnt-1|[EPL-4|];Failures=0;EXP=<>;TAQ=30;MRPC.T=0;MRPC.R=0;AD.T=4;AD.R=3;RCM=0;LFTE=0;LLPE.T=16;LLPE.D=Exch2013MB.contoso.com;LLP.T=0;LLP.R=16;LLP.D=Exch2013MB.contoso.com;LT.T=16;LT.R=1;TCLP.T=15;TCLP.D=LocalRequest.Execute;PreGetQueries=0;PostGetQueries=15;RequestDispatcher.PreQuery=0;RequestDispatcher.BeginInvoke=0;RequestDispatcher.Complete=15;PostQuery=0;';S:WLM.BT=Ews;S:BudgetMetadata.MaxConn=27;S:BudgetMetadata.MaxBurst=300000;S:BudgetMetadata.BeginBalance=300000;S:BudgetMetadata.Cutoff=3000000;S:BudgetMetadata.RechargeRate=900000;S:BudgetMetadata.IsServiceAct=False;S:BudgetMetadata.LiveTime=00:00:00;S:BudgetMetadata.EndBalance=299753.5;Dbl:WLM.TS=434;Dbl:BudgUse.T[]=258.247805595398;Dbl:CCpu.T[CMD]=0;I32:ADS.C[DC]=8;F:ADS.AL[DC]=1.845638;I32:ATE.C[DC.contoso.com]=7;F:ATE.AL[DC.contoso.com]=0,,,

Exchange 2010 IIS log:

2015-08-18 07:22:40 192.168.2.60 POST /autodiscover/autodiscover.svc/WSSecurity - 443 - 192.168.2.54 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 200 0 0 2953

2015-08-18 07:22:40 192.168.2.60 POST /ews/exchange.asmx/WSSecurity Requester=CloudUser@contoso.mail.onmicrosoft.com;local=1;Threads.Worker.Available=399;Threads.Worker.InUse=0;Threads.IO.Available=400;Threads.IO.InUse=1;Failures=0;MailboxRPC.TimeTaken=0;MailboxRPC.RequestCount=0;AD.TimeTaken=0;AD.RequestCount=6;Request.CPU.Main=15;Local.FirstThreadExecute=0;Local.LongPole.Elapsed.TimeTaken=33;Local.LongPole.Elapsed.Destination=EXCH2010.contoso.com;LocalLongPole.TimeTaken=0;LocalLongPole.RequestCount=17;LocalLongPole.Destination=EXCH2010.contoso.com;TotalLocal.TimeTaken=33;TotalLocal.RequestCount=1;Thread.CPU.LongPole.TimeTaken=15;Thread.CPU.LongPole.Destination=LocalRequest.Execute;Request.Phase.PreQuery=15;Request.Phase.RequestDispatcher.BeginInvoke=0;Request.Phase.RequestDispatcher.Complete=31;Request.Phase.PostQuery=0;Request.CPU.Total=30; 443 - 192.168.2.54 ASProxy/CrossForest/EmailDomain//15.01.0231.021 200 0 0 312

Exchange 2010 EWS log

2015-08-18T07:22:40.978Z,Negotiate,True,CloudUser@contoso.mail.onmicrosoft.com,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.54,EXCH2010,GetCloudUservailability,200,,,DQXO0P9EFLPTFMNQ,0,1,0,0,30000/30000/0%,30000/30000/0%,54000/54000/0%,54000/53954/1%,36000/36000/0%,36000/36000/0%,1000/0,1000/0,5000/0,5000/0,DC.contoso.com,-1%,0,Mailbox Database 1249352423,-1%,0,[Fallback],00:00:00.0156255,[C],1,0,9,0,234,AddressCount=1;MessageId=urn:uuid:62e72944-204c-45e2-a05f-8725cf1f6ceb;TimeInAS=60;,,

Same requests using OAUTH

2013 CAS - IIS log:

2015-08-18 08:40:54 192.168.2.54 POST /autodiscover/autodiscover.svc &CorrelationID=<empty>;&ClientId=BSQTQYEQCX9P0FSJRQ&cafeReqId=36f8b1d9-0d5e-458a-9786-2cae6f8a44ae; 443 - 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 401 0 0 187

2015-08-18 08:40:54 192.168.2.54 POST /autodiscover/autodiscover.svc &CorrelationID=<empty>;&ClientId=EC0OXTTSKGZ9QVBSWDWG&cafeReqId=014b16ae-1693-4dba-a03f-8c55f3470d2e; 443 - 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 401 0 0 390

2015-08-18 08:40:54 192.168.2.54 POST /autodiscover/autodiscover.svc &CorrelationID=<empty>;&ClientId=ZGTTSN0UF0SDWPPHF9W&cafeReqId=55ac375e-b3b1-4db9-a070-c201e00d2cd8; 443 S2S~00000002-0000-0ff1-ce00-000000000000 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 484

2015-08-18 08:40:55 192.168.2.54 POST /ews/exchange.asmx &CorrelationID=<empty>;&ClientId=UHIRKKDGE0APRYZKHXA&cafeReqId=7938b147-1a95-46c7-b143-ebdcd2e34438; 443 - 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 401 0 0 156

2015-08-18 08:40:55 192.168.2.54 POST /ews/exchange.asmx &CorrelationID=<empty>;&ClientId=UHIRKKDGE0APRYZKHXA&cafeReqId=fdd60731-6b03-4d47-b65e-3280d857bf8c; 443 - 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 401 0 0 312

2015-08-18 08:40:57 192.168.2.54 POST /ews/exchange.asmx &CorrelationID=<empty>;&ClientId=UHIRKKDGE0APRYZKHXA&cafeReqId=f9e9c880-0308-48d8-aa6a-a8e2d101b31f; 443 <unverified>actas1(sip:CloudUser@contoso.com|smtp:CloudUser@contoso.com|upn:CloudUser@contoso.com) 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 765

2015-08-18 08:41:00 192.168.2.54 POST /autodiscover/autodiscover.svc &CorrelationID=<empty>;&ClientId=YUBHBBIX0UTXDZHFDPZA&cafeReqId=9fce7682-d138-47a0-9db9-e4923424e696; 443 S2S~00000002-0000-0ff1-ce00-000000000000 192.168.2.56 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 234

2015-08-18 08:41:09 192.168.2.54 POST /ews/exchange.asmx &CorrelationID=<empty>;&ClientId=SCKUCFTESXKP9XFNRG&cafeReqId=ff2601e9-6a17-4e97-950c-178855987ae7; 443 <unverified>actas1(sip:CloudUser@contoso.com|smtp:CloudUser@contoso.com|upn:CloudUser@contoso.com) 192.168.2.56 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 9172

2013 CAS - Exchange HttpProxy - Autodiscover:

2015-08-18T08:40:54.004Z,36f8b1d9-0d5e-458a-9786-2cae6f8a44ae,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc,,,false,,,,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,401,,UnauthenticatedRequest,POST,,,,,,,,,1455,,,,11,,,0,,0,,0,0,,0,41,0,,,,,,,,,1,30,0,,30,,41,41,,,,BeginRequest=2015-08-18T08:40:53.972Z;CorrelationID=<empty>;ProxyState-Run=None;ProxyState-Complete=CalculateBackEnd;EndRequest=2015-08-18T08:40:54.004Z;,

2015-08-18T08:40:54.347Z,014b16ae-1693-4dba-a03f-8c55f3470d2e,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc,,Bearer,false,,,,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,401,,,POST,,,,,,,,,1455,,,,,,,,,,,,,,,195,,,,,,,,,,,,,,196,,196,196,,,,BeginRequest=2015-08-18T08:40:54.160Z;CorrelationID=<empty>;EndRequest=2015-08-18T08:40:54.347Z;I32:ADS.C[DC]=7;F:ADS.AL[DC]=1.927843;I32:ADR.C[DC]=2;F:ADR.AL[DC]=1.38465;I32:ATE.C[DC.contoso.com]=9;F:ATE.AL[DC.contoso.com]=1.666667,

2015-08-18T08:40:54.941Z,55ac375e-b3b1-4db9-a070-c201e00d2cd8,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc,,Bearer,true,S2S~00000002-0000-0ff1-ce00-000000000000,,OrganizationId~OrganizationAnchor@,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2013mb.contoso.com,15.00.1104.000,IntraForest,OAuthIdentity-AppOrganization,,,,1455,1703,1,,10,36,0;,0,23;,23,,0,23,,0,277,0,4,24,6,16,0,0,1,3,0,267,0,90,216,240,250,277,,,,BeginRequest=2015-08-18T08:40:54.660Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1941996624;NewConnection=192.168.2.53&0;BeginGetRequestStream=2015-08-18T08:40:54.769Z;OnRequestStreamReady=2015-08-18T08:40:54.785Z;BeginGetResponse=2015-08-18T08:40:54.847Z;OnResponseReady=2015-08-18T08:40:54.863Z;EndGetResponse=2015-08-18T08:40:54.863Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T08:40:54.941Z;S:ServiceLatencyMetadata.AuthModuleLatency=8;S:ServiceCommonMetadata.OAuthExtraInfo=Category:S2SAppOnly|AppId:S2S~00000002-0000-0ff1-ce00-000000000000|;S:ServiceCommonMetadata.OAuthToken=eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsIng1dCI6Ik1uQ19WWmNBVGZNNXBPWWlKSE1iYTlnb0VLWSIsImtpZCI6Ik1uQ19WWmNBVGZNNXBPWWlKSE1iYTlnb0VLWSJ9LnsiYXVkIjoiMDAwMDAwMDItMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwL2F1dG9kaXNjb3Zlci5hLWlvdXJzdS5tc2Z0b25saW5lcmVwcm8uY29tQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsImlzcyI6IjAwMDAwMDAxLTAwMDAtMDAwMC1jMDAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJpYXQiOjE0Mzk4ODY4NjIsIm5iZiI6MTQzOTg4Njg2MiwiZXhwIjoxNDM5ODkwNzYyLCJpZGVudGl0eXByb3ZpZGVyIjoiMDAwMDAwMDEtMDAwMC0wMDAwLWMwMDAtMDAwMDAwMDAwMDAwQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsIm5hbWVpZCI6IjAwMDAwMDAyLTAwMDAtMGZmMS1jZTAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJvaWQiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJzdWIiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJ0cnVzdGVkZm9yZGVsZWdhdGlvbiI6InRydWUifQ==;I32:ADS.C[DC]=4;F:ADS.AL[DC]=3.38515;I32:ATE.C[DC.contoso.com]=3;F:ATE.AL[DC.contoso.com]=5.333333,

2015-08-18T08:41:00.410Z,9fce7682-d138-47a0-9db9-e4923424e696,15,0,1104,2,,Autodiscover,autodiscover.contoso.com,/autodiscover/autodiscover.svc,,Bearer,true,S2S~00000002-0000-0ff1-ce00-000000000000,,OrganizationId~OrganizationAnchor@,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2013mb.contoso.com,15.00.1104.000,IntraForest,OAuthIdentity-AppOrganization,,,,1455,1703,1,,1,0,,0,,0,,0,0,,0,36,0,0,0,1,32,0,0,0,0,0,35,0,33,2,2,3,36,,,,BeginRequest=2015-08-18T08:41:00.363Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1941996624;BeginGetRequestStream=2015-08-18T08:41:00.363Z;OnRequestStreamReady=2015-08-18T08:41:00.363Z;BeginGetResponse=2015-08-18T08:41:00.363Z;OnResponseReady=2015-08-18T08:41:00.410Z;EndGetResponse=2015-08-18T08:41:00.410Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T08:41:00.410Z;S:ServiceLatencyMetadata.AuthModuleLatency=0;S:ServiceCommonMetadata.OAuthExtraInfo=Category:S2SAppOnly|AppId:S2S~00000002-0000-0ff1-ce00-000000000000|;S:ServiceCommonMetadata.OAuthToken=eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsIng1dCI6Ik1uQ19WWmNBVGZNNXBPWWlKSE1iYTlnb0VLWSIsImtpZCI6Ik1uQ19WWmNBVGZNNXBPWWlKSE1iYTlnb0VLWSJ9LnsiYXVkIjoiMDAwMDAwMDItMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwL2F1dG9kaXNjb3Zlci5hLWlvdXJzdS5tc2Z0b25saW5lcmVwcm8uY29tQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsImlzcyI6IjAwMDAwMDAxLTAwMDAtMDAwMC1jMDAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJpYXQiOjE0Mzk4ODY4NjIsIm5iZiI6MTQzOTg4Njg2MiwiZXhwIjoxNDM5ODkwNzYyLCJpZGVudGl0eXByb3ZpZGVyIjoiMDAwMDAwMDEtMDAwMC0wMDAwLWMwMDAtMDAwMDAwMDAwMDAwQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsIm5hbWVpZCI6IjAwMDAwMDAyLTAwMDAtMGZmMS1jZTAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJvaWQiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJzdWIiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJ0cnVzdGVkZm9yZGVsZWdhdGlvbiI6InRydWUifQ==,

2013 CAS - Exchange HttpProxy – EWS:

2015-08-18T08:40:55.832Z,7938b147-1a95-46c7-b143-ebdcd2e34438,15,0,1104,2,4b49af38829e48e290f529a161bddfbb,Ews,mail.contoso.com,/ews/exchange.asmx,,,false,,,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,401,,,POST,,,,,,,,,2853,,,,,,,,,,,,,,,3,,,,,,,,,,,,,,3,,3,3,,,,BeginRequest=2015-08-18T08:40:55.816Z;CorrelationID=<empty>;AnonymousRequestFilterModule=AnonymousRequestDisallowed;EndRequest=2015-08-18T08:40:55.832Z;,

2015-08-18T08:40:56.082Z,fdd60731-6b03-4d47-b65e-3280d857bf8c,15,0,1104,2,4b49af38829e48e290f529a161bddfbb,Ews,mail.contoso.com,/ews/exchange.asmx,,Bearer,false,,,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,401,,,POST,,,,,,,,,2853,,,,,,,,,,,,,,,108,,,,,,,,,,,,,,108,,108,108,,,,BeginRequest=2015-08-18T08:40:55.972Z;CorrelationID=<empty>;EndRequest=2015-08-18T08:40:56.082Z;I32:ADS.C[DC]=7;F:ADS.AL[DC]=1.824214;I32:ADR.C[DC]=2;F:ADR.AL[DC]=1.44715;I32:ATE.C[DC.contoso.com]=9;F:ATE.AL[DC.contoso.com]=0,

2015-08-18T08:40:57.160Z,f9e9c880-0308-48d8-aa6a-a8e2d101b31f,15,0,1104,2,4b49af38829e48e290f529a161bddfbb,Ews,mail.contoso.com,/ews/exchange.asmx,,Bearer,true,<unverified>actas1(sip:CloudUser@contoso.com|smtp:CloudUser@contoso.com|upn:CloudUser@contoso.com), contoso.com,Smtp~2013user@contoso.com,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2013mb.contoso.com,15.00.1104.000,IntraForest,AnchorMailboxHeader-SMTP,,,,2853,2781,1,,11,335,,0,4;,4,,0,4,,0,755,0,4,23,6,188,0,0,1,3,1,744,0,264,522,545,556,755,,,,BeginRequest=2015-08-18T08:40:56.394Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1941996624;ActAsUserVerified=False;NewConnection=192.168.2.53&0;BeginGetRequestStream=2015-08-18T08:40:56.816Z;OnRequestStreamReady=2015-08-18T08:40:56.832Z;BeginGetResponse=2015-08-18T08:40:56.894Z;OnResponseReady=2015-08-18T08:40:57.082Z;EndGetResponse=2015-08-18T08:40:57.082Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T08:40:57.160Z;S:ServiceLatencyMetadata.AuthModuleLatency=8;S:ServiceCommonMetadata.Cookie=a37688b8e2d44dc89a015832a3c0bf75;S:ServiceCommonMetadata.OAuthExtraInfo=Category:S2SAppActAs|AppId:S2S~00000002-0000-0ff1-ce00-000000000000|;S:ServiceCommonMetadata.OAuthToken=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0ueyJpc3MiOiIwMDAwMDAwMi0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDBAYzJmZjM0ODQtYzJiZC00ZjFmLWFlYWMtZjRiYWI1NTZlMTNkIiwiYXVkIjoiMDAwMDAwMDItMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwL21haWwuYS1pb3Vyc3UubXNmdG9ubGluZXJlcHJvLmNvbUBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJuYmYiOjE0Mzk4ODcxNjQsImV4cCI6MTQzOTkxNTk2NCwibmFtZWlkIjoiMTAwMzAwMDA5MkZCQ0Q2NiIsInVwbiI6InVzZXJhQGEtaW91cnN1Lm1zZnRvbmxpbmVyZXByby5jb20iLCJzbXRwIjoiVXNlckFAYS1pb3Vyc3UubXNmdG9ubGluZXJlcHJvLmNvbSIsInNpcCI6InVzZXJhQGEtaW91cnN1Lm1zZnRvbmxpbmVyZXByby5jb20iLCJuaWkiOiJ1cm46ZmVkZXJhdGlvbjpNaWNyb3NvZnRPbmxpbmUiLCJhY3RvcnRva2VuIjoiLi4uIn07IGFjdG9yOiB7InR5cCI6IkpXVCIsImFsZyI6IlJTMjU2IiwieDV0IjoiTW5DX1ZaY0FUZk01cE9ZaUpITWJhOWdvRUtZIiwia2lkIjoiTW5DX1ZaY0FUZk01cE9ZaUpITWJhOWdvRUtZIn0ueyJhdWQiOiIwMDAwMDAwMi0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvbWFpbC5hLWlvdXJzdS5tc2Z0b25saW5lcmVwcm8uY29tQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsImlzcyI6IjAwMDAwMDAxLTAwMDAtMDAwMC1jMDAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJpYXQiOjE0Mzk4ODY4NjQsIm5iZiI6MTQzOTg4Njg2NCwiZXhwIjoxNDM5ODkwNzY0LCJpZGVudGl0eXByb3ZpZGVyIjoiMDAwMDAwMDEtMDAwMC0wMDAwLWMwMDAtMDAwMDAwMDAwMDAwQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsIm5hbWVpZCI6IjAwMDAwMDAyLTAwMDAtMGZmMS1jZTAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJvaWQiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJzdWIiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJ0cnVzdGVkZm9yZGVsZWdhdGlvbiI6InRydWUifQ==;I32:ADS.C[DC]=4;F:ADS.AL[DC]=2.005325;I32:ATE.C[DC.contoso.com]=3;F:ATE.AL[DC.contoso.com]=0,

2015-08-18T08:41:09.536Z,ff2601e9-6a17-4e97-950c-178855987ae7,15,0,1104,2,a394c3baf92441d4ab39008d7cd5a8bc,Ews,mail.contoso.com,/ews/exchange.asmx,,Bearer,true,S-1-5-21-3451821684-4191209344-3344592087-1162,contoso.com,Smtp~2010user@contoso.com,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013,200,200,,POST,Proxy,exch2010.contoso.com,14.03.0123.000,IntraForest,AnchorMailboxHeader-SMTP,,EXCH2010,129,2853,3034,1,,2,156,,0,1;,1,2;2;,4,5,,0,8975,0,0,2,0,8758,0,1,0,0,1,8973,0,8777,212,214,216,8975,,,,BeginRequest=2015-08-18T08:41:00.551Z;CorrelationID=<empty>;ProxyState-Run=None;ServerLocatorCall=DM:76894869-7016-4bcc-b289-21c797b0b9eb~~contoso.com;DownLevelTargetHash=0/0/1;ClientAccessServer=EXCH2010.contoso.com;ResolveCasLatency=18;FEAuth=BEVersion-1937997947;ProxyToDownLevel=True;ActAsUserVerified=True;NewConnection=192.168.2.60&0;BeginGetRequestStream=2015-08-18T08:41:00.723Z;OnRequestStreamReady=2015-08-18T08:41:00.723Z;BeginGetResponse=2015-08-18T08:41:00.754Z;OnResponseReady=2015-08-18T08:41:09.504Z;EndGetResponse=2015-08-18T08:41:09.504Z;ProxyState-Complete=ProxyResponseData;EndRequest=2015-08-18T08:41:09.536Z;S:ServiceLatencyMetadata.AuthModuleLatency=0;S:ServiceCommonMetadata.Cookie=b0a9c6f4adcb430eb4dec7f885f39715;S:ServiceCommonMetadata.OAuthExtraInfo=Category:S2SAppActAs|AppId:S2S~00000002-0000-0ff1-ce00-000000000000|;S:ServiceCommonMetadata.OAuthToken=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0ueyJpc3MiOiIwMDAwMDAwMi0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDBAYzJmZjM0ODQtYzJiZC00ZjFmLWFlYWMtZjRiYWI1NTZlMTNkIiwiYXVkIjoiMDAwMDAwMDItMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwL21haWwuYS1pb3Vyc3UubXNmdG9ubGluZXJlcHJvLmNvbUBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJuYmYiOjE0Mzk4ODcxNjksImV4cCI6MTQzOTkxNTk2OSwibmFtZWlkIjoiMTAwMzAwMDA5MkZCQ0Q2NiIsInVwbiI6InVzZXJhQGEtaW91cnN1Lm1zZnRvbmxpbmVyZXByby5jb20iLCJzbXRwIjoiVXNlckFAYS1pb3Vyc3UubXNmdG9ubGluZXJlcHJvLmNvbSIsInNpcCI6InVzZXJhQGEtaW91cnN1Lm1zZnRvbmxpbmVyZXByby5jb20iLCJuaWkiOiJ1cm46ZmVkZXJhdGlvbjpNaWNyb3NvZnRPbmxpbmUiLCJhY3RvcnRva2VuIjoiLi4uIn07IGFjdG9yOiB7InR5cCI6IkpXVCIsImFsZyI6IlJTMjU2IiwieDV0IjoiTW5DX1ZaY0FUZk01cE9ZaUpITWJhOWdvRUtZIiwia2lkIjoiTW5DX1ZaY0FUZk01cE9ZaUpITWJhOWdvRUtZIn0ueyJhdWQiOiIwMDAwMDAwMi0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvbWFpbC5hLWlvdXJzdS5tc2Z0b25saW5lcmVwcm8uY29tQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsImlzcyI6IjAwMDAwMDAxLTAwMDAtMDAwMC1jMDAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJpYXQiOjE0Mzk4ODY4NjQsIm5iZiI6MTQzOTg4Njg2NCwiZXhwIjoxNDM5ODkwNzY0LCJpZGVudGl0eXByb3ZpZGVyIjoiMDAwMDAwMDEtMDAwMC0wMDAwLWMwMDAtMDAwMDAwMDAwMDAwQGMyZmYzNDg0LWMyYmQtNGYxZi1hZWFjLWY0YmFiNTU2ZTEzZCIsIm5hbWVpZCI6IjAwMDAwMDAyLTAwMDAtMGZmMS1jZTAwLTAwMDAwMDAwMDAwMEBjMmZmMzQ4NC1jMmJkLTRmMWYtYWVhYy1mNGJhYjU1NmUxM2QiLCJvaWQiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJzdWIiOiJmNjAzM2M4NC1lODUxLTQ0MTktOTg4Ni01ODZkZDE3MjQxN2MiLCJ0cnVzdGVkZm9yZGVsZWdhdGlvbiI6InRydWUifQ==;I32:ADS.C[DC]=9;F:ADS.AL[DC]=1.4819;I32:ADR.C[DC]=3;F:ADR.AL[DC]=1.430933;I32:ATE.C[DC.contoso.com]=11;F:ATE.AL[DC.contoso.com]=0,

MBX 2013 – IIS Log:

2015-08-18 08:40:54 192.168.2.53 POST /autodiscover/autodiscover.svc - 444 S2S~00000002-0000-0ff1-ce00-000000000000 192.168.2.54 ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 62

2015-08-18 08:40:57 192.168.2.53 POST /ews/exchange.asmx - 444 S-1-5-21-3451821684-4191209344-3344592087-1162 192.168.2.54 ASProxy/CrossForest/EmailDomain//15.01.0231.021 - 200 0 0 250

MBX 2013 – Exchange Autodiscover log:

2015-08-18T08:40:55.238Z,55ac375e-b3b1-4db9-a070-c201e00d2cd8,15,0,1104,2,,Bearer,true,S2S~00000002-0000-0ff1-ce00-000000000000,,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013MB,EXCH2013.contoso.com,GetUserSettings,200,NoError,0,0,1,,,,,[Unthrottled],,,36,0,28,,5,10,65,ExchangePrincipal=2013user@contoso.com; SkipST=False;S:ServiceCommonMetadata.RequestSize=1455;S:WLM.BT=Ews;S:BudgetMetadata.MaxConn=Unlimited;S:BudgetMetadata.MaxBurst=Unlimited;S:BudgetMetadata.BeginBalance=$null;S:BudgetMetadata.Cutoff=Unlimited;S:BudgetMetadata.RechargeRate=Unlimited;S:BudgetMetadata.IsServiceAct=False;S:BudgetMetadata.LiveTime=00:00:00;S:BudgetMetadata.EndBalance=$null;Dbl:WLM.TS=65;Dbl:BudgUse.T[]=31.2504997253418;I32:ADS.C[DC]=6;F:ADS.AL[DC]=2.146267;I32:ADR.C[DC]=2;F:ADR.AL[DC]=2.16305;I32:ATE.C[DC.contoso.com]=8;F:ATE.AL[DC.contoso.com]=1.875,,ErrorMessage=No error.;,

2015-08-18T08:41:00.785Z,9fce7682-d138-47a0-9db9-e4923424e696,15,0,1104,2,,Bearer,true,S2S~00000002-0000-0ff1-ce00-000000000000,,ASAutoDiscover/CrossForest/EmailDomain//15.01.0231.021,192.168.2.56,EXCH2013MB,EXCH2013.contoso.com,GetUserSettings,200,NoError,0,0,1,,,,,[Unthrottled],,,1,0,29,,11,9,31,ExchangePrincipal=2010user@contoso.com;SkipST=False;S:ServiceCommonMetadata.RequestSize=1455;S:WLM.BT=Ews;S:BudgetMetadata.MaxConn=Unlimited;S:BudgetMetadata.MaxBurst=Unlimited;S:BudgetMetadata.BeginBalance=$null;S:BudgetMetadata.Cutoff=Unlimited;S:BudgetMetadata.RechargeRate=Unlimited;S:BudgetMetadata.IsServiceAct=False;S:BudgetMetadata.LiveTime=00:00:05.5471988;S:BudgetMetadata.EndBalance=$null;Dbl:WLM.TS=31;Dbl:BudgUse.T[]=31.4064998626709;I32:ADS.C[DC]=5;F:ADS.AL[DC]=2.16688;I32:ADR.C[DC]=2;F:ADR.AL[DC]=1.1391;I32:ATE.C[DC.contoso.com]=7;F:ATE.AL[DC.contoso.com]=2.142857,,ErrorMessage=No error.;,

MBX 2013 – Exchange EWS Log:

2015-08-18T08:40:57.457Z,f9e9c880-0308-48d8-aa6a-a8e2d101b31f,15,0,1104,2,4b49af38829e48e290f529a161bddfbb,Bearer,true,CloudUser@contoso.com,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,Target=None;Req=Exchange2012/Exchange2013;,192.168.2.56,EXCH2013MB,EXCH2013.contoso.com,GetCloudUservailability,200,2853,,,CloudUser@contoso.com,,,a37688b8e2d44dc89a015832a3c0bf75,4a4c07a8-4127-495c-9616-d3de4cfd9119,PrimaryServer,LocalTask,0,0,0,0,0,0,1,0,0,,,,,,,,,0 Max,0 Max,,,,GlobalThrottlingPolicy_b1653804-e572-4ffd-8788-e7fe782aefb4,0.0348,[C],2,5,0,0,6,0,40,15,,132,191,45,238,,,BackEndAuthenticator=OAuthAuthenticator;TotalBERehydrationModuleLatency=3;ADIdentityCache=Miss;AuthzFlags=AuthzSkipTokenGroups;AuthzFlags=AuthzSkipTokenGroups;MailboxTypeCacheSize=0;S:WLM.Cl=InternalMaintenance;S:ServiceTaskMetadata.ADCount=2;S:WLM.Type=Ews;S:AS.IntC=0;S:ServiceTaskMetadata.ADLatency=5.93600082397461;S:WLM.Int=True;S:AS.PASQ1=0;S:ServiceTaskMetadata.RpcCount=0;S:ServiceTaskMetadata.RpcLatency=0;S:WLM.SvcA=False;S:AS.PASQ2=0;S:WLM.Bal=299811;S:AS.PASQT=0;S:ServiceTaskMetadata.WatsonReportCount=0;S:ServiceTaskMetadata.ServiceCommandBegin=191;S:AS.TimeInAS=45;S:ServiceTaskMetadata.ServiceCommandEnd=237;S:AS.PEL=191;S:ActivityStandardMetadata.Component=Ews;'S:AS.ReqStats=AddressCount=1;MessageId=urn:uuid:e5dd52ad-340e-4d94-96f3-991fca4c546d;Requester=S-1-5-21-3451821684-4191209344-3344592087-1162;local=1;Threads.Worker.Available=398;Threads.Worker.InUse=0;Threads.IO.Available=400;Threads.IO.InUse=1;Target-e3d91eaa-d427-4d1c-b9e9-247cda0c21e9|QT-Local|Cnt-1|;Failures=0;EXP=<>;TAQ=45;MRPC.T=0;MRPC.R=0;AD.T=5;AD.R=2;RCM=0;LFTE=0;LLPE.T=37;LLPE.D=Exch2013MB.contoso.com;LLP.T=1;LLP.R=16;LLP.D=Exch2013MB.contoso.com;LT.T=37;LT.R=1;TCLP.T=31;TCLP.D=LocalRequest.Execute;PreGetQueries=0;PostGetQueries=0;RequestDispatcher.PreQuery=0;RequestDispatcher.BeginInvoke=0;RequestDispatcher.Complete=46;PostQuery=0;';S:WLM.BT=Ews;S:BudgetMetadata.MaxConn=27;S:BudgetMetadata.MaxBurst=300000;S:BudgetMetadata.BeginBalance=300000;S:BudgetMetadata.Cutoff=3000000;S:BudgetMetadata.RechargeRate=900000;S:BudgetMetadata.IsServiceAct=False;S:BudgetMetadata.LiveTime=00:00:00;S:BudgetMetadata.EndBalance=299811;Dbl:WLM.TS=238;Dbl:BudgUse.T[]=204.624298095703;Dbl:CCpu.T[CMD]=0;I32:ADS.C[DC]=11;F:ADS.AL[DC]=2.839091;I32:ADR.C[DC]=3;F:ADR.AL[DC]=3.791633;I32:ATE.C[DC.contoso.com]=14;F:ATE.AL[DC.contoso.com]=0,,,

Exchange 2010 - IIS log:

2015-08-18 08:41:09 192.168.2.60 POST /ews/exchange.asmx Requester=S-1-5-21-3451821684-4191209344-3344592087-1162;local=1;Threads.Worker.Available=399;Threads.Worker.InUse=0;Threads.IO.Available=400;Threads.IO.InUse=1;Failures=0;MailboxRPC.TimeTaken=0;MailboxRPC.RequestCount=0;AD.TimeTaken=0;AD.RequestCount=6;Request.CPU.Main=1358;Local.FirstThreadExecute=9;Local.LongPole.Elapsed.TimeTaken=2227;Local.LongPole.Elapsed.Destination=EXCH2010.contoso.com;LocalLongPole.TimeTaken=1;LocalLongPole.RequestCount=26;LocalLongPole.Destination=EXCH2010.contoso.com;TotalLocal.TimeTaken=2245;TotalLocal.RequestCount=1;Thread.CPU.LongPole.TimeTaken=2218;Thread.CPU.LongPole.Destination=LocalRequest.Execute;Request.Phase.PreQuery=1750;Request.Phase.RequestDispatcher.BeginInvoke=0;Request.Phase.RequestDispatcher.Complete=2250;Request.Phase.PostQuery=15;Request.CPU.Total=3576; 443 CONTOSOEXCH2013$ 192.168.2.54 ASProxy/CrossForest/EmailDomain//15.01.0231.021 200 0 0 8797

Exchange 2010 - EWS log:

2015-08-18T08:41:09.320Z,Negotiate,True,CONTOSOEXCH2013$ ,,ASProxy/CrossForest/EmailDomain//15.01.0231.021,192.168.2.54,EXCH2010,GetCloudUservailability,200,,,SCKUCFTESXKP9XFNRG,0,1,0,0,30000/30000/0%,30000/30000/0%,54000/54000/0%,54000/49847/7%,36000/36000/0%,36000/35940/1%,1000/0,1000/0,5000/0,5000/0,DC.contoso.com,-1%,0,Mailbox Database 1249352423,-1%,0,DefaultThrottlingPolicy_4e4714d9-f925-40eb-af6d-82838824b459,00:00:00.0156257,[C],2,0,13,15,8750,ProxyAs=CONTOSOCloudUser;AddressCount=1;MessageId=urn:uuid:0e76e671-cfb5-43b4-8e52-d009c0a554c8;TimeInAS=4073;,,

So, quite a bunch of logging for a successful request…

As mentioned, the above logs are for successful requests. When something fails, the response code will be different, depending on the error. If you do not find any entry in the IIS log, that usually means that the request never reached the IIS server, so it might be something related to the firewall/reverse proxy and you should direct your attention there and look for some dropped connections, or to what server those connections were sent.

Also, depending where the on-premise mailbox is located, the response code from the CAS IIS/Exchange log can be received from some other backend server, depending where the request was proxied, so follow the logs, first with the IIS, then with the Exchange ones, depending on the request type (EWS or Autodiscover). The above logs might be slightly different than yours, as the level of details might change, depending on the update level of the server.

When you’ve reached the server where the actual error is generated, if the reason behind the error is not identified quickly (web folder property, IIS property, certificate etc) you can use FREB (Failed Requests Tracing – formerly known as Failed Request Event Buffering) to go deeper and check the module generating the error code.

Next we’ll talk a bit about FREB

Failed Requests Tracing – formerly known as Failed Request Event Buffering

When you’ll receive responses other than 200 that you want to investigate, like 401 or 500, you can enable FREB and configure it on the error codes you are interested in, to find the actual module causing the error.

To do this, follow the below procedure:

Open IIS Manager and navigate to the level you want to manage.
In the Connections pane, click Sites.
In Features View, select the site for which you want to enable FREB.
In the Actions pane, under Configure, click Failed Request Tracing.
In the Edit Web Site Failed Request Tracing Settings dialog box, select Enable to enable logging for this site.
In the Directory text box, type the path where you want to store the log files or click the browse button (…) to find a location on the computer. The default is %SystemDrive%inetpublogsFailedReqLogFiles.
Next, select the directory you are interested in like Autodiscover or EWS, and in the Features View, under IIS, open Failed Request Tracking rules
Click Add in the Actions pane and select All content. Click Next
In the conditions box, type the error codes you want to trace, like 401,500
Leave default selections in the next box and click finish
Reproduce the error, and open the fr0000x.xml file located in the configured log directory

The file should be opened in Internet Explorer and the freb.xml file should be present in the same directory in case you copy the files to a different location, in order to maintain the formatting of the page for easier view.

Remember to disable FREB after collecting the information, or the logs will increase….

Below is a sample output:

In this sample, for demonstration purposes, a Deny All permission was assigned on the autodiscover.svc file under the Autodiscover virtual directory, so FREB tells that the module giving the 401 error is FileAuthorization. Of course, this might be considered a simple situation. There could be other responses that are more difficult to interpret and in that case, I suggest opening a case to support.

Exchange Event Logging

FREB is one tool, however, as always, you should also increase the logging lever for involved services like MSExchange Autodiscover or MSExchange Availability and see if any errors or relevant information is logged in the Event log. The default logging level is Lowest. You can see it with the following command:

[PS] C:windowssystem32>Get-EventLogLevel 'MSExchange Autodiscover'

Identity EventLevel

-------- ----------

MSExchange AutodiscoverCore Lowest

MSExchange AutodiscoverWeb Lowest

MSExchange AutodiscoverProvider Lowest

[PS] C:windowssystem32>Get-EventLogLevel 'MSExchange Availability'

Identity EventLevel

-------- ----------

MSExchange AvailabilityAvailability Service Lowest

MSExchange AvailabilityAvailability Service General Lowest

MSExchange AvailabilityAvailability Service Authentication Lowest

MSExchange AvailabilityAvailability Service Authorization Lowest

And change it with something like this:

Get-EventLogLevel 'MSExchange Availability' | Set-EventLogLevel -Level High

The Level parameter specifies the log level for the specific event logging category. The valid values are:

Lowest
Low
Medium
High
Expert

Be careful when setting the level to Medium or higher, as the amount of data written to the Application log can be overwhelming… After reproducing the error and, maybe identifying the cause, remember to change back the logging to the initial value.

Thank you!

Comments

Anonymous
May 25, 2016
Amazing stuffThanks
Anonymous
September 01, 2016
Great article! Helped me out significantly with a long running free/busy data problem from o365 to on premise.Eventually leading to this https://support.microsoft.com/en-us/kb/2752387 which fixed the issue.

Partager via