Lync Keyhole Diagnose

Die glauben gar nicht, was man bei SIP schon aus der Ferne quasi durch das Schlüsselloch über eine Firma erfahren kann. Man muss eigentlich nur eine gültige SIP-Adresse seines Gegenüber haben und das aktivierte Logging auf dem Client. Aber auch innerhalb der eigenen Lync-Umgebung ist das Client Logging sehr viel schneller und einfacher als erst einen Trace auf dem Server zu ziehen. Auf dieser Seite möchte ich exemplarisch ein paar Tricks und Kniffe dazu beschreiben. Gerade wenn jemand Lync neu mit Federation installiert und dann natürlich meine SIP-Adresse ausprobiert, verrät schon viel über seine Umgebung.

Logging aktivieren

Dazu müssen Sie natürlich das Logging auf dem Client erst einmal aktivieren.

Bei Lync 2013 ist das Logging per Default sogar aktiv, so dass im passenden Verzeichnis die Logdateien landen.

  • Skype 2016
    %Userprofile%\Appdata\Local\Microsoft\Office\16.0\Lync\Tracing
  • Lync 2013/Skype 2015 Client
    %Userprofile%\Appdata\Local\Microsoft\Office\15.0\Lync\Tracing
  • Lync2010:
    %Userprofile%\tracing
  • OCS2007R2
    %Userprofile%\tracing

Dort finden sich neben anderen Dateien auch die UCCAPI-Logs:

Auf diese Dateien habe ich es abgesehen. Der Lync Client legt bis zu drei Dateien a 50 Megabyte ab. Auf der Seite Parse-UCCAPI habe ich ein PowerShell-Script, um anhand dieser Dateien z.B. die Größe der SIP-Messages zu ermitteln.

Am besten sortieren die das Verzeichnis nach dem Änderungsdatum. Dann sollte die aktuellste UCCAPILOG -Datei oben stehen.

Achtung: Anscheinend löscht der Client in diesem Verzeichnisse alle Dateien mit der Endung UCCAPILOG nach dem Alter. Ich hatte z.B. mal eine Kopie einer UCCAPI-Log angelegt und einige Tage später meinte mein Texteditor dann, ob er die verschwundene Datei vergessen sollte.

Sie sollten also zumindest UCCAPILOG-Dateien in diesem Ordner nicht als Sicherung" verwenden.

Feintuning zum Logging

In der Regel reichen die Standardeinstellungen. Über die Registrierung können Sie aber durchaus noch weitere Einstellungen anpassen. Im folgenden Zweig finden Sie die Einstellungen

HKEY_CURRENT_User\Software\Microsoft\Tracing\UcClient\Lync

Hier finden sie direkt den Pfad zum Log und auch die Einstellungen zu den Größen der Dateien. 

MaxFileSize beschreibt, dass jedes Log bitte maximal 30 Megabyte groß wird und EnableLogRollOverCheck=1 sorgt dafür, dass dann ein neues Log angelegt wird. Mit dem hier nicht sichtbaren Parameter "MaxFiles = 3" wird bestimmt, dass drei Dateien angelegt werden.

Richard Schwendiman hat auf seinem Blog dies und weitere Daten beschrieben:

Interessant ist in dem Umfeld, dass die Logs fortgeschrieben werden aber nach 30 MB (default) eine neue Logdatei anfängt. Wenn ich es richtig beobachtet habe, dann werden die bestehenden Dateien nicht umbenannt, sondern eine neue Date mit höherer Nummer geschrieben und beim Erreichen der höchsten Datei wieder die erste überschrieben:

Immer wenn der Client komplett neu gestartet wird, werden die vorhanden Dateien nach *.BAK umbenannt und mit der Lync-UccApi-0.UccApilog neu gestartet.

Je nach Aktivität sammeln sich meist 2-10 Stunden in einer 30 Megabyte Datei.

Logging mit Snooper

Der Lync Communicator erstellt natürlich erst mal einfache TEXT-Dateien, die sie mit jedem Texteditor betrachten können. Die Dateien können aber bis zu 50MB groß werden und wenn mehrere SIP-Dialoge nebeneinander aktiv sind, dann ist es schon mühsam die zusammen gehörenden SIP-Pakete zu analysieren. Wenn Sie daher vermuten, das sich der Fehler im SIP-Paket finden lässt, dann ist Snooper das erste Mittel der Wahl, um im Trace nach SIP-Verbindungen zu filtern und diese zu analysieren.

Die folgenden Analysen wurden in einem abgeschotteten Testfeld gemacht und nicht für das Verständnis erforderliche Zeilen wurden zur besseren Lesbarkeit entfernt.

Fehlgeschlagene Audioverbindung

