Symptoms

Office 365 provisioning task fails in OA and Provider want to investigate the reason of the problem to get it solved. The failed task contains the name of the problem MOSI Gateway method.

The article describes how MOSI Gateway debug log may be used to troubleshoot problems with Office 365 provisioning tasks.

Resolution

Log into MOSI Gateway server using RDP, use the Knowledgebase article #114674 [Office 365] How to find where MOSI Gateway is installed to find the needed server.

Open the App_Data\sitelog file in the MOSI Gateway home folder.

MOSI Gateway debug log entries format

Log entries have the following format: 

`[DateTime] [Thread ID] [Log Level] [Logger Name] [Info]`
  • [Date Time] - Timestamp of a log entry.
  • [Thread ID] - Thread identifier. It is used to separate log entries that belong to different methods which are executed in parallel.
  • [Log Level] - Common log levels such as 'DEBUG', 'INFO', 'ERROR', etc.
  • [Logger Name] - Gateway application defines several loggers in order to simplify logs reading. The most important loggers are:
    • endpoint - used to log entry/exit of top-level Gateway methods such as add_customer, edit_user, del_useradmin etc. For each top-level Gateway method at least 2 log entries are emited: executing method_name … at the beginning and finished method_name … at the end. This fact may be used to sort out log entries for given call.
    • mosi-clients - used to log MOSI API methods calls.
    • callbacks - used to log callbacks calls.
    • flow - used to log extended information about method execution flow.
    • entity - used to log database operations such as create/update/remove records.
    • wait - used to log waiting state by calling asynchronous MOSI calls.
    • audit - used to log completed stages of provisioning process i.e. “Customer created”, “Subscription ordered” etc.
  • [Info] Additional information such as method name and its parameters, informative message etc.

The example of MOSI Gateway debug log entry is provided below: 

2011-08-31 11:17:40,115 [ 6] DEBUG mosi-clients: >>> 
AddDomain ({"Domain":{"ExtensionData":null, "Name":"officeplus.parallelscloud.com"}
"ExtensionData":null,"CustomerId":"4e219649-dfd9-428d-9e71-20a21ab4d5e9",
"SubscriptionId":"09e9501f-c969-4276-b51e-2806833e41e5"})

Let us analyze the parts of the log entry above:

  1. 2011-08-31 11:17:40,115 - log entry timestamp
  2. [ 6] - thread ID, all operations performed by the same MOSI Gateway thread are marked by the same ID
  3. DEBUG - log level
  4. mosi-clients - logger
  5. >>> AddDomain ... - detailed information

So, from the log entry above we may get the following information: MOSI Gateway thread #6 sent the AddDomain request to Microsoft Office 365 API servers. Somewhere below the response from Microsoft will be logged (it will be prefixed with '<<<').

How to read MOSI Gateway debug log

If Office 365 provisioning task failed in POA in many cases additional information about the reason of problem may be found in the MOSI Gateway debug log. Follow the steps below to understand how to read the log.

Open the App_Data\sitelog file in the MOSI Gateway home folder. Find out the last entry which corresponds to the method mentioned in the failed POA task. Method name is specified in the beginning of error description in the failed task properties, e.g. 'Method add_customer calling failed. Reason: …'.

How to find the needed entry in the log:

  • For methods add_customer and edit_customer the PA subscription ID or Office 365 customer ID may be used as search criteria.
  • For methods add_user and edit_user the  user’s UPN may be used as search criteria.

The requests add_customer and edit_customer contain Office 365 customer ID and PA subscription ID like in the example below:

"customer_id":"abdc3ad5-9876-41b9-5432-cdef387f1234"
"hosting_subscription_id":"1010022"

Both these IDs may be found in POA Provider or Customer Control Panels.

The requests add_user and edit_user contain User Principal Name which may be found in POA Customer CP in user properties: 

"UserPrincipalName":"jdoe@customer.com"

So, having ID of PA subscription, ID of Office 365 customer or UPN of user it is easy to find corresponding method in the MOSI Gateway debug log.

For each top-level MOSI Gateway method at least 2 log entries are created:

  • 'executing method_name' - at the beginning of a method execution
  • 'finished method_name' - at the end of method call

The combination of method name and thread ID may be used to sort out log entries for given call.

Synchronous vs asynchronous MOSI methods

Synchronous MOSI methods

Most of MOSI methods are synchronous, they do not need callbacks from Microsoft. The request and corresponding response may be found below in the log using ID of MOSI Gateway thread, see example below.

Synchronous request to Microsoft cloud:

`2011-08-31 11:17:40,115 [ 6] DEBUG mosi-clients: >>> AddDomain({"Domain":{"ExtensionData":null,"Name":"officeplus.parallelscloud.com"}, "ExtensionData":null, "CustomerId":"13579649-dfd9-9753-9e71-20a21ab4d5e9", "SubscriptionId":"1234501f-5678-4276-b51e-2806833e41e5"})`

Reply from Microsoft:

`2011-08-31 11:17:42,439 [ 6] DEBUG mosi-clients: <<< AddDomain = {"ExtensionData":{}}`

