How To: Lync Mobile Diagnostic Logs

image

Lync Mobile has the ability to send diagnostic logs from the client to the administrator. However, there is no documentation on what to do with this information if you are the administrator!

Sending the Logs

On Windows Phone, you first must enable diagnostic logging under the Settings section of the application.

In order to send these diagnostic logs, you will need to navigate to the About section of the application.

A button will be there allowing you to send your diagnostic logs. This saves a file to your phone as a JPG (instructions on screen are very clear), and creates an email that you must attach that JPG too.

Now, that is a bit confusing, but at least the application tells you to do all of that pretty clearly.

Receiving the Logs

As the administrator, you will receive an email containing the JPG with embedded data, and the relevant device information.

Through some trial and error, I was able to decide saving this JPG as a .LOG file produces the best results. Opening this in a file editor like Notepad ++ has given me the easiest view of this information.

image

Reading the Logs

Once you open this file, there will be a big confusing bit of information at the top, as of right now I have no idea what this is for, but just ignore it:

image

After the mess, you will see some text. A lot of this is deep diagnostic information, however you can start to make sense of what is happening. The example shown here is during a sign on+ sending and receiving a single IM.

2011-12-13 13:47:31.302-5. Info. 527118098. CredentialManager. Got a new user credential from app layer.

2011-12-13 13:47:31.304-5. Info. 527118098. TrustManager. Adding unifysquare.com to trusted domain list for Autodiscovery .

2011-12-13 13:47:31.309-5. Info. 527118098. DiscoverySession. Uri for request IntDisc_https is https://lyncdiscoverinternal.unifysquare.com/?sipuri=rwintle@unifysquare.com .

2011-12-13 13:47:31.309-5. Info. 527118098. DiscoverySession. Uri for request IntDisc_http is http://lyncdiscoverinternal.unifysquare.com/?sipuri=rwintle@unifysquare.com .

2011-12-13 13:47:31.350-5. Info. 527118098. LogonSession. SignInState: SigningIn

The highlighted text shows when I try to login, this is showing my SIP Domain as being entered, and then the URLs it will use for internal discover (internal first, then external).

Requests to the internal servers will fail, as I am remote:

2011-12-13 13:47:31.543-5. Info. 527118098. LogonSession. New LogonSession internal state = DiscoveringServer

2011-12-13 13:47:32.123-5. Warning. 485963238. HttpRequestPump. Got a WebException while reading the response for IntDisc_https.

2011-12-13 13:47:32.124-5. Error. 485963238. HttpRequestPump. Request IntDisc_https failed due to an unidentified network error.

2011-12-13 13:47:32.124-5. Error. 485963238. HttpRequestPump. Calling back IntDisc_https with error ConnectionError [Error, Transport, TransportFramework].

2011-12-13 13:47:32.131-5. Info. 527118098. ConfigurationResolver. A discover request has failed. Waiting for parallel request result.

2011-12-13 13:47:32.135-5. Warning. 526265910. HttpRequestPump. Got a WebException while reading the response for IntDisc_http.

2011-12-13 13:47:32.135-5. Error. 526265910. HttpRequestPump. Request IntDisc_http failed due to an unidentified network error.

2011-12-13 13:47:32.136-5. Error. 526265910. HttpRequestPump. Calling back IntDisc_http with error ConnectionError [Error, Transport, TransportFramework].

2011-12-13 13:47:32.149-5. Info. 527118098. ConfigurationResolver. Internal autodiscovery requests failed. Trying external.

Remember, the client tries HTTPS and HTTP, see the above highlighted sections for this example.

Next the client will try the external discovery URLs: (some information has been modified)

2011-12-13 13:47:32.149-5. Info. 527118098. DiscoverySession. Uri for request ExtDisc_https is https://lyncdiscover.unifysquare.com/?sipuri=rwintle@unifysquare.com .

2011-12-13 13:47:32.149-5. Info. 527118098. DiscoverySession : Uri for request ExtDisc_http is http://lyncdiscover.unifysquare.com/?sipuri=rwintle@unifysquare.com .

2011-12-13 13:47:32.471-5. Info. 526265910. HttpRequestPump. Completed request ExtDisc_http.

2011-12-13 13:47:32.479-5. Info. 527118098. ConfigurationResolver. Redirect to https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root?sipuri=rwintle@unifysquare.com requires a trust decision.

2011-12-13 13:47:32.482-5. Info. 527118098. TrustManager. Trust of https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root?sipuri=rwintle@unifysquare.com for Autodiscovery is inherited through unifysquare.com.

