Office Communicator SIP Trace – Multiple Points of Presence (MPOP)
During my work on OCS engagements, I’ve already seen situations where OCS admins would start successful trace of SIP sessions (IM, voice calls, conferences, etc) but at one point they would be “lost” in that bunch of SIP packets in the log. In short – they’d expect to see less messages related to the call than they would find in their logs.
Provided that they correctly sorted SIP messages belonging to the same SIP session (which is easily done by finding all messages with same Call-ID[1]), they’d still see more SIP messages than they’d expect to see.
When talking about Voice Call Flow SIP trace, I didn’t mention one of rather frequent situations you’re going to encounter in your SIP traces: multiple points of presence (MPOP). While I did it on purpose in that particular blog post (for simplicity), it’s necessary to address those scenarios as you will often find in SIP traces more SIP messages (mainly provisional, 1xx replies) than you’d expect, usually due to recipient having multiple registered SIP endpoints (and thus multiple points of presence).
For more detailed information on MPOP, please see Sriram’s blog.
Following examples address such communication where called party (in this case IzabelaF) has logged on with two endpoints: Office Communicator Phone 2007 R2 and Office Communicator 2007 R2, while remote user (MarinoF) uses his OC 2007 R2 client to place a call.
Please note that in parenthesis after each SIP method/header, I’m putting the direction of the message from the caller’s point of view.
[1] Each SIP session is uniquely identified with Call-ID header parameter, so the first step in finding related SIP messages would be to search for all SIP messages with identical Call-ID
SIP Invite (OUT)
Excerpt:
01/05/2010|14:00:47.889 418:D8 INFO :: INVITE sip:izabelaf@uclab.org SIP/2.0
Via: SIP/2.0/TLS 200.1.1.201:2604
Max-Forwards: 70
From: <sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 1 INVITE
Contact: <sip:marinof@uclab.org;opaque=user:epid:NFExHZ6mj1yDHREOYWtdYQAA;gruu>
User-Agent: UCCAPI/3.5.6907.0 OC/3.5.6907.0 (Microsoft Office Communicator 2007 R2)
The first message shows an attempt to setup a SIP session between a caller (sip:marinof@uclab.org) and a called party (sip:izabelaf@uclab.org).
If we skip next two “standard” messages sent from FE server (100 Trying and 183 Session Progress), we’ll see an interesting ms-diagnostics header value in 101 Progress Report message:
101 Progress Report (IN)
Excerpt:
ms-diagnostics: 13004;reason="Request was proxied to one or more registered endpoints";source="R2EE01.uclab.org";appName="InboundRouting"
Server: InboundRouting/3.5.0.0
101 Progress Report shows that the request was handled by server-side Inbound Routing component. Inbound Routing handles incoming calls in such way that it forks the call to all called party’s registered endpoints.
183 Session Progress (endpoint 1) (IN)
Excerpt:
01/05/2010|14:00:48.831 418:D8 INFO :: SIP/2.0 183 Session Progress
ms-user-logon-data: RemoteUser
Authentication-Info: NTLM rspauth="0100000000000000C2EA75A8807B40EA", srand="8E9BFD7E", snum="16", opaque="135DF6CC", qop="auth", targetname="R2EE01.uclab.org", realm="SIP Communications Service"
Via: SIP/2.0/TLS 200.1.1.201:2604;ms-received-port=2604;ms-received-cid=500
From: "Marino Filipovic"<sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=aad34505db;tag=c34587eaa8
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 1 INVITE
Record-Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
Contact: <sip:izabelaf@uclab.org;opaque=user:epid:ATX04NzZClmCm9_s1BVjeAAA;gruu>
User-Agent: UCCAPI/3.5.6907.0 OC/3.5.6907.0 (Microsoft Office Communicator 2007 R2)
First 183 Session Progress message shows reply from one of Izabela’s registered endpoints, OC 2007 R2 client, which is visible from User-Agent header value:
User-Agent: UCCAPI/3.5.6907.0 OC/3.5.6907.0 (Microsoft Office Communicator 2007 R2)
Please, pay attention to epid and tag values in To: header. I stressed in my previous blog that you can expect different epid and tag values in To: headers in case recipient has multiple registered endpoints, as those values uniquely identify each registered endpoint. This is also one of very helpful information when differentiating between multiple SIP messages (such as multiple 183 Session Progress messages).
So, lets see the second 183 Session Progress message.
183 Session Progress (endpoint 2) (IN)
Excerpt:
01/05/2010|14:00:49.191 418:D8 INFO :: SIP/2.0 183 Session Progress
ms-user-logon-data: RemoteUser
Authentication-Info: NTLM rspauth="01000000000000005DBAB6FE807B40EA", srand="B48CE0F0", snum="19", opaque="135DF6CC", qop="auth", targetname="R2EE01.uclab.org", realm="SIP Communications Service"
Via: SIP/2.0/TLS 200.1.1.201:2604;ms-received-port=2604;ms-received-cid=500
From: "Marino Filipovic"<sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=2798f0b3cc;tag=97a7d6045d
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 1 INVITE
Record-Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
Contact: <sip:izabelaf@uclab.org;opaque=user:epid:uozeqPgOuFOVd0DaRpeFCgAA;gruu>
User-Agent: CPE/3.5.6907.0 OCPhone/3.5.6907.0 (Office Communicator Phone 2007 R2)
Second 183 Session Progress message shows reply from another Izabela’s registered endpoint: this time it’s Office Communicator Phone (User-Agent: CPE/3.5.6907.0 OCPhone/3.5.6907.0 (Office Communicator Phone 2007 R2)).
If you click on screenshots in both 183 messages you will see SDP data containing ICE protocol details used to establish media flow between the caller and called party. This is nothing else than answer to SDP offer sent in first analyzed packet (SIP Invite from Marino) where you can find two SDP blocks (to accommodate both R1 and R2 OC clients, as mentioned in my previous blog) with Marino’s candidates to be used for establishing media flow.
Note: ICE negotiation has several phases which is not within the scope of this blog post, but just for informational purposes let’s say that the actions performed during media path negotiation are: address discovery and exchange, connectivity check and address candidate promotion.
Note: It’s important to stress that SDP details can be seen in provisional (1xx) messages only in case of OCS 2007 R2 and later. In previous releases, SDP offer with caller’s ICE candidates would still be sent in SIP Invite message, but called party would reply with it’s own candidates in 200 OK message which would sometimes lead to first Hello going unheard. As of OCS 2007 R2, the support for early media is added so that media negotiation starts before the call is actually answered by called party. It’s also necessary that endpoints support early media which is the case with OCS 2007 R2 and later endpoints.
200 OK (IN)
Excerpt:
01/05/2010|14:00:59.296 418:D8 INFO :: SIP/2.0 200 OK
ms-user-logon-data: RemoteUser
Authentication-Info: NTLM rspauth="01000000000000007CA5BF76807B40EA", srand="5F94A5D3", snum="21", opaque="135DF6CC", qop="auth", targetname="R2EE01.uclab.org", realm="SIP Communications Service"
P-Asserted-Identity: <sip:izabelaf@uclab.org>, <tel:+38514802551>
Via: SIP/2.0/TLS 200.1.1.201:2604;ms-received-port=2604;ms-received-cid=500
From: "Marino Filipovic"<sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=2798f0b3cc;tag=97a7d6045d
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 1 INVITE
Record-Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
Contact: <sip:izabelaf@uclab.org;opaque=user:epid:uozeqPgOuFOVd0DaRpeFCgAA;gruu>
User-Agent: CPE/3.5.6907.0 OCPhone/3.5.6907.0 (Office Communicator Phone 2007 R2)
.
. (cut due to simplicity)
a=ice-ufrag:Ec9d
a=ice-pwd:EWRPxB9CrdW64VXL1trp587N
a=candidate:1 1 UDP 2130706431 172.31.255.73 32039 typ host
a=candidate:1 2 UDP 2130705918 172.31.255.73 3599 typ host
a=candidate:2 1 TCP-PASS 6556159 200.1.1.20 51553 typ relay raddr 200.1.1.20 rport 51553
a=candidate:2 2 TCP-PASS 6556158 200.1.1.20 51553 typ relay raddr 200.1.1.20 rport 51553
a=candidate:3 1 UDP 16648703 200.1.1.20 52279 typ relay raddr 200.1.1.20 rport 52279
a=candidate:3 2 UDP 16648702 200.1.1.20 57326 typ relay raddr 200.1.1.20 rport 57326
a=candidate:4 1 TCP-ACT 7076863 200.1.1.20 51553 typ relay raddr 200.1.1.20 rport 51553
a=candidate:4 2 TCP-ACT 7076350 200.1.1.20 51553 typ relay raddr 200.1.1.20 rport 51553
a=candidate:5 1 TCP-ACT 1684797951 172.31.255.73 31247 typ srflx raddr 172.31.255.73 rport 31247
a=candidate:5 2 TCP-ACT 1684797438 172.31.255.73 31247 typ srflx raddr 172.31.255.73 rport 31247
Although media negotiations starts before the call is answered (to accommodate early-media requirements), the called party still sends its final candidates (from the endpoint that answered the call) in 200 OK message to complete ICE negotiation.
Note: what is not visible from this trace (as that is communication between the server and the other endpoint) is that server cancels invitation to the other endpoint using SIP CANCEL method.
ACK (OUT)
Excerpt:
01/05/2010|14:00:59.456 418:D8 INFO :: ACK sip:izabelaf@uclab.org;opaque=user:epid:uozeqPgOuFOVd0DaRpeFCgAA;gruu SIP/2.0
Via: SIP/2.0/TLS 200.1.1.201:2604
Max-Forwards: 70
From: <sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=2798f0b3cc;tag=97a7d6045d
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 1 ACK
Route: <sip:sip.uclab.org:443;transport=tls;opaque=state:Ci.R500;lr;ms-route-sig=babjyotg5YrHahdExfv5G_R78glc6rHo0ChevgyAAA>
Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
User-Agent: UCCAPI/3.5.6907.0 OC/3.5.6907.0 (Microsoft Office Communicator 2007 R2)
Supported: ms-dialog-route-set-update
Proxy-Authorization: NTLM qop="auth", realm="SIP Communications Service", opaque="135DF6CC", targetname="R2EE01.uclab.org", crand="a1b5d2ce", cnum="15", response="0100000000000000adf58669807b40ea"
SIP session three way handshake completes with acknowledgement from Marino’s endpoint to Izabela’s endpoint that was picked to answer the call.
SIP INVITE (OUT)
Excerpt:
01/05/2010|14:01:04.934 418:D8 INFO :: INVITE sip:izabelaf@uclab.org;opaque=user:epid:uozeqPgOuFOVd0DaRpeFCgAA;gruu SIP/2.0
Via: SIP/2.0/TLS 200.1.1.201:2604
Max-Forwards: 70
From: <sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=2798f0b3cc;tag=97a7d6045d
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 3 INVITE
Route: <sip:sip.uclab.org:443;transport=tls;opaque=state:Ci.R500;lr;ms-route-sig=babjyotg5YrHahdExfv5G_R78glc6rHo0ChevgyAAA>
Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
Contact: <sip:marinof@uclab.org;opaque=user:epid:NFExHZ6mj1yDHREOYWtdYQAA;gruu>
User-Agent: UCCAPI/3.5.6907.0 OC/3.5.6907.0 (Microsoft Office Communicator 2007 R2)
.
. (cut due to simplicity)
a=candidate:1 1 UDP 2130706431 200.1.1.201 50016 typ host
a=candidate:1 2 UDP 2130705918 200.1.1.201 50018 typ host
a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:JTZf0de/tIGNK+5aQmVJCgslAzCLYsPwNJgG/Ga+|2^31|1:1
a=remote-candidates:1 200.1.1.20 52279 2 200.1.1.20 57326
After ICE connectivity check and candidate promotion is completed (very detailed information can be found in Bernd’s blog), Marino is sending the second SIP INVITE with chosen candidates (both local and remote), which can be seen in above excerpt.
200 OK (IN)
Excerpt:
01/05/2010|14:01:05.154 418:D8 INFO :: SIP/2.0 200 OK
ms-user-logon-data: RemoteUser
Authentication-Info: NTLM rspauth="01000000000000006A0598A9807B40EA", srand="E662685E", snum="27", opaque="135DF6CC", qop="auth", targetname="R2EE01.uclab.org", realm="SIP Communications Service"
Via: SIP/2.0/TLS 200.1.1.201:2604;ms-received-port=2604;ms-received-cid=500
From: <sip:marinof@uclab.org>;tag=0fae8454e3;epid=1488039028
To: <sip:izabelaf@uclab.org>;epid=2798f0b3cc;tag=97a7d6045d
Call-ID: e34305289c3b4c368c583f531fddeff3
CSeq: 3 INVITE
Record-Route: <sip:pool01.uclab.org:5061;transport=tls;ms-fe=R2EE01.uclab.org;opaque=state:F:T:Eu;lr;received=172.31.255.222;ms-received-cid=401>
Contact: <sip:izabelaf@uclab.org;opaque=user:epid:uozeqPgOuFOVd0DaRpeFCgAA;gruu>
User-Agent: CPE/3.5.6907.0 OCPhone/3.5.6907.0 (Office Communicator Phone 2007 R2)
.
. (cut due to simplicity)
a=candidate:3 1 UDP 16648703 200.1.1.20 52279 typ relay raddr 200.1.1.20 rport 52279
a=candidate:3 2 UDP 16648702 200.1.1.20 57326 typ relay raddr 200.1.1.20 rport 57326
a=crypto:2 AES_CM_128_HMAC_SHA1_80 inline:kSYTWb/FPgCEeGKC1/6z4in0Nr1gNfYymLwBMfCc|2^31|1:1
a=remote-candidates:1 200.1.1.201 50016 2 200.1.1.201 50018
Izabela’s client confirms the candidates and formally completes the candidate negotiation.
Summary
When tracing a particular SIP session you might encounter slightly more complex traces than you usually would see in the logs. Reasons could be various: simultaneous ringing set on called party’s side, delegation, but also that called party has multiple registered endpoints in which case each endpoint would reply to initial SIP INVITE. However, you’ll notice that only one of those endpoints (the one that picked the call) would complete the three way handshake process (INVITE/200 OK/ACK).
Although it might look confusing to see multiple 180 and 183 messages, paying attention to tag and epid values in To: header will help resolve most doubts. As for multiple 200 OK messages in the same SIP session, it’s very helpful to check CSeq header value in each 200 OK message, as it identifies a particular transaction (looking at CSeq values, you will see that some of those 200 OK messages belong to first INVITE, some to PRACK and some to second INVITE).