Was tun, wenn der Lync Client ihnen eine nichtssagende Fehlermeldung präsentiert?

Dann hilft nur ein Blick in das ClientLog. Vielleicht baue ich mir später mal eine Tray-App, die bei solchen Fehlern den Detailstatus ausgeben. Hier ein paar Diagnosen zu diesem Fehler

Telefonat mangels Route oder Rechte mit 403 Forbidden

Ein einfacher Test ist die Blockade von so genannten "Premium Nummern" (0900) über eine Voice route Exception. Ein Anrufversuch wird von Lync dann relativ schnell abgelehnt.

09/30/2014|22:51:41.449 E18:E1C INFO  :: SIP/2.0 403 Forbidden
Via: SIP/2.0/TLS 192.168.178.210:49700;ms-received-port=49700;ms-received-cid=114100
From: "User 1"<sip:User1@uclabor.de>;tag=ed0c26975c;epid=c6e8d30aa8
To: <sip:+499002323@uclabor.de;User=phone>;tag=23EFAE57BB6B875AD8984F3F6F8998FE
Call-ID: ec575543eb424d3896978629bc48ee98
CSeq: 1 INVITE
ms-diagnostics: 12004;
   reason="The User is not authorized to call the specified number or none of the routes have a valid gateway configured.";
   source="LYNC.UCLABOR.DE";
   appName="OutboundRouting"
Server: OutboundRouting/5.0.0.0

Der Fehler kann aber auch jede andere Nummerngasse betreffen.

Zwischenmeldung 101

Sollte es einen gültigen Leitweg geben, dann unterbleibt das "403 Forbidden". Interessant ist dann als erstes die Zwischenmeldung "101 Progress Report". Sie verrät schon einiges über die PSTN-Konfiguration in Lync

09/30/2014|23:08:24.370 E18:E1C INFO  :: SIP/2.0 101 Progress Report
Content-Length: 0
Via: SIP/2.0/TLS 192.168.178.210:49933;ms-received-port=49933;ms-received-cid=12ED00
From: "User 1"<sip:User1@uclabor.de>;tag=199d05c08a;epid=c6e8d30aa8
To: <sip:+495251304613@uclabor.de;User=phone>
Call-ID: 6c77c58934f147f0aab1ec7a0e74b4c8
CSeq: 1 INVITE
ms-diagnostics: 12006;
   reason="Trying next hop";
   source="LYNC.UCLABOR.DE";
   PhoneUsage="DE - Welt Standard";
   PhoneRoute="Essen DE";
   Gateway="sbc.uclabor.de";
   appName="OutboundRouting"
Server: OutboundRouting/5.0.0.0

Dieser Ruf wird wohl an das Gateway "sbc.uclabor.de" geleitet. Der Anwender hat zwei PSTN-Usages. Sollte das Gateway "Down" sein und nicht innerhalb von 1 Sekunde mit einem "100 Trying" antworten, dann versucht Lync eine alternative Route und meldet dies ebenfalls

Gateway nicht erreichbar 503 Service unavailable

Wenn das Gateway nicht erreichbar ist, dann meldet Lync dies mit einem "503 Service unavailable"

Auch diese Meldung ist durchaus aufschlussreiche. Man sieht nämlich über welchen Trunk versucht wurde, welches Gateway anzusprechen.

09/30/2014|23:08:24.461 E18:E1C INFO  :: SIP/2.0 503 Service unavailable
Via: SIP/2.0/TLS 192.168.178.210:49933;ms-received-port=49933;ms-received-cid=12ED00
CONTENT-LENGTH: 0
From: "User 1"<sip:User1@uclabor.de>;tag=199d05c08a;epid=c6e8d30aa8
To: <sip:+495251304613@uclabor.de;User=phone>;epid=95BBB2A114;tag=aa21472ae
CSeq: 1 INVITE
Call-ID: 6c77c58934f147f0aab1ec7a0e74b4c8
Server: RTCC/5.0.0.0 MediationServer
ms-endpoint-location-data: NetworkScope;ms-media-location-type=intranet
ms-trunking-peer-state: down
ms-trunking-peer: sbc.uclabor.de;trunk=sbc.uclabor.de
ms-enable-dns-failover: yes
ms-diagnostics: 10001;source="lync.uclabor.de";reason="Gateway did not respond in a timely manner (timeout)";component="MediationServer"
ms-diagnostics-public: 10001;reason="Gateway did not respond in a timely manner (timeout)";component="MediationServer"

In diesem Fall hat das Gateway einfach nicht geantwortet.

Fehler auf der anderen Seite Beispiel 484 Address Incomplete