2011-12-13 13:47:32.484-5. Info. 527118098. TrustManager. Redirection to https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root?sipuri=rwintle@unifysquare.com is trusted for Autodiscovery

In the highlighted sections above, the client attempts to connect to the external URL for lyncdiscover and succeeds. This request then redirects the client to the External Web Services URL, as expected. Because the SIP Domain matches what I entered, it is trusted for AutoDIscovery

Next, the client must discover where to perform web ticket authentication requests:

2011-12-13 13:47:32.644-5. Verbose. 527118098. HttpRequestPump. Request AuthDisc to https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user requires metadata.

2011-12-13 13:47:32.645-5. Verbose. 527118098. MetadataManager. Got a resolve request for https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user .

2011-12-13 13:47:32.765-5. Warning. 526265910. HttpRequestPump. Got a WebException while reading the response for UnauthGethttps://<EXTWEBSERVICEURL>..unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user.

2011-12-13 13:47:32.766-5. Info. 526265910. MetadataManager. Found web ticket issuer header for unauthenticated get.

2011-12-13 13:47:32.766-5. Error. 526265910. HttpRequestPump. Parsed error from failed response to UnauthGethttps://<EXTWEBSERVICEURL>..unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user. Status=AcceptErrorResponse [Error, Transport, TransportFramework].

2011-12-13 13:47:32.767-5. Error. 526265910. HttpRequestPump. Calling back UnauthGethttps://<EXTWEBSERVICEURL>..unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user with error AcceptErrorResponse [Error, Transport, TransportFramework].

From what I can tell, the discovery request is sent, and a WebException is expected. This appears to be simply a discovery/connectivity check for the services.

You can see it does find a Web Ticket Issuer Header, at this point it needs to try Web Ticket Authentication.

This process below shows the discovery process ending, it returns the web ticket URL and completes discovery.

2011-12-13 13:47:32.774-5. Info. 526265910. WebTicketManager. Sending a new web ticket request for https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root/user to issuer https://<EXTWEBSERVICEURL>.unifysquare.com/WebTicket/WebTicketService.svc .

2011-12-13 13:47:32.800-5. Info. 520886686. HttpRequestPump. Completed request ExtDisc_https.

First, you see the client is sending a new web ticket request to the web ticket URL. Then you see that the ExtDisc_https process has completed.

At this point, there is a lot of back and forth about web ticket authentication and negotiation, so I will leave that out. However, the end of the process is important to know:

2011-12-13 13:47:33.101-5. Info. 526265910. CredentialManager. Asking for user credentials from app layer.

2011-12-13 13:47:33.101-5. Info. 526265910. HttpRequestPump. Completed request MEXhttps://<EXTWEBSERVICEURL>..unifysquare.com/WebTicket/WebTicketService.svc.

2011-12-13 13:47:33.113-5. Info. 527118098. CredentialManager. Got a new user credential from app layer.

2011-12-13 13:47:33.342-5. Info. 520886686. HttpRequestPump. Completed request IssueWT.

2011-12-13 13:47:33.490-5. Info. 485963238. HttpRequestPump. Completed request AuthDisc.

You see the client resolving the URLs for the web ticket service, and then requesting credentials. The credentials are accepted, and then the processes complete.

At this point, the client can sign in to the service because they have received a web ticket from the Lync Server.

This is basically the client summarizing what just happened, the values for the MCX service URLS, where it needs to go, and starting the sign-in process:

2011-12-13 13:47:33.515-5. Verbose. 527118098. ConfigurationResolver. Value for internal MCX is https://<EXTWEBSERVICEURL>.unifysquare.com/Mcx/McxService.svc .

2011-12-13 13:47:33.515-5. Verbose. 527118098. ConfigurationResolver. Value for external MCX is https://<EXTWEBSERVICEURL>.unifysquare.com/Mcx/McxService.svc .

2011-12-13 13:47:33.517-5. Info. 527118098. ConfigurationResolver. Discovery complete for rwintle@unifysquare.com. Internal MCX: https://<EXTWEBSERVICEURL>.unifysquare.com/Mcx/McxService.svc . External MCX: https://<EXTWEBSERVICEURL>.unifysquare.com/Mcx/McxService.svc . Is internal? False.

2011-12-13 13:47:33.532-5. Info. 527118098. InternalExternalSelector. Setting mode to EXTERNAL

