Skype for Business Web App -Debugging

Wenn Anwender an einem Skype for Business Meeting mit einem PC teilnehmen, der selbst keinen Skype for Business Client hat, dann erkennt das Skype for Business und bietet dem Anwender den Download der Skype for Business WebApp an und startet das Meeting mit dieser App. So kann auch ein Anwender am PC per Audio und Video teilnehmen. Ohne die App ist nur eine Teilnahme per Browser für Chat und PowerPoint-Sharing möglich. Da aber auch eine Meeting-Teilnahme mit der App scheitern kann, beschreibe ich hier die Optionen der Fehlersuche. Die ist nämlich alles andere als "einfach". Wie gehen Sie mit so einer nichtssagenden Meldung um ?

Mehr ist hier nicht zu sehen. Also müssen wir auf die Suche nach Protokollen gehen.

Logfiles überall

Sysinternals "Process Monitor" ist ein geeignetes Werkzeug, um Programmen auf die Finger zu schauen und schon recht schnell sind die Pfade zu den Protokolldateien zu erkennen:

Es sind schon mal zwei Prozesse, die unterschiedliche Logdateien mit einem Zeitstempel schreiben.

Da stellt sich natürlich die Frage, in welchen Dateien welche Daten stehen. In meinem Beispiel war es ein fehlerhafter Verbindungsaufbau zu einem Kunden, bei dem Audio nicht funktioniert hat. Insofern habe ich erwartet, dass ich in den Logdateien irgendwas zu MRAS, ICEWARN,  INVITE, "m=audio", SDP o..ä finde. Das war letztlich dann aber doch nicht so einfach, da einige Informationen leider in XML-Strukturen enthalten sind und daher BASE64 codiert sind. Dennoch hier ein Versuch ein paar Auszüge aus den Dateien zu analysieren

Wo ist der INVITE und Candidates in JavaScript_yyyy-mm-dd_hh_mm_ss.log

Auch wenn die Teilnahme per WebApp erfolgt und HTTPS intensiv genutzt wird (Siehe Trace:LyncWebAppJoin) werden Audio/Video und Desktopsharing natürlich per RTP über den Edge übertragen. Selbst in Verbindung mit WebApp ist das ein INVITE mit SDP Kandidaten etc. Nur dass dieser Invite per UCWA eingeliefert wird. er muss aber zu finden sein.

Eine direkte Suche nach "INVITE" hat zwar einige Treffer geliefert, aber nicht was ich so erwartet hätte. Über eine Suche nach CANDIDATES" kommt man hier weiter und so finde ich die ausgehende Einladung per UCWA:

10:24:5:306, TL_INFO, , UCWASpecificCommunication, Sending Request for: POST:/ucwa/v1/applications/11283xxxx/
   communication/audioVideoInvitations?conversation=%guid%_26,  
   Lync_Client_Model_Session_UCWACommunicationContext$sendRequest
10:24:5:307, TL_INFO, , UCWASpecificCommunication, aqcuring connectin isHighPriority true, 
   url /ucwa/v1/applications/11283xxxx/communication/audioVideoInvitations?conversation=%guid%,  
   Lync_Client_Model_Session_UCWACommunicationContext$getConnectionObject
10:24:5:307, TL_INFO, , UCWASpecificCommunication, Getting high priority connection false,  
   Lync_Client_Model_Session_UCWAConnectionPool$getHighPriRequestConnection
10:24:5:307, TL_INFO, , UCWASpecificCommunication, <headers>,  
      Lync_Client_Model_Session_UCWACommunicationContext$sendRequest
      Content-Type: multipart/related;boundary=E650D65A-EA75-4A6D-83F9-CC94AA2E7FD8;
            type="application/vnd.microsoft.com.ucwa+json",  
      Accept: application/vnd.microsoft.com.ucwa+json,
      Content-Length: 2672,
   <\headers>,  Lync_Client_Model_Session_UCWACommunicationContext$sendRequest
10:24:5:308, TL_INFO, , UCWASpecificCommunication, <request>
%!PII!{"operationId":"%gui%","sessionContext":"%guid%",
    "mediaOffer":"cid:%gui%","telemetryId":"%gui%",
    "joinAudioMuted":true,"joinVideoMuted":false,"to":null}
