Direct Routing, REFER und TLS

Ein Support Case mit fehlgeschlagenen Anrufen über einen Auto Attendant in eine Call Queue was der Auslöser diese Seite zu schreiben.

Regelfall

Die Konstellation ist eigentlich nicht unüblich. Eine Call Queue wird gerne für die Verteilung von Anrufen genutzt und kann sogar eine externe Rufnummer haben aber es fehlt an der "Ansage" oder einem Auswahlmenü. Daher kombinieren Firmen gerne einen "AutoAttendant", der davor geschaltet wird. Der Anrufer landet also zuerst auf dem AutoAttendant, der eine Ansage oder auch ein Auswahlmenü anbieten kann, ehe er den Anruf dann in die entsprechende CallQueue weiterleitet. In meinem Fall prüft der AutoAttendant sogar nur die "Öffnungszeiten", um einen Anrufer entweder in eine CallQueue oder zu einer Ansatz zu leiten.

Bei dieser Weiterleitung nutzt Teams, wie viele andere VoIP-Lösungen auch ein REFER. Der Anruf wird also nicht vom AutoAttendant zum nächsten Ziel weiter gegeben, sondern der Auto Attendant informiert den Anrufer, bzw. hier den lokalen SBC über das neue Ziel und der Anrufer baut eine neue Verbindung auf. Siehe dazu auch die Seite SIP und Weiterleitungen. Ein Verbindungsaufbau per SIP sieht dann wie folgt aus:

Ich werde hier nicht auf jeden einzelnes SIP-Paket eingehen aber ein paar Stichpunkte und Hinweise geben:

  • Blauer Call des Carrier zum SBC
    Das ist der normale eingehende Anruf vom Carrier zum SBC des Kunden. Er wird am Anfang aufgebaut und ganz am Ende legt der Anrufer auf. Dazwischen kommt ein Crypto Update, wozu der Client sich aber neu authentifizieren muss (401). Das ist nicht weiter relevant.
  • Orange Call zu Teams
    Auch hier ist zu sehen, das der SBC eine Verbindung zum sip.pstnhub.microsoft.com macht und die Verbindung hergestellt wird. Die SIP-Verbindung geht hier zu 52.114.75.24 und bleibt auch bei der IP-Adresse. Die RTP-Verbindung nutzt 52.113.136.29
  • Orange Call REFER
    Dann kommt von Teams der REFER, der drei Pakete später einen neuen Call (grün) des SBC auslöst. Interessanter ist im REFER-Paket aber, dass die SourceIP zwar weiterhin die 52.114.75.24 ist aber der UserAgent von EUWE.0 auf EUWE.10 wechselt. Wenn ich diese Nummern als "SBC-Kennzeichnung" nutze, dann ist dies ein anderer SBC hinter der gleichen Nummer, der aber einen eigenen TLS-Handshake aufbaut. Da kommen wir später noch drauf
  • Grüner Call vom SBC zu Teams
    Auf Basis des REFER baut der SBC einen zweiten Call zu Teams auf. Auf den ersten grünen "INVITE" meldet sich diesmal wieder EUWO.0. Meine Affinität des SBC bleibt gewahrt, obwohl der REFER von einem anderen System gekommen ist.
  • RTP Call2 established
    Nach etwas hin und her hat der SBC die zweite Verbindung zu eine anderen RTP Endpunkt (52.113.52.173) aufgebaut. In der Zwischenzeit wird Call1 durch EUWE.10 abgebaut

Wir wissen, dass sip.pstnhub.microsoft.com auf wenige IP-Adressen auflöst und sich dahinter vermutlich mehrere Server verbergen. Ich interpretiere die Daten so, dass der REFER nicht mehr von dem gleichen SBC ausgeführt wird, über die die bisherige SIP-Verbindung gesteuert wurde. Hier hat Microsoft intern vermutlich seine Gründe, warum die Session zu einem anderen physikalischen SBC verlagert wird, der nach extern aber die gleiche öffentliche IP-Adresse hat. Die komplette SIP-Kommunikation geht in diesem Fall immer über die 52.114.75.24.

REFER FAIL