In the example above we see request AddDomain with thread ID #6 ([ 6]), and below we see reply AddDomain with the same thread ID. This means reply was received exactly for request with the same thread ID.

Absolutely the same situation takes place for most other types of requests/replies.

Synchronous request from MOSI Gateway to Microsoft to create user (thread ID is 6):

`2011-08-31 11:46:55,773 [ 6] DEBUG mosi-clients: >>> AddUser ({"ExtensionData":null, "CustomerId":"13579649-dfd9-9753-9e71-20a21ab4d5e9", "Password":"EA59934-4854", "SubscriptionIds":["1234501f-5678-4276-b51e-2806833e41e5"], "UserInfo":{"ExtensionData":null, "BlockCredential":false, "City":"Vancouver", "Country":"Canada", "Department":"", "DisplayName":"John Doe", "Fax":"", "FirstName":"John", "LastName":"Doe", "MobilePhone":"", "Office":"", "PasswordNeverExpires":true, "PhoneNumber":"", "PostalCode":"", "PreferredLanguage":"en-US", "State":"", "StreetAddress":"", "StrongPasswordRequired":false, "Title":"", "UsageLocation":"USA", "UserPrincipalName":"johndoe@cloud.parallelscloud.com"}})`

Reply from Micosoft (thread ID is 6):

`2011-08-31 11:46:59,611 [ 6] DEBUG mosi-clients: <<< AddUser = {"ExtensionData":{},"Password":"*******-****"}`

Asynchronous MOSI methods

Let us consider the asynchronous MOSI method CreateCustomerAccount as an example. The sequence of steps to create customer account in Office 365 is provided below.

POA calls method add_customer on MOSI Gateway (customer ID is passed as parameter):

2011-06-25 23:45:05,407 [ 14] DEBUG endpoint  : executing add_customer(…"customer_id":"ea2da929-71c8-4bf9-bbcd-728466a72c63" …)

MOSI Gateway accepts request:

2011-06-25 23:45:05,407 [ 14] DEBUG flow  : Create customer: John Doe (ea2da929-71c8-4bf9-bbcd-728466a72c63:1001339)

MOSI Gateway sends request CreateCustomerAccount to Microsoft (customer ID is passed as parameter):

2011-06-25 23:45:05,563 [ 14] DEBUG mosi-clients: >>> CreateCustomerAccount(…CustomerId":"ea2da929-71c8-4bf9-bbcd-728466a72c63” ..)

Microsoft accepts request and sends aknowledgement:

2011-06-25 23:45:10,867 [ 14] DEBUG mosi-clients: <<< CreateCustomerAccount

MOSI Gateway saves information about customer into 2 tables in own database – csts (all customers) and waiting_customers (customers that are not created yet in Microsoft):

2011-06-25 23:45:10,882 [ 14] DEBUG entity  : waiting_customers create ea2da929-71c8-4bf9-bbcd-728466a72c63={"waiting_for":"Create"}
2011-06-25 23:45:10,914 [ 14] DEBUG entity  : csts create ea2da929-71c8-4bf9-bbcd-728466a72c63

MOSI Gateway starts to wait for callback from Microsoft (up to 300 seconds):

2011-06-25 23:45:10,976 [ 14] DEBUG wait  : - waiting for creation of customer John Doe (ea2da929-71c8-4bf9-bbcd-728466a72c63:1001339) up to 300 seconds
2011-06-25 23:45:12,988 [ 14] DEBUG wait  : - ... still waiting for creation of customer John Doe (ea2da929-71c8-4bf9-bbcd-728466a72c63:1001339) 2 of 300 seconds
2011-06-25 23:45:16,998 [ 14] DEBUG wait  : - ... still waiting for creation of customer John Doe (ea2da929-71c8-4bf9-bbcd-728466a72c63:1001339) 6 of 300 seconds

After some time customer account is being created in Microsoft and MOSI receives callback CustomerAccountCreated. Important - callback was received by another thread of MOSI Gateway process – 5 (original MOSI Gateway thread that sent request to create customer in Office 365 was thread #14), callback contains customer ID:

2011-06-25 23:47:18,865 [ 5] DEBUG callbacks  : CustomerAccountCreated:{"AdminUserName":"admin@cloud1001339.ccsctp.net","CustomerId":"ea2da929-71c8-4bf9-bbcd-728466a72c63", "DomainName":"cloud1001339.ccsctp.net","RequestId":"6aeeb6b2-bbae-4087-b041-2c6f36454377","TemporaryAdminPassword":"Vaxa4030"}

MOSI Gateway thread 5 which received callback removes customer from waiting queue:

2011-06-25 23:47:18,865 [ 5] DEBUG entity  : waiting_customers remove ea2da929-71c8-4bf9-bbcd-728466a72c63

And finally original thread 14 finishes customer creation process:

2011-06-25 23:47:49,051 [ 14] DEBUG wait  : - wait for creation of customer John Doe (ea2da929-71c8-4bf9-bbcd-728466a72c63:1001339) success, total time:158

Internal content