2011-12-13 13:47:33.532-5. Info. 527118098. InternalExternalSelector : Configuring Transport to use EXTERNAL URLs

2011-12-13 13:47:33.533-5. Info. 527118098. LogonSession : Server discovery complete. Beginning sign-in.

So after all of that, the client has all of the URLs it needs to connects. The client then determines it is an external client, and will connect to external URLs.

Sign In Process:

Now that the client is starting to sign in, we will see actual requests to the MCX service, and usage of the web ticket requested before:

2011-12-13 13:47:33.537-5. Info. 527118098. Mcx14Session. InitSession request: Culture ‘en-US’, UA ‘WPLync/4.0.7878.0 (Microsoft Windows CE 7.10.7720; SAMSUNG SGH-i937 2103.11.10.1)’.

2011-12-13 13:47:33.538-5. Verbose. 527118098. HttpRequestPump. Request InitSess to https://<EXTWEBSERVICEURL>.unifysquare.com/Mcx/McxService.svc requires metadata.

2011-12-13 13:47:33.538-5. Verbose. 527118098. MetadataManager. Using cached metadata for service https://<EXTWEBSERVICEURL>..unifysquare.com/Mcx/McxService.svc .

2011-12-13 13:47:33.538-5. Verbose. 527118098. WebTicketManager. Got a web ticket request for endpoint https://<EXTWEBSERVICEURL>..unifysquare.com/Mcx/McxService.svc . Issuer is https://<EXTWEBSERVICEURL>..unifysquare.com/WebTicket/WebTicketService.svc .

2011-12-13 13:47:33.539-5. Verbose. 527118098. WebTicketManager : Using cached web ticket for https://<EXTWEBSERVICEURL>..unifysquare.com/Mcx/McxService.svc .

2011-12-13 13:47:33.539-5.

Info. 527118098. LogonSession. New LogonSession internal state = SigningIn

2011-12-13 13:47:34.062-5. Info. 485963238. Mcx14Session. Session id: f17e4c4f-77b6-2a7d-3072-21992b111614

Sip Uri: sip:rwintle@unifysquare.com

2011-12-13 13:47:34.062-5. Info. 485963238. HttpRequestPump. Completed request InitSess .

2011-12-13 13:47:34.075-5. Info. 527118098. LogonSession. SignInState: SignedIn

First, you will see the request being prepared with all information about my phone and software running.

Next, it makes a request to the MCX service with that information.

The service requests a web ticket, the client responds with the cached web ticket from eralier.

A new session is created, there is a Session ID and my associated SIP URI.

Then the sign in process completes, and I am marked as signed in.

At this point my client immediately starts subscribing to users to show me presence information. Below are some examples:

2011-12-13 13:47:34.087-5. Verbose. 527118098. PresenceSubscriptionManager. Subscribing uris…

2011-12-13 13:47:34.088-5. Verbose. 527118098. PresenceSubscriptionManager. (sub) sip:kevinp@unifysquare.com

Push Subscription:

I don’t know the details of how this works, but at this point my client will register with the push notification service. I will not attempt to explain it all, but it does seem that my client registers with the service with a (very) unique ID.

011-12-13 13:47:34.110-5. Info. 527118098. TransactionManager. Opened a transaction for Mcx request Sub2264 with id 2264.

2011-12-13 13:47:34.111-5. Info. 527118098. PushNotificationChannel. Desired ==> True

2011-12-13 13:47:34.111-5. Info. 527118098. PushNotificationChannel. Syncing actual=Closed to desiredOpen=True

2011-12-13 13:47:34.111-5. Info. 527118098. PushNotificationChannel. Attempting to open channel

2011-12-13 13:47:34.230-5. Info. 527118098. PushNotificationChannel. Actual ==> Opening

2011-12-13 13:47:34.230-5. Info. 527118098. PushNotificationChannel. Syncing actual=Opening to desiredOpen=True

2011-12-13 13:47:34.230-5. Info. 527118098. PushNotificationSynchronizer. Attempting to sync remote=” to local=”

2011-12-13 13:47:34.233-5. Info. 527118098. TransactionManager. Opened a transaction for Mcx request PushUnsub2265 with id 2265.

2011-12-13 13:47:34.280-5. Info. 527118098. TransactionManager. Opened a transaction for Mcx request Activity2266 with id 2266.

2011-12-13 13:47:34.284-5. Info. 527118098. LogonSession. New LogonSession internal state = SignedIn