Natürlich habe ich noch einen Trace, der eine Fehlersituation zeigt. Der Anruf kommt beim AutoAttendant an aber wird dann nicht erfolgreich weiter vermittelt.

Das Bild unterscheidet sich fundamental von dem funktionierenden Modell. Es fehlt komplett der REFER und daher hat der SBC auch keinen Grund den Anruf zur Call Queue umzubauen. Stattdessen bleibt der erste Anruf zum AutoAttendant bestehen. Der Anrufer hört dann die Ansage, dass der Anruf nicht durchgestellt werden kann und legt dann auf. Er hat aber sein Ziel nicht erreicht und für eine Firma ist es ein verpasster Kunde.

Wo ist der REFER?

Der SBC kann in seinem Trace natürlich nur die Meldungen anzeigen, die er auch empfangen hat. Die Frage bleibt also, ob Microsoft Teams den REFER senden wollte und er nicht zugestellt werden konnte oder ob ein Konfigurationsfehler auf der anderen Seite generell den REFER verhindert. Klar ist die Aussage, dass REFER vom eigenen SBC unterstützt werden muss:

When the Microsoft SIP proxy sends an SIP Refer message to SBC, an SIP Invite message should be returned to the SIP proxy, not to PSTN or to any other destination.
Quelle: Issues that affect call transfers https://docs.microsoft.com/en-us/microsoftteams/troubleshoot/phone-system/direct-routing/issues-with-call-transfers

Auf der Seite wird ein eigener Abschnitt dem fehlenden REFER gewidmet: Hier steht dann auch:

SIP Refer can come from any of the IP addresses by using new TLS connection, even if the previous part of the call came from another IP address.

In meinem Beispiel war die Source-IP-Adresse unverändert aber es kann dennoch eine neue TLS-Verbindung sein. Wir müssen also ein Stück "tiefer" gehen und auf dem Netzwerklevel prüfen, ob der Microsoft SIP Proxy eine eingehende Verbindung zur Übermittlung des REFER startet und diese nicht erfolgt. Mehrere Quellen kommen dafür in Betracht:

  • Microsoft Support
    Wenn der eingehende REFER nicht gelingt, dann sollte Microsoft auf ihrer Seite natürlich ein "Logging" generieren. Leider gibt es noch keinen Weg, wie ich als Admin eines SBC von einem Tenant die dazugehörigen Logs erhalten kann. Das Exchange Team ist hier schon weiter, da das Messagetracking schon alleine entsprechende Informationen eines "Hybrid Connectors" liefert. Mit Teams Direct Routing können Sie aber ein Support Ticket aufmachen und hoffen, dass nach einigen Tagen oder Wochen der richtige Supporter die richtigen Hinweise findet
  • Firewall-Logs
    Wenn der REFER über eine eigene TCP-Connection mit TLS-Handshake übertragen wird, sollte man zu dem Zeitpunkt ja eine neue eingehende Verbindung oder zumindest ein Verbindungsversuch sehen. Das müsste eine Firewall protokollieren.
  • WireShark
    Auch ein Mitschnitt der Verbindungen zur SBC-IP-Adresse kann die eingehende Verbindung für den REFER anzeigen. Auch wenn es bei TLS-Verbindungen nur umständlich möglich ist, in die Nutzdaten zu schauen, so sollte allein über den Zeitpunkt der TCP-Handshake und TLS-Handshake erkennbar sein. Ein ClientHello und Server Antwort sind eigentlich immer sichtbar und geben einen Hinweis auf Inkompatibilitäten
  • Logging des SBC
    Wenn der REFER irgendwie über eine bestehende Verbindung kommt dann muss er in einem SIP-Trace des SBC auffindbar sein. Vielleicht ist nur ein Filter zu eng gefasst, weil Sie bislang nicht damit gerechnet haben, dass der REFER über eine neue Verbindung mit eigener CallID ankommt.
    Vielleicht können Sie im Trace aber auch "einseitige" TCP-Connections erkennen, die dann wieder abgebrochen werden, weil der Gegenseite ihr TLS Zertifikat nicht gefällt.
  • NetFlow/SFlow/IPFix/IDS
    Wenn ihr Netzwerk entsprechend ausgestattet ist, können sie auch über diese Protokolle entsprechende Verbindungen erfassen und sehen, welche Paarungen aus Quell-IP:Port und Ziel-IP:Port zu welcher Zeit wie viele Pakete und Bytes übertragen. Eine SIP-Verbindung überträgt durchaus einige "Kilobyte" an Daten, wenn es nicht nur ein OPTIONS-Healthcheck ist. Allzu kurze Verbindungen können ein Hinweisauf Probleme oder auch Angriffe oder Probing sein. Vielleicht können Sie über diesen Weg solche "Unregelmäßigkeiten" aufspüren