!
<\request>,  Lync_Client_Model_Transport_TransportUtils$
10:24:5:308, TL_INFO, , UCWASpecificCommunication, <request>
%!PII!v=0
o=- 0 0 IN IP4 192.168.178.55
s=session
c=IN IP4 192.168.178.55
b=CT:99980
t=0 0
m=audio 5062 RTP/AVP 117 104 114 9 112 111 0 103 8 116 115 97 13 118 101
a=x-ssrc-range:303082752-303082752
a=rtcp-fb:* x-message app send:dsh recv:dsh
a=rtcp-rsize
a=label:main-audio
a=x-source:main-audio
a=ice-ufrag:Acyd
a=ice-pwd:B92PPdLYO7W740dNNok2SHEZ
a=candidate:1 1 UDP 2130706431 192.168.178.55 5062 typ host 
a=candidate:1 2 UDP 2130705918 192.168.178.55 5063 typ host 
a=candidate:2 1 UDP 2130705919 192.168.56.1 23162 typ host 
a=candidate:2 2 UDP 2130705406 192.168.56.1 23163 typ host 
a=candidate:3 1 UDP 2130705407 192.168.182.1 31442 typ host 
a=candidate:3 2 UDP 2130704894 192.168.182.1 31443 typ host 
a=candidate:4 1 UDP 2130704895 192.168.23.1 14418 typ host 
a=candidate:4 2 UDP 2130704382 192.168.23.1 14419 typ host 
a=candidate:5 1 UDP 2130704383 192.168.178.77 3564 typ host 
a=candidate:5 2 UDP 2130703870 192.168.178.77 3565 typ host 
a=candidate:6 1 TCP-ACT 1684796927 192.168.178.55 5062 typ srflx raddr 192.168.178.55 rport 5062 
a=candidate:6 2 TCP-ACT 1684796414 192.168.178.55 5062 typ srflx raddr 192.168.178.55 rport 5062 
a=cryptoscale:1 client AES_CM_128_HMAC_SHA1_80 inline:jPm0fqQoHTuO3+AURYNHqvYoioBcgMjgwmKpbzM+|2^31|1:1
a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:fSmv/RdbbF6WKbQYxuV2vVgESxH+1W9G6CmahEEP|2^31|1:1
a=crypto:3 AES_CM_128_HMAC_SHA1_80 inline:i+JZZL0TCG0SNsOzqEXiRNccE2RGS8DiS5bRd5kX|2^31
a=maxptime:200
a=rtcp:5063
a=rtpmap:117 G722/8000/2
a=rtpmap:104 SILK/16000
a=fmtp:104 useinbandfec=1; usedtx=0
a=rtpmap:114 x-msrta/16000
a=fmtp:114 bitrate=29000
a=rtpmap:9 G722/8000
a=rtpmap:112 G7221/16000
a=fmtp:112 bitrate=24000
a=rtpmap:111 SIREN/16000
a=fmtp:111 bitrate=16000
a=rtpmap:0 PCMU/8000
a=rtpmap:103 SILK/8000
a=fmtp:103 useinbandfec=1; usedtx=0
a=rtpmap:8 PCMA/8000
a=rtpmap:116 AAL2-G726-32/8000
a=rtpmap:115 x-msrta/8000
a=fmtp:115 bitrate=11800
a=rtpmap:97 RED/8000
a=rtpmap:13 CN/8000
a=rtpmap:118 CN/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp-mux
a=ptime:20

!
<\request>,  Lync_Client_Model_Transport_TransportUtils$$Q

Man kann gut erkennen, dass mein Client sehr viele lokale IP-Adressen vom "typ host" hat und die NAT-Adresse nicht gültig ist. Zudem gibt es hier komplett keine TURN-Kandidaten. Damit ist eigentlich schon klar, warum in diesem Fall die Audio-Verbindung nicht aufgebaut werden konnte. Insbesondere wenn ich weitersuche und die Antwort der Gegenseite sehe.

10:24:5:713, TL_INFO, , UCWASpecificCommunication, <response>
%!PII!v=0
o=- 5 0 IN IP4 192.168.100.103
s=session
c=IN IP4 192.168.100.103
b=CT:1000000
t=0 0
m=audio 49742 RTP/SAVP 117 9 111 0 8 97 13 118 101
c=IN IP4 192.168.100.103
a=rtcp-rsize
a=rtcp-fb:* x-message app send:dsh recv:dsh
a=x-ssrc-range:2603-2603
a=x-source-streamid:20
a=rtcp:49742
a=ice-ufrag:XEd2
a=ice-pwd:3/Ir4N9IMd69MjrtDl9Nytj4
a=rtcp-mux
a=candidate:1 1 UDP 2130706431 192.168.100.103 49742 typ host
a=candidate:5 1 tcp-act 1684797439 192.168.100.103 49742 typ srflx raddr 192.168.100.103 rport 49742
a=label:main-audio
a=cryptoscale:1 server AES_CM_128_HMAC_SHA1_80 inline:CR9S1Tk20AS1IAOIXQ02rgLQS4+pRYxlfKLbGPDs|2^31|1:1
a=x-audioflow:sendonly
a=x-dtmfflow:recvonly
a=rtpmap:117 g722/8000/2
a=fmtp:117 bitrate=128000
a=rtpmap:9 g722/8000
a=rtpmap:111 SIREN/16000
a=fmtp:111 bitrate=16000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 RED/8000
a=rtpmap:13 CN/8000
a=rtpmap:118 CN/16000
a=rtpmap:101 telephone-event/8000
a=ptime:20
!
<\response>,  Lync_Client_Model_Transport_TransportUtils$$Q