Anders sieht es aus, wenn das Gateway den INVITE schon zum nächsten System weiter leitet aber dort dann ein Fehler erscheint. Manchmal ist die Beschreibung schon hilfreich. Manchmal aber nicht.

Hier mal am Beispiel eines Rufs an eine Rufnummer über ein ISDN-Gateway mit unvollständiger Nummer.

09/30/2014|23:28:27.295 19D4:1208 INFO  :: SIP/2.0 484 Address Incomplete
ms-User-logon-data: RemoteUser
Via: SIP/2.0/TLS 192.168.178.60:62342;received=79.208.116.243;ms-received-port=62342;ms-received-cid=FDF200
From: "User1"<sip:User1@uclabor.de>;tag=5879295fa3;epid=2385f4c267
To: <sip:+49524670097@uclabor.de;User=phone>;tag=8c3d7c52d;epid=F7C00E80D3
CSeq: 1 INVITE
Call-ID: 48baf0ceef774e3890f600faf2810e93
P-Asserted-Identity: <sip:+49524670097@uclabor.de;User=phone>
Server: RTCC/5.0.0.0 MediationServer
ms-diagnostics: 10484;
   source="LYNC.uclabor.de";
   reason="Gateway responded with 484 Address Incomplete";
   component="MediationServer";
   SipResponseCode="484";
   SipResponseText="Address Incomplete";
   sip-reason="Q.850 ;cause=28";
   GatewayFqdn="isdn.uclabor.de;trunk=isdn.uclabor.de"
ms-diagnostics-public: 10484;
   reason="Gateway responded with 484 Address Incomplete";
   component="MediationServer";
   SipResponseCode="484";SipResponseText="Address Incomplete";sip-reason="Q.850 ;cause=28"
Reason: Q.850 ;cause=28
ms-trunking-peer: isdn.uclabor.de;isdn.uclabor.de;User-Agent="Audiocodes-Sip-Gateway-Mediant 1000/v.6.40A.042.004"
ms-endpoint-location-data: NetworkScope;ms-media-location-type=intranet

Das Gateway liefert nicht nur den übersetzten SIP-Fehler, sondern auch die ISDN-Meldung (Q.850 Cause 28). 

Keine Audio über Federation

Besonders interessant sind erste "Testanrufe" von Personen, die gerade ihren Edge Server einrichten und noch gar nicht genau wissen, ob alles funktioniert. Und was liegt da näher als einfach mal meine SIP-Adresse einzugeben. Aber Achtung: ich sehe natürlich auch, wer meine Präsenz abfragt. Meist kommt der Call natürlich erst mal nicht zustande. Dann reicht schon ein kleiner Blick in die ICE-Candidates, um zu sehen, ob die andere Seite ihre Edge-Installation korrekt vorgenommen hat. Auf der Seite ICE und Kandidaten habe ich ziemlich ausführlich die Aushandlung beschrieben und werde hier daher nicht auf die einzelnen Zeilen eingehen. Eine recht umfangreiche Kandidatenliste kann wie folgt aussehen. (Mit kommentaren)

Das sind die direkten IP-Adressen meines Hosts. Unschwer zu erkennen, dass ich 4x IPv4-Adressen und eine IPv6-Adresse habe.
Das ist der Preis von LAN, WiFi, Bluetooth und VMWare und VirtualBox
a=candidate:1 1 UDP 2130706431 192.168.56.1 18312 typ host
a=candidate:1 2 UDP 2130705918 192.168.56.1 18313 typ host
a=candidate:2 1 UDP 2130705919 192.168.182.1 31142 typ host
a=candidate:2 2 UDP 2130705406 192.168.182.1 31143 typ host
a=candidate:3 1 UDP 2130705407 192.168.23.1 28788 typ host
a=candidate:3 2 UDP 2130704894 192.168.23.1 28789 typ host
a=candidate:4 1 UDP 2130704895 192.168.178.60 6918 typ host
a=candidate:4 2 UDP 2130704382 192.168.178.60 6919 typ host
a=x-candidate-ipv6:5 1 UDP 33552383 2001:0:5ef5:79fd:18a9:1155:b02f:8b0c 4514 typ host
a=x-candidate-ipv6:5 2 UDP 33551870 2001:0:5ef5:79fd:18a9:1155:b02f:8b0c 4515 typ host

