Lync Mobile

Lync Push Notifications: 504 Timeout Error

I ran into an issue at a customer recently where push notifications for mobility were not working. Upon further investigation, the messages were receiving a 504 timeout with the Push Notification Clearing House (PNCH).

 

For reference, the push process interacts with the PNCH, and then on to the Apple or Microsoft Push Services. This happens through Lync Federation, through a Lync Edge Server.

clip_image001

When you are testing push notifications, Test-CSMCXPushNotification is the cmdlet to use. This will actually attempt to send a push message to the clearing house and report back any errors.

When using this cmdlet, use the following syntax: Test-CSMCXPushNotification – AcessEdgeFQDN <INTERNAL EDGE POOL>

In my case, the error below was displayed:

PS C:\Users\rwintle> Test-CsMcxPushNotification -AccessEdgeFqdn edgepool.contoso.com

Test-CsMcxPushNotification : A 504 (Server time-out) response was received from the network and the operation failed. See the exception details for more information.

At line:1 char:27

+ Test-CsMcxPushNotification <<<<  -AccessEdgeFqdn edgepool.contoso.com
+ CategoryInfo          : OperationStopped: (:) [Test-CsMcxPushNotificatio
n], FailureResponseException
+ FullyQualifiedErrorId : WorkflowNotCompleted,Microsoft.Rtc.Management.Sy
ntheticTransactions.TestMcxPushNotificationCmdlet

After some investigation, Microsoft has confirmed that the Federation SRV record is required for push notifications to work properly.

The PNCH will perform a look up on the SIP Domain for the Federation SRV record (_sipfederationtls._tcp.contoso.com). If this does not succeed, a 504 error will be thrown.

To fix this issue, you must configure that SRV record to point to your access edge server used for outbound Lync Push Federation Requests.

(1258)

Posted on by Randy Wintle in Uncategorized 15 Comments

Lync Mobility Calculator (Alpha)

This calculator is alpha at best. I plan on hopefully fine tuning and adding more to this very soon.

 

What this does to date is calculate the memory you will require for your Lync FE servers to properly scale for Lync Mobility.

 

It requires you to enter your planned user bases (IOS/Windows Phone or Android/Nokia) and will output data based on the Microsoft Planning Formulas.

 

I do not take any credit for these formulas, I am simply putting them in a spreadsheet for easy access.

 

Let me know your thoughts in the comments, I will continue to update and hopefully make this a valuable tool!

(44)

Posted on by Randy Wintle in Uncategorized 3 Comments

Why Lync Mobile Call-Via-Work Makes Sense

 

 