2011-12-13 13:47:34.284-5. Info. 527118098. LogonSession. Doing UI callback with Ok [Warning, Global, Global]

2011-12-13 13:47:34.401-5. Info. 527118098. AppLayerHelper. SignIn completed with Ok [Warning, Global, Global]

2011-12-13 13:47:34.929-5. Info. 485963238. PushNotificationChannel. Actual ==> Open

2011-12-13 13:47:34.929-5. Info. 485963238. PushNotificationChannel. Syncing actual=Open to desiredOpen=True

2011-12-13 13:47:35.639-5. Info. 485963238. TransactionManager. Transaction succeeded synchronously for request 2264 (Sub2264).

2011-12-13 13:47:35.639-5. Info. 485963238. HttpRequestPump. Completed request Sub2264.

In Band Settings:

Next, my lync client must receive its in band settings from the server.

2011-12-13 13:47:35.663-5. Info. 526265910. Mcx14Session. Got an inband settings event.

2011-12-13 13:47:35.664-5. Info. 526265910. Mcx14Session. External search url: https://<EXTWEBSERVICEURL>.unifysquare.com/groupexpansion/service.svc .

2011-12-13 13:47:35.665-5. Info. 526265910. Mcx14Session. External photo url: https://<EXTWEBSERVICEURL>.unifysquare.com/abs/handler .

2011-12-13 13:47:35.666-5. Info. 526265910. Mcx14Session : External group expansion url: https://<EXTWEBSERVICEURL>.unifysquare.com/groupexpansion/service.svc .

2011-12-13 13:47:35.692-5. Info. 526265910. Mcx14Session. Inband photoUsage: AllPhotos. UsePhotos inband setting: True.

2011-12-13 13:47:35.693-5. Info. 526265910. Mcx14Session. Simulring inband setting is True.

2011-12-13 13:47:35.693-5. Info. 526265910. Mcx14Session. Call forwarding inband setting is True.

2011-12-13 13:47:35.698-5. Info. 526265910. Mcx14Session. Delegation inband setting is True.

2011-12-13 13:47:35.699-5. Info. 526265910. Mcx14Session. Team call inband setting is True.

2011-12-13 13:47:35.699-5. Info. 526265910. Mcx14Session : Max photo size inband setting is 30kB.

2011-12-13 13:47:35.700-5. Info. 526265910. Mcx14Session. Inband voice mail url is sip:rwintle@unifysquare.com;opaque=app:voicemail.

2011-12-13 13:47:35.700-5. Info. 526265910. Mcx14Session. Push notifications inband setting is True.

==> True

2011-12-13 13:47:35.700-5. Info. 526265910. Mcx14Session. Outside voice inband setting is True.

2011-12-13 13:47:35.718-5. Info. 526265910. Mcx14Session. UC Enabled inband setting is True.

2011-12-13 13:47:35.718-5. Info. 526265910. Mcx14Session. Inband setting for dial string: 911. Dial mask: 112.

2011-12-13 13:47:35.720-5. Info. 526265910. Mcx14Session. Got inband location profile USBellevue.unifysquare.com with 9 rules.

This section essentially downloads all of my in band settings. Not the same list as would be on the Lync 2010 client, but all that pertain to the mobile client.

Because this is such a deep diagnostic log, you can even see when you swipe between screens:

2011-12-13 13:47:38.337-5. Info. 527118098. NavigationManager. Navigating to: /UI/Pages/Conversation.xaml?ID=a374aeff-a30a-4c5c-874e-c59872724734

Contact Groups

Next, the application must populate my contact groups, this is consistent with my Lync 2010 desktop client:

2011-12-13 13:47:41.269-5. Info. 193134654. Mcx14Session. Processing full MCX contact list.

2011-12-13 13:47:41.270-5. Info. 193134654. Mcx14Session. Group 1 (

) of type add to contact list.

2011-12-13 13:47:41.305-5. Info. 193134654. Mcx14Session. Group 2 (Pinned Contacts) of type pinnedGroup add to contact list.

2011-12-13 13:47:41.306-5. Info. 193134654. Mcx14Session. Group 5 (Unify Square US Team) of type dg add to contact list.

At this point each group is populated with contacts, and each contact is processed, including all details. Contact Information, photos, out of office notes, personal notes etc.

Conversation:

This one is a bit harder to follow, but I initiated an IM conversation with Kevin Peters (www.ocsguy.com ) from UnifySquare, there is a setup process, as well as session state information (typing):

This first section is me setting up the conversation for an invite, this is me sending an IM to Kevin:

2011-12-13 13:47:44.504-5. Info. 527118098. Conversation. Conversation Acy5okwZF8gNekrvgE69WfKPooiAXg== is disconnected. Sending invite with message.

2011-12-13 13:47:44.514-5. Info. 527118098. ConversationParticipant. IMState: Disconnected==>Connecting for sip:rwintle@unifysquare.com

2011-12-13 13:47:44.514-5. Info. 527118098. TransactionManager. Opened a transaction for Mcx request ConvInvite2271 with id 2271

Next it appears the conversation is setup between Kevin and I on the server:

2011-12-13 13:47:47.529-5. Info. 527118098. Mcx14Session. Calling back rid 2271 (ConvInvite2271) with status Ok [Warning, Global, Global].

2011-12-13 13:47:47.562-5. Info. 527118098. Conversation. message = “grt”, errorCode = Ok [Warning, Global, Global]

2011-12-13 13:47:47.682-5. Info. 520886686. Mcx14Session. Got a Full conversation state event for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==.

2011-12-13 13:47:47.685-5. Info. 520886686. Mcx14Session. Got Full session state for conv Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==. Active: True. ConfUri. Locked. Modalities: Text.

2011-12-13 13:47:47.687-5. Info. 520886686. Mcx14Session. Got a Full roster state for conv Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==. Conv size: 2. Roster supressed: False.

2011-12-13 13:47:47.690-5. Info. 520886686. Mcx14Session. Got Full participant state for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:rwintle@unifysquare.com. Lobby. IM: Connected. Voice: Disconnected.

2011-12-13 13:47:47.693-5. Info. 520886686. Mcx14Session. Got Full participant state for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:kevinp@unifysquare.com. Lobby. IM: Connected. Voice: Disconnected.

Next, we both accept the conversation, essentially Kevin has opened the window on his PC Client and is typing a reply:

2011-12-13 13:47:47.715-5. Info. 527118098. Conversation. Updating state for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==. Conference Uri. Active: True. Locked: False.

2011-12-13 13:47:47.722-5. Info. 527118098. Conversation. Updating IM state for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/ sip:rwintle@unifysquare.com from Connecting to Connected.

2011-12-13 13:47:47.722-5. Info. 527118098. ConversationParticipant. IMState: Connecting==>Connected for sip:rwintle@unifysquare.com

2011-12-13 13:47:47.723-5. Info. 527118098. Conversation. Updating IsInLobby for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:rwintle@unifysquare.com to False.

2011-12-13 13:47:47.726-5. Info. 527118098. Conversation. Updating source network for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:rwintle@unifysquare.com to Unknown.

2011-12-13 13:47:47.726-5. Info. 527118098. Conversation. Updating IM state for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/ sip:kevinp@unifysquare.com from Disconnected to Connected.

2011-12-13 13:47:47.726-5. Info. 527118098. ConversationParticipant. IMState: Disconnected==>Connected for sip:kevinp@unifysquare.com

2011-12-13 13:47:47.732-5. Info. 527118098. Conversation. Updating IsInLobby for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:kevinp@unifysquare.com to False.

2011-12-13 13:47:47.732-5. Info. 527118098. Conversation. Updating source network for Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:kevinp@unifysquare.com to SameEnterprise .

2011-12-13 13:47:47.755-5. Info. 527118098. Conversation. Sending isTyping = True request to MCX for conversation Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==.

The log shows that Kevin is in my Enterprise, and is Typing (as seen at the end).

Next, Kevin finishes typing and sends his message. The server receives the message, and then my client Receives the message:

2011-12-13 13:47:51.610-5. Info. 193134654. Mcx14Session. Got a typing event for conv Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==.

2011-12-13 13:47:51.612-5. Info. 193134654. Mcx14Session. Got a message from Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:kevinp@unifysquare.com.

2011-12-13 13:47:51.612-5. Info. 193134654. HttpRequestPump. Completed request Mcx14Poll.

2011-12-13 13:47:51.620-5. Info. 527118098. Mcx14Session. Dispatching async event to app layer.

2011-12-13 13:47:51.621-5. Info. 527118098. Conversation. Received IM from Acy5x7NSo51yZyl3n0GYx+YtC9J5Aw==/sip:kevinp@unifysquare.com.

Again, this log is not the easiest to read, but hoped to help some understand (as well as myself) what is going on with transactions on the phone.

Source: blog.ucmadeeasy.com

Category: Forex

Similar articles: