Junction Networks » Blogs » mike's blog »

Debugging a Grandstream Phone

May
08
2009
Posted by mike at 04:19 PM EST

Super techy post today.

We ran down a problem where a Grandstream phone had two users (Lisa and Michele) registered. Both users were in the same call group so the Grandstream phone received two calls that were nearly identical. The difference was the two calls designated two different call branches and were to different usernames, but both reflected the same call-ID (because they ARE the same call, just separate branches.)

After some work, we discovered that the Grandstream phone rang the line of the first SIP INVITE it received, but 'answered' the last INVITE. Following through the trail of INVITEs and CANCELs below, you can see where the confusion starts. We have submitted this information to Grandstream for their consideration - we are asking that their devices honor the "branch" tag.

For those SIP tech's out there, enjoy our analysis of a call to two users on the same SIP UA (all phone numbers, domains and IP addresses have been modified):

Two users in group Lisa and Michele

Lisa is on 192.168.1.107:5060 on a Grandstream - this phone receives Branch .2.
Michele is also on 192.168.1.107 but on port 5064 on a Grandstream - this phone receives Branch .5.

Customer reports that this call was picked up by the "Lisa" line.

**Invite to Lisa on Grandstream (GS) - Branch .2. of call ID 133...3a4c**
U 2009/05/08 09:40:18.325507 66.227.1xx.2xx:5060 -> 24.33.2xx.3xx:5060
INVITE sip:lisa@192.168.1.107:5060;transport=udp;aor=lisa%40xxuserdomainxx.onsip.com SIP/2.0.
Record-Route: .
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.2.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
From: "0000000000" ;tag=as2bbf1438.
To: .
Contact: .
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Asterisk PBX.
Max-Forwards: 69.
Date: Fri, 08 May 2009 13:40:18 GMT.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY.
Content-Type: application/sdp.
Content-Length: 381.
P-Gateway: 66.227.100.215.
.
v=0.
o=root 26678 26678 IN IP4 66.227.100.215.
s=session.
c=IN IP4 66.227.100.215.
t=0 0.
m=audio 19870 RTP/AVP 0 8 3 111 18 4 101.
a=rtpmap:0 PCMU/8000.
a=rtpmap:8 PCMA/8000.
a=rtpmap:3 GSM/8000.
a=rtpmap:111 G726-32/8000.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=rtpmap:4 G723/8000.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=silenceSupp:off - - - -.
a=ptime:20.


**Invite to Michele on GS - Branch .5. of call ID 133...3a4c**
U 2009/05/08 09:40:18.325571 66.227.1xx.2xx:5060 -> 24.33.2xx.3xx:5064
INVITE sip:michele@192.168.1.107:5064;transport=udp;aor=michele%40xxuserdomainxx.onsip.com SIP/2.0.
Record-Route: .
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.5.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
From: "0000000000" ;tag=as2bbf1438.
To: .
Contact: .
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Asterisk PBX.
Max-Forwards: 69.
Date: Fri, 08 May 2009 13:40:18 GMT.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY.
Content-Type: application/sdp.
Content-Length: 381.
P-Gateway: 66.227.100.215.
.
v=0.
o=root 26678 26678 IN IP4 66.227.100.215.
s=session.
c=IN IP4 66.227.100.215.
t=0 0.
m=audio 19870 RTP/AVP 0 8 3 111 18 4 101.
a=rtpmap:0 PCMU/8000.
a=rtpmap:8 PCMA/8000.
a=rtpmap:3 GSM/8000.
a=rtpmap:111 G726-32/8000.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=rtpmap:4 G723/8000.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=silenceSupp:off - - - -.
a=ptime:20.

**Receive "Trying" from Lisa on GS - Branch .2.**
U 2009/05/08 09:40:18.404981 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.2.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
From: "0000000000" ;tag=as2bbf1438.
To: .
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Content-Length: 0.
.

**"RINGING" from Lisa on GS - Branch .2.**
U 2009/05/08 09:40:18.416313 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.2.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
Record-Route: .
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Contact: .
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE.
Content-Length: 0.
.


** "RINGING" from Michele on GS - .5.  We did not receive "Trying" from the .5. branch, but that's not an issue.  However, customer reports that only one 'line' is ringing on the phone itself: the 'Lisa' line.**
U 2009/05/08 09:40:18.479063 24.33.2xx.3xx:5064 -> 66.227.1xx.2xx:5060
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.5.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
Record-Route: .
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Contact: .
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE.
Content-Length: 0.
.