Earlier this week, Microsoft released the Lync 2010 Mobile clients for all major platforms. (See more about that here http://lync.microsoft.com/en-us/Product/UserInterfaces/Pages/lync-2010-mobile.aspx)

With that release, a lot of people are talking about the lack of Voice over IP calling over 3G of Wifi in the product. Instead, Microsoft implemented a solution used for many years, referred to as “Call-Via Work”.

What is Call-Via-Work?

Call via work enables enterprises to deploy a consistently reliable enterprise voice solution to all mobile endpoints connecting to the Lync infrastructure. This functionality essentially bridges calls through the cell phone carrier network, and gives the appearance of a SIP call through your Lync identity.

This solution offers some great benefits:

  • A true “single number” solution, your identity is your work number. You can make or receive calls on this number from anydevice.
  • Battery friendly. This solution allows for users to actually utilize the tested and proven technology available on cell phones for years, reducing the impact on battery life when compared to a Voice over 3G, 4G or WiFi call.
  • Lync mobile users can call federated contacts.The call via work option allows users to make Lync calls to federated partners the same way it does to internal enterprise users, this is great because there is no gap in user capabilities from desktop to mobile.
  • I’ll say it again, Reliability! End users want a consistent experience, and do not want to be worried about the type of connection they are on when making a business call. Lets keep in mind, Lync is a business platform.

In some instances, VOIP makes sense, and lets face it, its kind of a popular technology right now. Everyone wants VOIP, not all end users know why they want it, but its just the new technology to use for most of them. However, it is important to understand that while it is a cool technology, with some potential for cost savings, a true enterprise grade solution cannot provide a reliable experience with VoIP on mobile devices, yet.

The potential savings that would be introduced through a VoIP solution deployed with Lync Mobile would definitely be eaten up by:

  • An overhaul of your Wireless Infrastructure. (If you want to deploy those fancy Cisco WAPs to support mobile VOIP, say good bye to any cost savings introduced by VOIP calling on your mobile)
  • Help Desk costs are a real problem in enterprise environments, these would definitely increase as users start having a poor experience when in an airport, or in a faux 4G area on an overloaded cell tower that provides limited bandwidth.
  • Costs for data vs cell minutes. Not many people know, but it isn’t always true that cell phone data is cheaper than cell phone minutes. Specifically when in roaming, and roaming international scenarios.In some instances, a roaming international 3G or 4G call could cost as much as 50 times more per minute than a roaming cell call…

So, to summarize:

Microsoft has done their research, they are not ignoring the fact that enabling mobile endpoints to communicate anywhere through their enterprise environment is important. What they are doing is deploying it properly! I would rather have a working, reliable solution, than have all the features in the world, that work half the time and provide me with a poor experience.

(697)

Posted on by Randy Wintle in Uncategorized 21 Comments

How To: Lync Mobile Diagnostic Logs

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.

image

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.

Discovery:

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).

Discovery 2:

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.

Discovery 3:

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

Discovery 4:

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.

Discovery 5:

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.776-5 : Verbose : 526265910 : HttpRequestPump : Request IssueWT to
https://<EXTWEBSERVICEURL>.unifysquare.com/WebTicket/WebTicketService.svc requires metadata.
2011-12-13 13:47:32.780-5 : Verbose : 526265910 : MetadataManager : Got a resolve request for
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.

Discovery 6:

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.094-5 : Info : 526265910 : MetadataManager : Resolved metadata for SOAP service https://<EXTWEBSERVICEURL>..unifysquare.com/WebTicket/WebTicketService.svc. WT: , WTI: , LI: , F: https://<EXTWEBSERVICEURL>..unifysquare.com/WebTicket/WebTicketService.svc/Auth
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.

Discovery 7:

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.515-5 : Verbose : 527118098 : ConfigurationResolver : Value for internal auto-discover is
https://<INTWEBSERVICEURL.unifysquare.com/Autodiscover/AutodiscoverService.svc/root.
2011-12-13 13:47:33.515-5 : Verbose : 527118098 : ConfigurationResolver : Value for external auto-discover is
https://<EXTWEBSERVICEURL>.unifysquare.com/Autodiscover/AutodiscoverService.svc/root.
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 : Got a resolve request for
https://<EXTWEBSERVICEURL>..unifysquare.com/Mcx/McxService.svc.
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.

Subscribes:

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 : channelUri ==> ‘
https://sn1.notify.live.net/unthrottledthirdparty/01.00/AAGxpT9ydENsQrJtJmbd3b1BAgAAAAADbQAAAAQUZm52OjYxNzgzODM2OUI2NkYzN0I’
2011-12-13 13:47:34.929-5 : Info : 485963238 : PushNotificationChannel : Notification channel URI: https://sn1.notify.live.net/unthrottledthirdparty/01.00/AAGxpT9ydENsQrJtJmbd3b1BAgAAAAADbQAAAAQUZm52OjYxNzgzODM2OUI2NkYzN0I
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 : Internal search url:
https://<INTWEBSERVICEURL>.unifysquare.com/groupexpansion/service.svc.
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 : Internal photo url:
https://<INTWEBSERVICEURL>.unifysquare.com/abs/handler.
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 : Internal group expansion url:
https://<INTWEBSERVICEURL>.unifysquare.com/groupexpansion/service.svc.
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.

Navigation:

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.

(1840)

Posted on by Randy Wintle in Uncategorized 14 Comments