[Serusers] Via: branch tags for CANCELs sometimes don't match the one in the INVITE

Mon Oct 12 21:57:11 CEST 2009

I have been tracking a problem for some time regarding
CANCELs that the switch beyond SER was randomly ignoring.
There appear to be a number of issues, but one that was
identified is caused by SER unexpectedly emitting a branch
tag on the Via: header of the CANCEL with a value that
isn't identical to the value that appeared in the
INVITE message.

When the CANCEL arrives at the destination switch with a
different branch tag than what was shown in the INVITE,
the destination switch correctly rejects the CANCEL with
a 481, saying it never heard of this call.  So the call
doesn't really end.  They say they are following RFC 3261,
and that does state that the Via: header MUST exactly
match.

This variance of the branch tag that SER emits doesn't happen
every time and is infrequent and random, occurring, perhaps
1% of the time.   99% of the time, the same branch
value appears in both INVITE and CANCEL messages.  This
occasional mismatch is being seen in 2.0.0-rc1 on FreeBSD,
Server: SER (2.0.0-rc1 (x86_64/freebsd))

syn_branch=0 is set because branches of zero in ACKs
were a really bad thing too.

Based on a number of these that have been reviewed, the
branch tag generated by SER has three parts,
eg  branch=STRING1.STRING2.0
I note that STRING1 remains the same but when the
malfunction occurs, STRING2 is completely different, as in:

FROM INVITE branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c11079.0
FROM CANCEL branch=z9hG4bK7314.b4c66001f96f5dd30ddbf6536fd34935.0

Below is a sample call showing one of these events.

Any suggestions on what the problem might be or if this is a
known bug (hopefully with a patch) are appreciated.

- - - - - - - - - - - - - - - - - -

Here is a sample call.  IP addresses and phone numbers have
been altered, but call ID and branch tags are untouched:

CALL ARRIVES AT SER

U 2009/10/05 23:00:45.616070 216.0.0.1:5060 -> 208.9.10.11:5060
INVITE sip:9615551212 at 208.9.10.11:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
P-Asserted-Identity: <sip:8881112222 at 216.0.0.1:5060>
To: sip:9615551212 at 208.9.10.11:5060
Contact: <sip:8881112222 at 216.0.0.1:5060>
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
Max-Forwards: 70
Content-Length: 281
Allow: INVITE, ACK, CANCEL, BYE
Content-Type: application/sdp
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1

v=0
o=SIPUAC_1.92.1.8 2077471748 1 IN IP4 55.66.77.88
s=call
c=IN IP4 55.66.77.88
t=0 0
m=audio 21356 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=maxptime:30

SER SENDS TRYING BACK TO CALLING SWITCH

U 2009/10/05 23:00:45.626174 208.9.10.11:5060 -> 216.0.0.1:5060
SIP/2.0 100 trying -- your call is important to us
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: sip:9615551212 at 208.9.10.11:5060
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: SER (2.0.0-rc1 (x86_64/freebsd))
Content-Length: 0

SER SENDS CALL ON TO PSTN SWITCH

U 2009/10/05 23:00:45.626192 10.100.20.42:5060 -> 10.133.44.55:5060
INVITE sip:9615551212 at 10.133.44.55:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
P-Asserted-Identity: <sip:8881112222 at 216.0.0.1:5060>
To: sip:9615551212 at 208.9.10.11:5060
Contact: <sip:8881112222 at 216.0.0.1:5060>
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
Max-Forwards: 16
Content-Length: 301
Allow: INVITE, ACK, CANCEL, BYE
Content-Type: application/sdp
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c1107
9.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1

v=0
o=SIPUAC_1.92.1.8 2077471748 1 IN IP4 55.66.77.88
s=call
c=IN IP4 55.66.77.88
t=0 0
m=audio 55878 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=maxptime:30
a=nortpproxy:yes

CALLING SWITCH TELLS SER IT IS TRYING

U 2009/10/05 23:00:45.629000 10.133.44.55:5060 -> 10.100.20.42:5060
SIP/2.0 100 Trying
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c1107
9.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Content-Length: 0

CALLING PARTY CHANGES MIND - GOES ON-HOOK

U 2009/10/05 23:00:50.579059 216.0.0.1:5060 -> 208.9.10.11:5060
CANCEL sip:9615551212 at 208.9.10.11:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 CANCEL
Max-Forwards: 70
Content-Length: 0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1

SER SENDS CANCEL TO PSTN SWITCH, BUT BRANCH TAGS DON'T MATCH:

U 2009/10/05 23:00:50.590039 10.100.20.42:5060 -> 10.133.44.55:5060
CANCEL sip:9615551212 at 10.133.44.55:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 CANCEL
Max-Forwards: 16
Content-Length: 0
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.b4c66001f96f5dd30ddbf6536fd3493
5.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1