Hier gibt es ebenfalls nur zwei Kandidaten, von denen der erste natürlich der direkte Weg ist und der NAT-Kandidat (srflx) ungültig ist. Diese Gegenstelle ist sicher nur aus dem internen LAN erreichbar aber sicher nicht aus dem Internet und schon gar nicht über einen Edge-Server. Damit ist schon mal klar, warum hier keine Verbindung zustande kommt.

MRAS in JavaScript_yyyy-mm-dd_hh_mm_ss.log

Immer, wenn in den Kandidaten die "TURN-Candidates" fehlen, gibt es zwei Stellen, die hierbei zu prüfen sind.

  • MRAS (Siehe MRAS Edge)
    Ein Client, der von einem Skype for Business Edge Server einen RTP-Kandidaten anfordern möchte, muss sich anmelden. Dazu benötigt er ein MRAS-Token, welches der Server dem Client er SIP, oder in diesem besonderen Fall per UCWA übermittelt. Dazu muss allerdings der Pool mit dem Edge Server über 5062 kommunizieren können.
  • 3478/UDP
    Mit dem MRAS-Token muss der Client sich am Edge Server von innen oder außen über Port 3478 verbinden, das Token vorweisen und eine Reservierung anfordern

Eines oder beide Schritt sind in dem Beispiel nicht möglich und damit bekommt der Client kein MRAS-Token. Ich habe natürlich gehofft, auch diesen Fehler in den Logfiles zu finden und wurde fündig (Umbrüche zur Lesbarkeit addiert):

10:23:58:464, TL_INFO, , MediaPlatformConfig, 
    Media settings url /ucwa/v1/applications/11283xxxx/mediaPolicies, 
    MRAS url /ucwa/v1/applications/11283xxxx/communication/mediaRelayAccessToken, 
    Lync_Client_Model_Conversation_MediaPlatformConfig
    $start 

10:23:59:538, TL_ERROR, , MediaPlatformConfig, 
    MRAS token retrieval failed with error 2147680262, 
    Lync_Client_Model_Conversation_MediaPlatformConfig
    $$Kl_2, STACKTRACE:: 

In dem großen 1.3 Megabyte großen File ist nur an zwei Stellen der String "MRAS" zu finden. Aber das reicht aus um gar nicht mehr weiter die Verbindung per 3478/UDP per Netmon zu prüfen. Ohne MRAS-Kandidaten kann der Client nicht arbeiten.

PNP Devices PluginHost_yyyy-mm-dd_hh_mm_ss.log

In dieser Datei finden Sie u.a. Informationen zu den Audio und Video-Geräte, die das Plug-In erkannt hat. (Umbrüche zur Lesbarkeit addiert)

11748, 18596, 2016-03-21 10:24:03.753, TL_INFO, <no file info>, Other, 
    Device added with DisplayName: Realtek High Definition Audio Desc: Lautsprecher/Kopfhörer (Realtek High Definition Audio)
11748, 18596, 2016-03-21 10:24:03.753, TL_INFO, <no file info>, Other, 
    New media device added to collection. Lautsprecher/Kopfhörer (Realtek High Definition Audio)
11748, 18596, 2016-03-21 10:24:03.753, TL_INFO, <no file info>, Other,  
    Device added with DisplayName: 7- Dell AC511 USB SoundBar Desc: Lautsprecher (7- Dell AC511 USB SoundBar)
11748, 18596, 2016-03-21 10:24:03.784, TL_INFO, <no file info>, Other,  
    Device added with DisplayName: GN 9350 Desc: Kopfhörer (GN 9350) 

Das ist schon mal hilfreich, um Probleme mit Soundkarten o.ä. zu ermitteln. Bei der Suche nach Fehlern bei der Audio-Verbindung habe ich nach ICE gesucht und wurde auch fündig. (Umbrüche zur Lesbarkeit addiert)

