Symptoms
Office 365 task fails in OA with error message 'Timeout exception' like in the example below:
Task ID 4944655
Queue name aps_application_instance1039
Task name Executing configuration script for instance with id 1444 of service 'customer' of instance with id 1039 of APS application with id 152
Task description Executing configuration script for instance with id 1444 of service 'customer' of instance with id 1039 of APS application with id 152
Queue status Failed
Start not earlier than July 23, 2011 07:36
Method name taskExecuteApplicationInstanceScript on OBJREF:APSManagerTasks:0:getAPSExternalTasks:0
Last execution output Application configuration script reported errors: '<?xml version="1.0"?>
<output xmlns="http://apstandard.com/ns/1/configure-output">
<errors>
<error id="validation-error" setting-id="Configuration">
<message>Method edit_customer calling failed. Reason:Timeout exception</message>
</error>
</errors>
</output>
As a result OA cannot successfully create subscription with Office 365 services for a customer.
Cause
There are two types of OA requests to MOSI (Microsoft Online Services Interface) - synchronous and asynchronous.
In case of asynchronous request to Microsoft OA sends requests to MOSI API servers and waits for callback from Microsoft side.
If callback from Microsoft side is not received then corresponding OA task fails with error message 'Timeout exception'.
The asynchronous MOSI requests are:
- Customer account creation
- All offer-related operations
- Add offer
- Remove offer
- Upgrade number of seats for offer
Resolution
Log on the server where MOSI Gateway software is working and find log of requests/responses to/from Microsoft. The log name is sitelog and it is located in App_Data folder of IIS website where MOSI Gateway software is installed. Refer to the Knowledgebase article #114674 [Office 365] How to find where MOSI Gateway is installed to find the needed server.
In this log find all operations related to problem account or subscription provisioning - requests to Microsoft servers and replies from them.
If you found request from OA to Microsoft and there is no callback from Microsoft to the request it exactly means that problem is out of OA scope. In this case Provider has to contact Microsoft to check what happened to OA request and why MOSI servers did not send callback to OA.
The example of investigating the problem with async MOSI request CreateCustomerAccount is provided below.
Customer subscribed to Office 365 Service Plan and subscription was created for them. OA scheduled background tasks to create customer account in Office 365 Cloud, the task failed with 'Timeout exception'. Let us analyze the MOSI Gateway log sitelog to find if the reason of problem is absent callback from Microsoft.
When OA creates customer account in Microsoft the following entry will be found in the sitelog file on MOSI Gateway server:
2011-06-17 12:11:06,687 [ 10] DEBUG endpoint : executing add_customer({"cu":{... "customer_id":"13c14b02-8960-4c56-be90-472df22f545d","hosting_subscription_id":"1001314", ...)
2011-06-17 12:11:06,687 [ 10] DEBUG flow : Create customer: John Doe (13c14b02-8960-4c56-be90-472df22f545d:1001314)
2011-06-17 12:11:06,702 [ 10] DEBUG mosi-clients: Going to call:https://mosi-preview.ccsctp.com/Syndication/OrderManagement.svc
2011-06-17 12:11:06,718 [ 10] DEBUG mosi-clients: >>> CreateCustomerAccount({... "CustomerId":"13c14b02-8960-4c56-be90-472df22f545d","RequestId":"db661363-a01b-4204-85ea-8cdd881f73c3","SubDomain":"cloud1001314"})
2011-06-17 12:11:10,899 [ 10] DEBUG mosi-clients: <<< CreateCustomerAccount
2011-06-17 12:11:10,899 [ 10] INFO audit : Customer John Doe (13c14b02-8960-4c56-be90-472df22f545d:1001314) created
2011-06-17 12:11:10,899 [ 10] DEBUG entity : waiting_customers create 13c14b02-8960-4c56-be90-472df22f545d={"waiting_for":"Create"}
2011-06-17 12:11:10,930 [ 10] DEBUG entity : csts create 13c14b02-8960-4c56-be90-472df22f545d = ...
2011-06-17 12:11:10,992 [ 10] DEBUG wait : - waiting for creation of customer John Doe (13c14b02-8960-4c56-be90-472df22f545d:1001314) up to 300 seconds`
In the provided example it is seen that MOSI Gateway received request add_customer from OA for account with GUID 13c14b02-8960-4c56-be90-472df22f545d (OA subscription ID is 1001314).
Upon receiving the request MOSI Gateway performed the following actions:
- Sent asynchronous request CreateCustomerAccount to Microsoft MOSI servers
- Put customer ID into two tables in own database:
- waiting_customers - list of customer accounts awaiting callbacks from Microsoft
- csts - list of all customers
- Started to wait for callback from Microsoft
When Microsoft create customer account it will send callback to MOSI Gateway about operation completing and the following entries will appear in the sitelog file on MOSI Gateway server:
2011-06-17 12:12:18,634 [ 5] DEBUG callbacks : CustomerAccountCreated:{... "CustomerId":"13c14b02-8960-4c56-be90-472df22f545d", "DomainName":"cloud1001314.ccsctp.net", "RequestId":"db661363-a01b-4204-85ea-8cdd881f73c3"...}
2011-06-17 12:12:18,634 [ 5] DEBUG entity : waiting_customers remove 13c14b02-8960-4c56-be90-472df22f545d
2011-06-17 12:12:18,665 [ 5] DEBUG entity : csts save 13c14b02-8960-4c56-be90-472df22f545d = ...
2011-06-17 12:12:45,045 [ 10] DEBUG wait : - wait for creation of customer John Doe (13c14b02-8960-4c56-be90-472df22f545d:1001314) success, total time:94`
Pay attention to the fact that customer ID in the CustomerAccountCreated callback is the same as in the request CreateCustomerAccount above. Based on the customer ID in the received callback MOSI Gateway performs the following operations:
- Removes record for the customer account from the waiting_customers table
- Updates information about customer account in the csts table
At this point asynchronous request to create customer account in Microsoft Office 365 Cloud is treated as successfully completed and OA background task completes too.
So, to investigate the problem with timeouts during Office 365 provisioning tasks execution one need to find the request from MOSI Gateway to Microsoft Cloud for the needed object (customer, subscription) in the sitelog file and then check below in the log if callback from Microsoft for the same customer ID was received. If callback was not received in reasonable peiod of time Provider has to contact Microsoft Support Team to investigate the reason of problem with callback.