NOTE BRANCH MISMATCH:
FROM INVITE branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c11079.0
FROM CANCEL branch=z9hG4bK7314.b4c66001f96f5dd30ddbf6536fd34935.0

SER SENDS 200 CANCELING BACK TO CALLING SWITCH

U 2009/10/05 23:00:50.590054 208.9.10.11:5060 -> 216.0.0.1:5060
SIP/2.0 200 canceling
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: 
<sip:9615551212 at 208.9.10.11:5060>;tag=68cf7f6b22161b0d4dc719dbc13e05af-90a6
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 CANCEL
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: SER (2.0.0-rc1 (x86_64/freebsd))
Content-Length: 0

PSTN SWITCH REJECTS CANCEL, NOT RECOGNIZING THE CALL
PSTN NETWORK CONTINUES TO PROCESS CALL DESPITE CALLER
NOW BEING ON-HOOK

U 2009/10/05 23:00:50.591489 10.133.44.55:5060 -> 10.100.20.42:5060
SIP/2.0 481 Call/Transaction Does Not Exist
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 CANCEL
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+0+b6afb3ac
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.b4c66001f96f5dd30ddbf6536fd3493
5.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Content-Length: 0

PSTN SWITCH SENDS BACK ACM/183 Session Progress TO SER

U 2009/10/05 23:00:52.619487 10.133.44.55:5060 -> 10.100.20.42:5060
SIP/2.0 183 Session Progress
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c1107
9.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 10.133.44.55:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

SER SENDS 183 SESSION PROGRESS BACK TO CALLING SWITCH

U 2009/10/05 23:00:52.629924 208.9.10.11:5060 -> 216.0.0.1:5060
SIP/2.0 183 Session Progress
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 208.9.10.11:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

SER RECEIVES 200 OK FROM PSTN SWITCH

U 2009/10/05 23:00:58.129670 10.133.44.55:5060 -> 10.100.20.42:5060
SIP/2.0 200 OK
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c1107
9.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 10.133.44.55:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

SER PASSES 200 OK ON TO CALLING SWITCH

U 2009/10/05 23:00:58.137724 208.9.10.11:5060 -> 216.0.0.1:5060
SIP/2.0 200 OK
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 208.9.10.11:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

BECAUSE OF NO RESPONSE TO 200 OK, PSTN SWITCH SENDS IT AGAIN

U 2009/10/05 23:00:58.629267 10.133.44.55:5060 -> 10.100.20.42:5060
SIP/2.0 200 OK
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.6082c3659eb65543a8e2788f54c1107
9.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 10.133.44.55:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

U 2009/10/05 23:00:58.639701 208.9.10.11:5060 -> 216.0.0.1:5060
SIP/2.0 200 OK
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 INVITE
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_1
Server: DC-SIP/2.0
Contact: <sip:9615551212 at 208.9.10.11:5060;user=phone>
Content-Type: application/sdp
Content-Length: 223

v=0
o=- 3463772452 3463772517 IN IP4 10.133.44.55
s=-
c=IN IP4 10.200.20.40
t=0 0
m=audio 50924 RTP/AVP 18 101
a=sendrecv
a=ptime:20
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no

CALLING SWITCH FINALLY SENDS AN ACK TO SER TO GET RETRIES TO STOP.

U 2009/10/05 23:00:58.690296 216.0.0.1:5060 -> 208.9.10.11:5060
ACK sip:9615551212 at 208.9.10.11:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 ACK
Max-Forwards: 70
Content-Length: 0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_2

SER FORWARDS ACK TO PSTN SWITCH.
PSTN NETWORK THINKS CALL IS ALIVE, VOIP NETWORK KNOWS CALL IS DEAD.

U 2009/10/05 23:00:58.690355 10.100.20.42:5060 -> 10.133.44.55:5060
ACK sip:9615551212 at 10.133.44.55:5060;user=phone SIP/2.0
From: <sip:8881112222 at 216.0.0.1:5060>;tag=2077471748_C
To: <sip:9615551212 at 208.9.10.11:5060>;tag=000a0285+1+21a4018b+2cd8ce96
Call-ID: 
sbcsipuac.2_11.22.33.44_b09sb07_1_2009100519004555_2077471748_716911
CSeq: 1005 ACK
Max-Forwards: 16
Content-Length: 0
Via: SIP/2.0/UDP 
10.100.20.42;branch=z9hG4bK7314.1fc8626bef702f1428ad6fd4fd2aa7a
f.0
Via: SIP/2.0/UDP 216.0.0.1:5060;branch=z9hG4bK_2077471748_2110_2

....

So the called party has answered the call and can't hear
anything. Depending on whether a human or automation was
called, this call could remain active on the PSTN for some
time.