11748, 18596, 2016-03-21 10:27:11.004, TL_INFO, <no file info>, Other,  
    Diagnostic data RemoteBwCheckResult 0 ConnectivityDiagnosticMessage ICEWarn="0x80020"; 
    ICEWarnEx="0x1";LocalSite="192.168.178.55:29060";RemoteSite="192.168.100.103:56865"; 
    PortRange="1025:65000";LocalLocation="1";RemoteLocation="0";FederationType="0"; 
    NetworkName="FC2";Interfaces="0x6";IceRole="1";RtpRtcpMux="1";MediaDllVersion="6.0.8808.21"; 
    MrDnsX="NoRelays" MediaDiagnosticMessage NetworkErr="no error";ErrTime="0";RTPSeq="0"; 
    SeqDelta="0";RTPTime="0";RTCPTime="0";TransptRecvErr="0x0";RecvErrTime="0"; 
    TransptSendErr="0x80004005";SendErrTime="3667541217598";InterfacesStall="0x0"; 
    InterfacesConnCheck="0x0";MrDnsX="NoRelays"
11748, 18596, 2016-03-21 10:27:11.005, TL_INFO, <no file info>, Other,  
    Raising 'AVComponent' event 'MEDIA_CHANGED' with args ' 
    <args> 
       <int>1</int>
       <int>5000</int>
       <int>2</int>
       <int>4</int>
       <int>2</int>
       <string>TmV0d29ya0Vycj0ibm8gZXJyb3IiO0VyclRpbWU9IjAiO1JUUFNlcT0iMCI7U2VxRGVsdGE9Ij
               AiO1JUUFRpbWU9IjAiO1JUQ1BUaW1lPSIwIjtUcmFuc3B0UmVjdkVycj0iMHgwIjtSZWN2RXJy
               VGltZT0iMCI7VHJhbnNwdFNlbmRFcnI9IjB4ODAwMDQwMDUiO1NlbmRFcnJUaW1lPSIzNjY3NT
               QxMjE3NTk4IjtJbnRlcmZhY2VzU3RhbGw9IjB4MCI7SW50ZXJmYWNlc0Nvbm5DaGVjaz0iMHgw
               IjtNckRuc1g9Ik5vUmVsYXlzIg==
       </string>
    </args>'
11748, 18596, 2016-03-21 10:27:11.005, TL_INFO, <no file info>, Other,  
    Fire event 'CONNECTIVITY_CHECK_STATUS' with data '
      <args><int>1</int><bool>false</bool>
        <string>SUNFV2Fybj0iMHg4MDAyMCI7SUNFV2FybkV4PSIweDEiO0xvY2FsU2l0ZT0iMTkyLjE2OC4xN
        zguNTU6MjkwNjAiO1JlbW90ZVNpdGU9Ijg0LjIxLjM4Ljc1OjU2ODY1IjtQb3J0UmFuZ2U9IjEwMjU6Nj
        UwMDAiO0xvY2FsTG9jYXRpb249IjEiO1JlbW90ZUxvY2F0aW9uPSIwIjtGZWRlcmF0aW9uVHlwZT0iMCI
        7TmV0d29ya05hbWU9IkZDMiI7SW50ZXJmYWNlcz0iMHg2IjtJY2VSb2xlPSIxIjtSdHBSdGNwTXV4PSIx
        IjtNZWRpYURsbFZlcnNpb249IjYuMC44ODA4LjIxIjtNckRuc1g9Ik5vUmVsYXlzIg==</string>
      </args>'
11748, 18596, 2016-03-21 10:27:11.011, TL_INFO, <no file info>, Other,  
    Processing AVComponent method - Terminate

Hier ist die Meldung "ICEWarn="0x80020" interessant. Anhand der Liste auf CEWarn Liste bedeutet dies, dass es keine direkte Verbindung zustande gekommen ist und kein TURN-Server konfiguriert ist. Das passt natürlich genau auf die oben beschriebenen SDP-Kandidaten.

Der "MEDIA_CHANGED" Event machte mich neugierig und so habe ich den langen String einfach mal durch einen BASE64-Decover geschickt:

NetworkErr="no error";ErrTime="0";RTPSeq="0";SeqDelta="0";RTPTime="0";RTCPTime="0";
TransptRecvErr="0x0";RecvErrTime="0";TransptSendErr="0x80004005";
SendErrTime="3667541217598";InterfacesStall="0x0";InterfacesConnCheck="0x0";
MrDnsX="NoRelays"

Der zweite String decodiert sich ebenfalls:

ICEWarn="0x80020";ICEWarnEx="0x1";LocalSite="192.168.178.55:29060";
RemoteSite="192.168.100.103:56865";PortRange="1025:65000";
LocalLocation="1";RemoteLocation="0";FederationType="0";NetworkName="FC2";Interfaces="0x6";
IceRole="1";RtpRtcpMux="1";MediaDllVersion="6.0.8808.21";MrDnsX="NoRelays"

Hier ist auch noch mal die ICE-Warnung enthalten. Das Decodieren kann man sich aber natürlich sparen, wenn die Meldung auch so schon im Klartext geschrieben ist. Etwas weiter kommt dann auch die UCWA-Meldung mit dem Ende des Versuchs:

10:24:17:204, TL_INFO, , UCWASpecificCommunication, 
    Sending Request for: POST:/ucwa/v1/applications/11283xxxxx/communication/conversations/%guid%
          /audioVideo/terminate?reason=CallEstablishFailureOneInternalOneExternal_27,  
    Lync_Client_Model_Session_UCWACommunicationContext$sendRequest

In dem Beispiel war keine Verbindung zwischen meinem Externen Client und der internen MCU bei dem Meeting möglich

ICE in PluginHost_yyyy-mm-dd_hh_mm_ss.log

Wenn Sie anonym an einem Meeting teilnehmen wollen, dann muss der Edge-Server des Konferenzanbieters ihnen TURN/STUN-Dienste bereitstellen., damit Sie auch hinter einer Firewall oder NAT-Router eine RTP-Verbindung aufbauen können. Auch dieses "Angebot" können Sie im Logfile finden. Suchen Sie mal nach "AddIceServer"

10868, 13724, 2016-03-23 17:39:53.272, TL_NOISE, <no file info>, Other, Method enter
10868, 13724, 2016-03-23 17:39:53.272, TL_INFO, <no file info>, Other, Adding ICE server type 1 name avedge.msxfaq.net port 3478
10868, 13724, 2016-03-23 17:39:53.272, TL_INFO, <no file info>, Other, Processing MediaPlatformConfig method complete - AddIceServer. Result 0.
10868, 13724, 2016-03-23 17:39:53.277, TL_INFO, <no file info>, Other, Processing MediaPlatformConfig method - AddIceServer
10868, 13724, 2016-03-23 17:39:53.277, TL_NOISE, <no file info>, Other, Method enter
10868, 13724, 2016-03-23 17:39:53.277, TL_INFO, <no file info>, Other, Adding ICE server type 2 name avedge.msxfaq.net port 443
10868, 13724, 2016-03-23 17:39:53.277, TL_INFO, <no file info>, Other, Processing MediaPlatformConfig method complete - AddIceServer. Result 0.
10868, 13724, 2016-03-23 17:39:53.280, TL_INFO, <no file info>, Other, Fire event '__FxLoadComplete' with data '<args><int>0</int></args>' complete.

Einige Zeilen später finden sich dann auch die Namen in den ICE-Meldungen

10868, 13724, 2016-03-23 17:39:53.736, TL_INFO, <no file info>, Other, Diagnostic data RemoteBwCheckResult 0 ConnectivityDiagnosticMessage 
   ICEWarn="0x0";ICEWarnEx="0x1";LocalMR="80.66.20.22:3478";PortRange="1025:65000";LocalLocation="1";RemoteLocation="0";FederationType="0";
   Interfaces="0x6";BaseInterface="0x1";IceRole="1";RtpRtcpMux="0";MediaDllVersion="6.0.8808.21";MrDnsU="avedge.netatwork.de";MrResU="0";
   MrDnsCacheReadAttempt="0" MediaDiagnosticMessage NetworkErr="no error";ErrTime="0";RTPSeq="0";SeqDelta="0";RTPTime="0";RTCPTime="0";
   TransptRecvErr="0x0";RecvErrTime="0";TransptSendErr="0x0";SendErrTime="0";InterfacesStall="0x0";InterfacesConnCheck="0x0";
   MrDnsU="avedge.netatwork.de";MrResU="0";MrDnsCacheReadAttempt="0"

Hier ist dann auch die Meldung "ICEWarn=0x0", d.h. kein Fehler mehr.

GatewayActiveX_yyyy-mm-dd_hh_mm_ss.log

In der Datei habe ich bislang noch nie etwas gefunden, was für die Analyse weiterführend war.

Cleanup

Wer nun gedacht hat, dass diese Logfiles nun für immer auf dem PC bleiben und die Festplatte voll schreiben, hat sich getäuscht. Wann genau wer die Dateien löscht, kann ich erst mal nicht sagen. Ich habe aber noch keine älteren Dateien gesehen. Ich könnte mir vorstelle, dass das PlugIn beim nächsten Start selbst aufräumt.

Weitere Links