Weitere Quellen kann ich so erst einmal nicht erkennen.

Und was war es jetzt?

Ich habe sie nun lange genug auf die Folter gespannt. Es war tatsächlich "etwas mit TLS". Anhand des funktionierenden Traces sehen Sie ja, dass der REFER von einem anderen SIP-Proxy bei Microsoft kommt. Es ist in meinem Fall zwar die gleichen Source-IP gewesen aber den noch eine neue TLS-Verbindung, die Microsoft dazu eingehend auf meinen SBC aufgebaut hat. Im Fehlerfall die die Lücke zwischen dem ACK und vor dem INVITE interessant:

Und ich musste auch gar nicht lange suchen, denn ich sehe im Audiocodes Log die eingehende TLS-Verbindung von Microsoft, die aber sofort wieder abgebrochen wird. In Zeile 08 sehen Sie den Neueintrag in die interne Whitelist-Datenbank um dann aber in Zeile 15 und ca. 17ms später schon wieder das Ende zu vermelden.

01 09:55:05.313  SIPListeningSocketTLS(#0) Socket debug message: CTcpSocket::HandleSocketEvent socket connectedSocketName: SIPLISTENING#0, FileDesc: 57  [Time:04-01@09:55:04.716]
02 09:55:05.313  SIPListeningSocketTLS(#0) Socket debug message: CTcpServerSocket::IsSocketPending socket is pending for acceptSocketName: SIPLISTENING#0, FileDesc: 57  [Time:04-01@09:55:04.716]
03 09:55:05.313  TlsThresholdManager::OkayToAcceptTlsConnection - returning True [Time:04-01@09:55:04.716]
04 09:55:05.313  SIPListeningSocketTLS(#0)::OkayToHandleAccept - returning True [Time:04-01@09:55:04.716]
05 09:55:05.313  New SIPSocketReliable created - (#1528) - SocketID=7535 [Time:04-01@09:55:04.716]
06 09:55:05.313  New TLSSocketAPI created (#1528) - SocketID=7535 [Time:04-01@09:55:04.716]
07 09:55:05.313  New Socket buffer allocated - (#1528) [Time:04-01@09:55:04.716]
08 09:55:05.313  WhiteListManager: Adding TCPTLSSocket Remote IP: 52.114.75.24, Port: 8576, Interface ID: 0, Local Port: 5061, Protocol: 6 succeeded [Time:04-01@09:55:04.716]
09 09:55:05.313  SIPAppMngr::GetTlsContextIdForIpAddress: ProxySetId = -1, SIPInterface = 0, ContextID = 0 [Time:04-01@09:55:04.716]
10 09:55:05.314  SIPListeningSocketTLS(#0)::AcceptNewConnection - Incoming connection from 52.114.75.24:8576 accepted. SocketID=7535 [Time:04-01@09:55:04.717]
11 09:55:05.330  TLSSocketAPI(#1528) Socket debug message: CTcpClientSocket::HandleSocketEvent socket close/resetSocketName: SIPTcpChild, FileDesc: 114  [Time:04-01@09:55:04.732]
12 09:55:05.330  TLSSocketAPI(#1528)::HandleDisconnectEvent(EVENT_RECEIVER_DISCONNECT) [Time:04-01@09:55:04.732]
13 09:55:05.330  TLSSocketAPI(#1528)::DispatchQueueEvent(EVENT_RECEIVER_ERROR) - Closing connection [Time:04-01@09:55:04.732]
14 09:55:05.330  TLSSocketAPI(#1528) Removing closed socket from White List [Time:04-01@09:55:04.732]
15 09:55:05.330  WhiteListManager: Removing TCPTLSSocket Remote IP: 52.114.75.24, Port: 8576, Interface ID: 0, Local Port: 5061, Protocol: 6 succeeded [Time:04-01@09:55:04.732]
16 09:55:05.330  SIPSocketReliable(#1528)::ReleaseConnection - Closing connection [Time:04-01@09:55:04.732]
17 09:55:05.330  TLSSocketAPI(#1528) Released [Time:04-01@09:55:04.732]
18 09:55:05.330  SIPSocketReliable(#1528) Released - SocketID=7535 [Time:04-01@09:55:04.732]
19 09:55:05.330  TLSSocketAPI(#1528)::CloseConnection - Closing connection [Time:04-01@09:55:04.732]

Das ganze wiederholt sich dreimal in weniger als 1 Sekunde und ein viertes Mal nach ca. 12 Sekunden. Ich sehe in dem Log aber nicht, was Microsoft stört sondern nur, dass die TLS-Verbindung durch die initiierende Gegenseite wieder abgebaut wurde. Ich muss davon ausgehen, dass Sie mit ein "Client Hello" sendet und meine Server-Antwort ihm nicht gefällt. Mehr kann ich hier aber nicht sehen, denn die Fehlermeldung auf der Microsoft-Seite wird mir nicht übermittelt.

Also war doch wieder WireShark gefordert und über die Ansicht der Konversationen sind die Verbindungen mit wenigen Paketen leicht ausfindig zu machen:

Drei Pakete für den TCP-Handshake, dann den ClientHello/ServerHello mit ACK und am Ende der Abbau mit FIN/ACK passen in 6 Pakte je Richtung. Mit dem Filter sehe ich dann direkt die fehlgeschlagene Verbindung:

Im ClientHello finde ich Informationen über die von der Gegenseite angebotenen Optionen und den gewünschten Servernamen (SNI) und der Audiocodes reagiert darauf mit seinem ServerHello. Hier haben wir dann gesehen, dass Teams den SBC-Namen anfordert aber der Audiocodes ein "SelfSigned" Zertifikat zurückliefert. Das war auch die Vermutung des Microsoft Support

..however our assumption is that for some reason the SBC was randomly using the default TLS context and not the Teams TLS Context.
Quelle: Auszug Support Ticket

Passend dazu auch die Fehlermeldung, die Microsoft in ihrem System gefunden haben;

{
  "transferCompletion": {
    "reason": "unknown",
    "sender": null,
    "code": 504,
    "subCode": 549009,
    "phrase": "Unable to deliver REFER: outgoing TLS negotiation 
failed; HRESULT=0x80090325 SEC_E_UNTRUSTED_ROOT"
  },
  "debugContent": null
}
)

Die Meldung ist eindeutig. Bei den erfolgreichen Verbindungen vom gleichen Quellsystem (gleiche IP) hat der Audiocodes allerdings mit dem öffentlichen Zertifikat geantwortet. Daher habe ich mir die "Client Hello"-Pakete einer erfolgreichen und einer erfolglosen Verbindung genauer angeschaut:

Die Pakete waren 99% identisch. Nur der der QuellPort  die "Zufallszahl" und der Zeitstempel und entsprechend die Prüfsummen waren unterschiedlich.

Bei der weiteren Analyse ist dann aufgefallen, dass im Audiocodes im TLS-Context des SIP-Interface für die Verbindung zu Teams nicht das Teams-Profil mit dem Teams-Zertifikat sondern das "Default-Profil" eingetragen war. Damit ist natürlich erklärbar, dass der SBC das falsche Zertifikat liefert und Teams darüber nicht glücklich ist. Es erklärt aber nicht, warum die meisten normalen ausgehende Anrufe von Teams zum Amt problemlos möglich waren. Prüft Teams hier das Zertifikat vielleicht nicht oder liefert der Audiocodes ein anderes Zertifikat anhand einer Information im Client Hello aus. Wir haben dann im Audiocodes die TLS-Konfiguration noch einmal geprüft und tatsächlich noch eine falsche Bindung beim TLS-Context korrigiert.

Das die Verbindung für den Anrufer nicht zustande kommt und Teams die RTP-Verbindung nicht weiter betreibt, sendet mein Client ein BYE

BYE sip:xx.xx.xx.xx:5061;transport=tls;x-i=x-x-x-x-x;x-c=x/s/1/x SIP/2.0
Via: SIP/2.0/TLS 192.168.2.10:5061;alias;branch=xxxx
Max-Forwards: 57
From: <sip:+xxxxx@carriersbc.xxxxxx.de;user=phone>;tag=1c2029136551
To: <sip:+49xxxxxx@sbc.xxxxxxx.de>;tag=fded3353c9f143a3aa8383bc0e58583d
Call-ID: xxxxxxx@192.168.2.10
CSeq: 3 BYE
Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, INVITE, ACK, OPTIONS, CANCEL, BYE
User-Agent: M800C/v.7.40A.100.114
Reason: Q.850 ;cause=22 ;text="<guid>;MediaError"
Content-Length: 0

Monitoring

Es ist nicht sehr einfach, solche "suspekte" Verbindungen zu erkennen. Solange eine Verbindung auf selbst verwalteten Systemen einen Fehler generiert, ist das Monitoring recht einfach. Dieses Beispiel zeigt aber, dass Fehler nicht direkt lokal sichtbar sind aber den Anrufer stören oder gar verärgern.

Eine Meldung oder einen Counter von Microsoft über "nicht erfolgreiche REFER oder INVITE-Pakete" habe ich bislang noch nicht gesehen. der SBC-Status im Teams Admin Panel ist doch recht überschaubar:

In den Details zu einem SBC gibt es noch ein paar statistische Werte mehr und zu den Calls den Microsoft und SIP-Statuscode. Leider ist dort der ausgehende REFER oder die fehlerhafte Vermittlung nicht zu sehen.

Aber auch mein Audiocodes führt auch einige Statistiken mit. Die Anrufe auf einen Auto Attendant, die dann nicht über REFER auf eine CallQueue geleitet werden, sind relativ kurz und genau dafür gibt es entsprechende Counter. Interessant ist hier z.B. der "Short Call Counter":


Quelle: https://www.audiocodes.com/media/15570/sbc-gateway-performance-monitoring-reference-guide-ver-74.pdf Seite 633/593

Der Wert ist per REST und SNMP anrufbar. Damit eröffnet sich natürlich ein Weg, solche Probleme frühzeitig zu erkennen.

Offen ist noch, was laut Audiocodes der "pre-set threshold

Performance Monitoring
https://www.audiocodes.com/media/15570/sbc-gateway-performance-monitoring-reference-guide-ver-74.pdf

REST API for Devices
https://www.audiocodes.com/media/15604/rest-api-for-sbc-gateway-msbr-devices-ver-74.pdf

Zusammenfassung

Das Problem mit den "manchmal" nicht funktionierenden REFER-Sitzungen ist natürlich nicht einfach zu finden und gleicht der Nadel im Heuhaufen. Zum Glück kann man solche TLS-Probleme sehr früh in einem Projekt entdecken. Allerdings kann ich auch nie sicher sein, ob ein Firmware-Updates meines SBC oder eine Weiterentwicklung bei Microsoft eine bislang sauber funktionierende Verbindung nicht doch stört.

Der beste Schutz ist hier wohl der Betrieb von zertifizierten SBCs mit einer vom Hersteller und Microsoft empfohlenen Konfiguration. Allerdings ist das auch keine Garantie aufgrund der Unmenge an möglichen Konstellationen und Feinheiten bei SIP.

Solange der Fehler auf der eigenen Umgebung sichtbar ist, kann ich diesen per Monitoring auch erfassen und melden. Fehler auf der entfernten Seite bei Microsoft kann ich aktuell nicht im "Self Service" fixen sondern nur mit einem Support Ticket. Schade ist, dass z.B. dieser spezielle TLS-Fehler auch nicht im SBC-Diagramm sichtbar war.

Eine Möglichkeit einer frühen Überwachung ist die Erfassung der Länge von Anrufen. Eine stark steigende Anzahl an kurzen Voice-Verbindungen kann ein erster Indikator für ein Problem sein. Auch eine Überwachung der TCP-Streams auf kurze TCP-Verbindungen kann ein Hinweis auf Verbindungsprobleme sein.

Weitere Links