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

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@208.9.10.11:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C P-Asserted-Identity: <sip:8881112222@216.0.0.1:5060> To: sip:9615551212@208.9.10.11:5060 Contact: <sip:8881112222@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@216.0.0.1:5060>;tag=2077471748_C To: sip:9615551212@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@10.133.44.55:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C P-Asserted-Identity: <sip:8881112222@216.0.0.1:5060> To: sip:9615551212@208.9.10.11:5060 Contact: <sip:8881112222@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@208.9.10.11:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@10.133.44.55:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@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@208.9.10.11:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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@10.133.44.55:5060;user=phone SIP/2.0 From: <sip:8881112222@216.0.0.1:5060>;tag=2077471748_C To: <sip:9615551212@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.