Das hier sind dann TURN Adressen von meinem Edge Server (80.66.20.21). Mein Client kann also TURN machen
Sie verweisen auf die NAT-IP-Adresse (79.208.116.243) des DSL-Routers bei mir zuhause
a=candidate:6 1 TCP-PASS 174454271 80.66.20.21 50564 typ relay raddr 79.208.116.243 rport 25471
a=candidate:6 2 TCP-PASS 174453758 80.66.20.21 50564 typ relay raddr 79.208.116.243 rport 25471
a=candidate:7 1 UDP 184546303 80.66.20.21 58962 typ relay raddr 79.208.116.243 rport 33394
a=candidate:7 2 UDP 184545790 80.66.20.21 51071 typ relay raddr 79.208.116.243 rport 33395 und hier die STUN Adressen. Mein Client konnte also per NAT durch den DSL-Router Ports öffnen
a=candidate:8 1 UDP 1694233087 79.208.116.243 33394 typ srflx raddr 192.168.178.60 rport 33394
a=candidate:8 2 UDP 1694232574 79.208.116.243 33395 typ srflx raddr 192.168.178.60 rport 33395

Hier noch mal ein TURN Nachzügler über TCP
a=candidate:9 1 TCP-ACT 174845951 80.66.20.21 50564 typ relay raddr 79.208.116.243 rport 25471
a=candidate:9 2 TCP-ACT 174845438 80.66.20.21 50564 typ relay raddr 79.208.116.243 rport 25471 und noch ein NAT-Kandidat
a=candidate:10 1 TCP-ACT 1684794879 79.208.116.243 25471 typ srflx raddr 192.168.178.60 rport 25471
a=candidate:10 2 TCP-ACT 1684794366 79.208.116.243 25471 typ srflx raddr 192.168.178.60 rport 25471

Wenn Sie genau hinschauen, dann sehen Sie also dass "RELAY" für TURN steht und SRLFX für NAT. Und mit all diesen Adressen kann man gut sehen, was die Gegenseite über ihre Umgebung preis gibt. Prüfpunkte sind u.a.

  • Gibt es RELAY-Einträge
    Nur dann hat der Client einen TURN-Server gefunden und hat von ihm "Candidates" bekommen. Das ist wichtig wenn der Client intern ist, also die HOSTS Einträge eine private Adressen darstellen
  • SRFLX-Einträge
    Entweder sind beide Adressen gleich, dann geht NAT nicht oder der linke Teil ist eine öffentliche Adresse. Wenn dem nicht so ist, könnte "doppeltes NAT" ein Problem sein.
  • NAT im internen LAN
    Wenn der Client über einen TURN-Server Kandidaten bekommt, und intern ist, dann sollte die interne IP mit der Host-IP übereinstimmen. Das interne Bein des Edge-Servers ist wir ein interner Client zu betrachten. NAT ist nicht nicht erlaubt.

Record Route Einträge

Auch diese Felder sind interessant, da sie ähnlich wie beim SMTP-Header nicht nur den Weg durch die verschiedenen Zwischenstationen anzeigt, sondern auch den Rückweg enthält. Bei SIP laufen die Antwortpakete nämlich immer genau den gleichen Weg wieder zurück. Und so ist ganz gut zu erkennen, wie z.B. die internen Server heißen. Wer also z.B. einen Kontakt bei Microsoft hat, kann in der Antwort auf den SUBSCRIBE den Weg sehen

09/30/2014|21:44:51.421 19D4:1208 INFO  :: SIP/2.0 200 OK
ms-User-logon-data: RemoteUser
Contact: <sip:000DDB3L50PL2.europe.corp.microsoft.com:5061;transport=tls;ms-fe=000DDB3L50FE2A.europe.corp.microsoft.com>
CSeq: 1 SUBSCRIBE
Record-Route: <sip:000dtk5l50pl1.redmond.corp.microsoft.com:5061;transport=tls;ms-fe=000DTK5L50FE1K.redmond.corp.microsoft.com;lr>
Record-Route: <sip:sipfed.microsoft.com:5061;transport=tls;lr;ms-key-info=xxxx>
Record-Route: <sip:nawlyncedge.netatwork.de:5061;transport=tls;lr>
Record-Route: <sip:LYNC.netatwork.de:5061;transport=tls;opaque=state:F;lr;received=192.168.1.100;ms-received-cid=DAB001>
Record-Route: <sip:sip.netatwork.de:443;transport=tls;opaque=state:Ci.Rfdf200;lr;ms-route-sig=xxxx>

Lesen Sie die Einträge von unten, dann werden Sie erkennen, dass ich zum Mitschnitt dieses Trace im Homeoffice war und mich mit sip.netatwork.de:443 verbunden hatte, der meine Pakete dann zum LYNC.netatwork.de an dessen IP-Adresse 192.168.1.100 gesendet hat. Von dort ging es dann direkt über den gleichen Edge wieder raus Richtung Microsoft auf sipfed.microsoft.com, der das Paket nach intern auf einen Server in Redmond geschickt hat. Der muss die Pakete dann wieder nach Europe senden. So kann ein SIP-Pakete zwischen Paderborn und München einmal über den großen Teich fliegen.