**Status:  At this point we have received provisional responses on both branch .2. and branch .5., but the customer states that only one 'line' on the phone is ringing.

**OK from Lisa on Grandstream - NOTE:  The ok is from the user 'Lisa' BUT it's in response to the .5. branch.  This is a problem.  The .5. branch was the user 'Michele's branch.  Theory - the first invite received is the line that rings, but when answered, the phone answers the last invite received.**
U 2009/05/08 09:40:27.712967 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.5.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
Record-Route: .
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Contact: .
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE.
Content-Type: application/sdp.
Supported: replaces, timer.
Content-Length: 213.
.
v=0.
o=lisa 8000 8000 IN IP4 192.168.1.107.
s=SIP Call.
c=IN IP4 192.168.1.107.
t=0 0.
m=audio 5056 RTP/AVP 0 101.
a=sendrecv.
a=rtpmap:0 PCMU/8000.
a=ptime:20.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-11.

**Sending "CANCEL" to Lisa at the .2. branch**
U 2009/05/08 09:40:27.713409 66.227.1xx.2xx:5060 -> 24.33.2xx.3xx:5060
CANCEL sip:lisa@192.168.1.107:5060;transport=udp;aor=lisa%40xxuserdomainxx.onsip.com SIP/2.0.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.2.
From: "0000000000" ;tag=as2bbf1438.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
To: .
CSeq: 102 CANCEL.
Max-Forwards: 70.
User-Agent: OpenSIPS (1.5.1-notls (x86_64/linux)).
Content-Length: 0.
.



**OK back from Lisa on GS regarding CANCEL - Branch .2.**
U 2009/05/08 09:40:27.784852 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.2.
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 CANCEL.
User-Agent: Grandstream GXP2000 1.1.6.46.
Supported: replaces, timer.
Content-Length: 0.
.

**Lisa user on GS saying Request Cancelled - however this shows branch .5. is being cancelled - the Grandstream previously gave an OK to the .5. branch in the OK above, now it's cancelling the call.  Basically it's confused between the branches.  The customer experience is that the call now drops.**
U 2009/05/08 09:40:27.793189 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 487 Request Cancelled.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.5.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK1a92f9f1;rport=5060.
Record-Route: .
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 102 INVITE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Content-Length: 0.
.


**Junction Networks ACK's the 'Request Cancelled" on the .5. branch in the above packet.**
U 2009/05/08 09:40:27.793432 66.227.1xx.2xx:5060 -> 24.33.2xx.3xx:5064
ACK sip:michele@192.168.1.107:5064;transport=udp;aor=michele%40xxuserdomainxx.onsip.com SIP/2.0.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKd146.d2c78147.5.
From: "0000000000" ;tag=as2bbf1438.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
To: ;tag=b71cb81c3beef471.
CSeq: 102 ACK.
Max-Forwards: 70.
User-Agent: OpenSIPS (1.5.1-notls (x86_64/linux)).
Content-Length: 0.
.


**Asterisk PBX sending "BYE" to user Lisa on GS for call - now that all other branches were cancelled, the call is now branch .0.**
U 2009/05/08 09:41:18.413797 66.227.1xx.2xx:5060 -> 24.33.2xx.3xx:5060
BYE sip:lisa@24.33.2xx.3xx:5060;transport=udp SIP/2.0.
Record-Route: .
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKe146.a562be32.0.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK3f1ae941;rport=5060.
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Contact: .
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 103 BYE.
User-Agent: Asterisk PBX.
Max-Forwards: 69.
Content-Length: 0.
.

**Lisa on GS complaining that there is no such call to send the BYE to - that phone had already cancelled the call**
U 2009/05/08 09:41:18.480821 24.33.2xx.3xx:5060 -> 66.227.1xx.2xx:5060
SIP/2.0 481 No Such Call.
Via: SIP/2.0/UDP 66.227.1xx.2xx;branch=z9hG4bKe146.a562be32.0.
Via: SIP/2.0/UDP 66.227.100.215:5060;received=66.227.100.215;branch=z9hG4bK3f1ae941;rport=5060.
Record-Route: .
From: "0000000000" ;tag=as2bbf1438.
To: ;tag=b71cb81c3beef471.
Call-ID: 1330352b536b8d7a74970bcf4df83a4c@jnctn.net.
CSeq: 103 BYE.
User-Agent: Grandstream GXP2000 1.1.6.46.
Content-Length: 0.
.