CAC schlägt zu

Wenn Lync intern mit aktivierter Bandbreitenkontrolle genutzt wird, dann kann ein Anruf auch mit einem Fehler beendet werden.

Auch diese Meldung kann im Client Log genau wieder gefunden werden. Auf einen INVITE antwortet die Gegenseite mit einem 183 Session Progress. Bei dem Beispiel hier ist Audio weiterhin erlaubt, aber Video wurde unterbunden.

09/30/2014|22:39:54.735 E18:E1C INFO  :: SIP/2.0 183 Session Progress
Via: SIP/2.0/TLS 192.168.178.210:49700;ms-received-port=49700;ms-received-cid=114100
From: "User 1"<sip:User1@uclabor.de>;tag=4bf7406e14;epid=c6e8d30aa8
To: <sip:User2@uclabor.de>;epid=8a02720fad;tag=bb9dd8c06d
Call-ID: fdf6aaf097f44e3ebad1d2f146719504
CSeq: 1 INVITE
Contact: <sip:User2@uclabor.de;opaque=User:epid:X-RlkT71bliq-wRUsMyYqQAA;gruu>
ms-endpoint-location-data: NetworkScope;ms-media-location-type=Intranet
Content-Type: application/sdp

v=0
o=- 0 0 IN IP4 10.20.2.122
s=session
c=IN IP4 10.20.2.122
b=CT:99980
t=0 0
a=x-mediabw:main-video send=4000;recv=4000
a=x-devicecaps:audio:send,recv;video:send,recv
m=audio 17416 RTP/SAVP 0 8 101
a=x-ssrc-range:1954868217-1954868217
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:/+ra
a=ice-pwd:Dmyju2ZZBzn/DaGL6ZMwOMko
a=candidate:1 1 UDP 2130706431 10.20.2.122 17416 typ host 
a=candidate:1 2 UDP 2130705918 10.20.2.122 17417 typ host 
a=candidate:4 1 TCP-ACT 1684798463 10.20.2.122 17416 typ srflx raddr 10.20.2.122 rport 17416 
a=candidate:4 2 TCP-ACT 1684797950 10.20.2.122 17416 typ srflx raddr 10.20.2.122 rport 17416 
a=maxptime:200
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
m=video 0 RTP/SAVP 34
a=x-ms-sdp-diagnostics:53000;reason="Insufficient Bandwidth Available"

Das kann man daran erkennen, das unter "m=audio" noch ganz viele gültige Kandidaten angeboten werden aber am Ende bei "m=video" nichts mehr kommt.

Exchange VoiceMail

Mit Exchange im Boot ist es natürlich auch interessant, hier die Fehler zu finden. In Exchange 2013 muss man ja zweimal den Dialplan an den Server koppeln und das wird gerne vergessen. Aber auch hier ist das Logging auf dem Client oftmals der schnellste Weg so eine Fehlkonfiguration zu entdecken und dann zu beheben. Hier ist erst mal der Exchange UM Server "offline"

Zuerst sieht noch alles Gut aus. Der INVITE wird von einem "100 Trying" und einem "183 Session Progress" und einem "101 Progress Report" gefolgt. Neu ist dann aber ein "101 Diagnostics"

10/01/2014|00:12:20.331 E18:E1C INFO  :: SIP/2.0 101 Diagnostics
Via: SIP/2.0/TLS 192.168.178.210:49933;ms-received-port=49933;ms-received-cid=12ED00
From: "User 1"<sip:User1@uclabor.de>;tag=1d5fe3ade3;epid=c6e8d30aa8
To: <sip:+49201801201@uclabor.de;User=phone>
Call-ID: 2a6ed2fe932e4d1fa45987afdd95759e
CSeq: 1 INVITE
ms-diagnostics: 15008;
   reason="Routing to UM für Subscriber Access";
   source="LYNC.UCLABOR.DE";
   dialplan="Essen_Dialplan.uclabor.de"; umserver="exchange.uclabor.de";
   appName="ExumRouting"
Server: ExumRouting/5.0.0.0
Content-Length: 0

Da hier der Server aber "Down" ist, dauert es nicht lange und der erste Hinweis kommt:

10/01/2014|00:12:30.366 E18:E1C INFO  :: SIP/2.0 101 Diagnostics
Via: SIP/2.0/TLS 192.168.178.210:49933;ms-received-port=49933;ms-received-cid=12ED00
From: "User 1"<sip:User1@uclabor.de>;tag=1d5fe3ade3;epid=c6e8d30aa8
To: <sip:+49201801201@uclabor.de;User=phone>
Call-ID: 2a6ed2fe932e4d1fa45987afdd95759e
CSeq: 1 INVITE
ms-diagnostics: 15007;
   reason="Exchange Unified Messaging server did not respond to request";
   source="LYNC.UCLABOR.DE";dialplan="Essen_Dialplan.uclabor.de"; umserver="exchange.uclabor.de";
   nexttarget="exchange.uclabor.de";
   routingtype="Routing to UM für Subscriber Access";
   appName="ExumRouting"
Server: ExumRouting/5.0.0.0
Content-Length: 0

Dann kommt noch ein 101 mit "Failed to Connect to peer" der dann mit einem "480 Temporarily unavailable" abgeschlossen wird

10/01/2014|00:12:41.362 E18:E1C INFO  :: SIP/2.0 480 Temporarily unavailable
Via: SIP/2.0/TLS 192.168.178.210:49933;ms-received-port=49933;ms-received-cid=12ED00
From: "User 1"<sip:User1@uclabor.de>;tag=1d5fe3ade3;epid=c6e8d30aa8
To: <sip:+49201801201@uclabor.de;User=phone>;tag=23EFAE57BB6B875AD8984F3F6F8998FE
Call-ID: 2a6ed2fe932e4d1fa45987afdd95759e
CSeq: 1 INVITE
ms-diagnostics: 15030;
   reason="Failed to route to Exchange Server";
   source="LYNC.UCLABOR.DE";
   dialplan="Essen_Dialplan.uclabor.de";
   appName="ExumRouting"
Server: ExumRouting/5.0.0.0
Content-Length: 0

Sollte aber, wie anfange erwähnt, die Konfiguration des Dialplans nicht stimmen, dann findet sich auch das in den Client-Traces.

EDGE Information und Verbindung

Bei der Anmeldung bekommt der Client als Antwort auf einen SERVICE-Request eine XML-Antwort mit den Edge-Servern

03/29/2016|08:24:25.252 B6128:B0C14 INFO  :: SIP/2.0 200 OK
ms-User-logon-data: RemoteUser
Via: SIP/2.0/TLS 10.1.24.165:53289;received=192.168.102.254;ms-received-port=38507;ms-received-cid=xxx
FROM: "Carius, Frank"<sip:frank.carius@msxfaq.de>;tag=xxx;epid=xxx
TO: <sip:sipedgeAM30E.infra.lync.com@online.lync.com;gruu;opaque=srvr:MRAS:xxxxxxx>;tag=c11a6dce2
CSEQ: 1 SERVICE
CALL-ID: xxxxxxxxxxxxxxx
CONTENT-LENGTH: 1220
CONTENT-TYPE: application/msrtc-media-relay-auth+xml
SERVER: RTCC/7.0.0.0 MRAS/3.0

<?xml version="1.0"?>
<response xmlns:xsd="http://www.w3.org/2001/XMLSchema" 
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" 
    requestID="354136568" version="3.0" serverVersion="3.0" 
    to="sip:sipedgeAM30E.infra.lync.com@online.lync.com;gruu;opaque=srvr:MRAS:xxxx" from="sip:frank.carius@msxfaq.de" 
    reasonPhrase="OK" xmlns="http://schemas.microsoft.com/2006/09/sip/mrasp">
  <credentialsResponse credentialsRequestID="354136568">
    <credentials>
      <Username>xxxxxx==</Username>
      <password>xxxxxxx=</password>
      <duration>480</duration>
    </credentials>
    <mediaRelayList>
      <mediaRelay>
        <location>internet</location>
        <hostName>mediaedge0E.online.lync.com</hostName>
        <udpPort>3478</udpPort>
        <tcpPort>443</tcpPort>
      </mediaRelay>
      <mediaRelay>
        <location>intranet</location>
        <hostName>sipedgeAM30E.infra.lync.com</hostName>
        <udpPort>3478</udpPort>
        <tcpPort>443</tcpPort>
      </mediaRelay>
    </mediaRelayList>
  </credentialsResponse>
</response>

Etwas später sollten Sie im UCCAPILOG dann auch sehen, dass der Client die Edge-Server zu seiner Konfiguration addiert:

02/23/2016|07:24:25.301 1234:1234 INFO  :: ~Out trxn corr-id (15408560)
02/23/2016|07:24:25.313 1234:1234 TRACE :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Adding ice server mediaedge0E.online.lync.com
02/23/2016|07:24:25.313 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - TCP server mediaedge0E.online.lync.com
02/23/2016|07:24:25.313 1234:1234 INFO  :: Function: CUccCredentialCache::GetCredential
02/23/2016|07:24:25.313 1234:1234 TRACE :: Condition failed with 80ee0058: 'iEntry != (-1)'
02/23/2016|07:24:25.313 1234:1234 INFO  :: Credentials- Username: AwAAOLv06RwB0nJfqACuGEUoIrGxuqrrHKiW/Tkjfk0AAAAABkQlJRtPfbcwS6Un0KSmQP4z+5TIsMgeYfnw45p+obY0GCE2zB1cJQ==, Domain: *
02/23/2016|07:24:25.313 1234:1234 TRACE :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Adding ice server mediaedge0E.online.lync.com
02/23/2016|07:24:25.313 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - UDP server mediaedge0E.online.lync.com
02/23/2016|07:24:25.313 1234:1234 INFO  :: Function: CUccCredentialCache::GetCredential
02/23/2016|07:24:25.313 1234:1234 TRACE :: Condition failed with 80ee0058: 'iEntry != (-1)'
02/23/2016|07:24:25.313 1234:1234 INFO  :: Credentials- Username: AwAAOLv06RwB0nJfqACuGEUoIrGxuqrrHKiW/Tkjfk0AAAAABkQlJRtPfbcwS6Un0KSmQP4z+5TIsMgeYfnw45p+obY0GCE2zB1cJQ==, Domain: *
02/23/2016|07:24:25.314 1234:1234 TRACE :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Adding ice server sipedgeAM30E.infra.lync.com
02/23/2016|07:24:25.314 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - TCP server sipedgeAM30E.infra.lync.com
02/23/2016|07:24:25.314 1234:1234 INFO  :: Function: CUccCredentialCache::GetCredential
02/23/2016|07:24:25.314 1234:1234 TRACE :: Condition failed with 80ee0058: 'iEntry != (-1)'
02/23/2016|07:24:25.314 1234:1234 INFO  :: Credentials- Username: AwAAOLv06RwB0nJfqACuGEUoIrGxuqrrHKiW/Tkjfk0AAAAABkQlJRtPfbcwS6Un0KSmQP4z+5TIsMgeYfnw45p+obY0GCE2zB1cJQ==, Domain: *
02/23/2016|07:24:25.314 1234:1234 TRACE :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Adding ice server sipedgeAM30E.infra.lync.com
02/23/2016|07:24:25.314 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - UDP server sipedgeAM30E.infra.lync.com
02/23/2016|07:24:25.314 1234:1234 INFO  :: Function: CUccCredentialCache::GetCredential
02/23/2016|07:24:25.314 1234:1234 TRACE :: Condition failed with 80ee0058: 'iEntry != (-1)'
02/23/2016|07:24:25.314 1234:1234 INFO  :: Credentials- Username: AwAAOLv06RwB0nJfqACuGEUoIrGxuqrrHKiW/Tkjfk0AAAAABkQlJRtPfbcwS6Un0KSmQP4z+5TIsMgeYfnw45p+obY0GCE2zB1cJQ==, Domain: *
02/23/2016|07:24:25.314 1234:1234 TRACE :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Adding ice server 10.0.0.62
02/23/2016|07:24:25.314 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - HTTP Proxy server 10.0.0.62
02/23/2016|07:24:25.314 1234:1234 INFO  :: no credentials for this config (might be HTTP proxy)
02/23/2016|07:24:25.314 1234:1234 INFO  :: CUccEndpoint::AddMediaConnectivityServerWithCredential MR-INFO - Credentials were not found in server config. Proceeding to add server without credentials.

Leider habe ich noch nichts gefunden, ob im den Log auch Fehler beim EDGE-Verbindungsaufbau stehen. Bislang orientiere ich mich hierbei dann an den SDP-Kandidaten und der Schlussmeldung mit dem ICEWARN-Wert über die ICEWarn Liste.

Hybrid

Vielleicht haben Sie schon mal einen Lync Server mit Office365 im Hybrid-Mode installiert. In einem Kundenszenario konnte ein On-Premises-User nicht die Präsenz eines Cloud Users einsehen. Ohne Zugang zu den Servern hat man mir das ClientLog des On-Prem-Anwender gesendet und da war sehr schnell ersichtlich, dass die Federation als solches funktioniert. Hier der ausgehende Subscribe:

09/30/2014|15:59:12.172 C58:182C INFO  :: SUBSCRIBE sip:User2@msxfaq.de SIP/2.0
Via: SIP/2.0/TLS 192.168.178.166:54897
Max-Forwards: 70
From: <sip:User2@msxfaq.de>;tag=ccb9b94ee2;epid=ae67c0e69e
To: <sip:User1@msxfaq.de>
Call-ID: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
CSeq: 1 SUBSCRIBE
Contact: <sip:User2@msxfaq.de;opaque=User:epid:xxx;gruu> User-Agent: UCCAPI/15.0.4649.1000 OC/15.0.4649.1000 (Microsoft Lync)
Event: presence
Accept: application/msrtc-event-categories+xml, application/xpidf+xml,
     text/xml+msrtc.pidf, application/pidf+xml, application/rlmi+xml, multipart/related
Supported: com.microsoft.autoextend
Supported: ms-benotify
Proxy-Require: ms-benotify
Supported: ms-piggyback-first-notify
Content-Type: application/msrtc-adrl-categorylist+xml
Content-Length: 462

Und wenn man anhand der Call-ID dann die Folgepakete sucht, findet sich recht schnell die Antworten:

09/30/2014|15:59:12.193 C58:182C INFO  :: SIP/2.0 200 OK
Contact: <sip:sippoolams0e09.infra.lync.com:5061;transport=tls;ms-fe=AMS0E09FES08.infra.lync.com>
Content-Length: 467
From: "User2"<sip:User2@msxfaq.de>;tag=ccb9b94ee2;epid=ae67c0e69e
To: <sip:User1@msxfaq.de>;tag=4B040080
Call-ID: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
CSeq: 1 SUBSCRIBE
Via: SIP/2.0/TLS 192.168.178.166:54897;ms-received-port=54897;ms-received-cid=745800
Record-Route: <sip:sipfed0E.online.lync.com:5061;transport=tls;lr;ms-key-info=xxx-xxxx;ms-route-sig=xxx>
Record-Route: <sip:lyncedge.msxfaq.de:5061;transport=tls;opaque=state:Si;lr>
Content-Type: multipart/related; type="application/rlmi+xml";start=resourceList; boundary=aaa
Event: presence
ms-split-domain-info: ms-traffic-type=SplitIntra;ms-remote-fqdn=sipfed.online.lync.com
Record-Route: <sip:lyncpoolsip1.msxfaq.de:5061;transport=tls;ms-fe=vm-lync-fep11.msxfaq.de>

--aaa
Content-Transfer-Encoding: binary
Content-ID: resourceList
Content-Type: application/rlmi+xml

<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:User2@msxfaq.de" version="0" fullState="false">
<resource uri="sip:User1@msxfaq.de">
<instance id="0" state="terminated" reason="forbidden" statusCode="403" cid="User1@msxfaq.de" msDiagCode="2157"/>
</resource>
</list>

--aaa--

Hier ist interessant, dass in der "Record-Route" die Office 365 Edge-Servers erscheinen und auch die "ms-split-domain-info" gefüllt ist. Das Paket ist also zumindest schon mal von der On-Prem-Umgebung zu Office 365 und wieder zurück gekommen. Probleme beim DNS, Edge, Zertifikate, Firewall, IP-Routing als auch DirSync etc. sind quasi ausgeschlossen. Aber am Ende kommt der "403 forbidden". Anscheinend hat der Anwender in der Cloud den Kontakt "verboten" oder in der Cloud ist generell der "Privacy-Mode" aktiv.

Sinnvolle Suchbegriffe

In einer Textdatei den Fehler schnell zu finden, funktioniert fast nur über die richtigen Suchbegriffe. Wenn man aber nicht genau den Fehler kennt, dann kann man nicht nach dem Fehler suchen, sondern muss die Präfixe können, hintern denen die ausführlichen Meldungen zu finden sind. Natürlich ist es hilfreich, wenn man die SIP-Adresse oder Rufnummer de fehlerhaften Dialogs hat oder zumindest die Zeit. Hier eine Auswahl von Suchfeldern:

  • ms-diagnostics:
    Aus meiner Sicht der erste Suchbegriff um Fehler in SIP-Meldungen zu finden. Fast immer gibt es neben dem generischen SIP-Fehler
  • msDiagCode
    Diese Meldung findet sich in er XML-Payload einer SIP-Meldung, z.B.: bei der Abfrage einer Präsenz.
  • "Candidate"
    Der String "Candidate" kommt fast immer nur in SIP-INVITE,  und SIP 183 Session Progress oder 200 OK vor. Es ist ein klarer Indikator für eine RTP-Verbindung und erlaubt eine schnelle Diagnose, ob die Kandidaten alle korrekt sind.
  • Call-ID
    Die Call ID ist eine eindeutige Kennzeichnung eines SIP-Dialogs und bleibt die ganze Zeit unverändert. Wenn Sie also mehrere SIP-Meldungen in einen logischen Zusammenhang bringen wollen, dann finden Sie eine Meldung dieses Dialogs und filtern dann auf die Call-ID:

Ich hoffe ich habe die ein oder andere interessante Strategie für die Fehlersuche aufgezeigt.

Weitere Links