PJSIP: Could not find matching INVITE transaction for CANCEL request

dumblebee · August 29, 2016, 9:00pm

Hi,

I am experiencing problems with CANCEL after INVITE requests from a users private PBX (Mitel):
[Aug 29 16:55:22] ERROR[11139]: res_pjsip/pjsip_distributor.c:231 find_dialog: Could not find matching INVITE transaction for CANCEL request

INVITE:

22:23:45.64 ZGS_SIP: INVITE sip:015112345678@sip.example.com SIP/2.0
22:23:45.65 ZGS_SIP: Via: SIP/2.0/UDP 192.168.96.230:10670;branch=z9hG4bK11552_INVITE;rport
22:23:45.65 ZGS_SIP: From: <sip:sip329892@sip.example.com>;tag=9fxced2231sl
22:23:45.65 ZGS_SIP: To: <sip:015112345678@sip.example.com>
22:23:45.65 ZGS_SIP: Call-ID: 1346-0-1978-1998d58@csip
22:23:45.65 ZGS_SIP: CSeq: 11552 INVITE
22:23:45.65 ZGS_SIP: Contact: <sip:sip329892@123.123.123.123:10670;transport=udp> #123 -> Public IP
22:23:45.65 ZGS_SIP: P-preferred-identity: <sip:0221987654321@sip.example.com>
22:23:45.65 ZGS_SIP: Privacy: none
22:23:45.65 ZGS_SIP: Max-Forwards: 70
22:23:45.65 ZGS_SIP: User-Agent: OpenCom X320 (R 1.576.19.1 mitel-ocx)
22:23:45.65 ZGS_SIP: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY, PRACK
22:23:45.65 ZGS_SIP: Content-Type: application/sdp
22:23:45.65 ZGS_SIP: Accept: application/sdp, multipart/mixed, application/vnd.etsi.pstn+xml, application/dtmf-relay
22:23:45.65 ZGS_SIP: Content-Length:   254
22:23:45.65 ZGS_SIP: v=0
22:23:45.65 ZGS_SIP: o=root 1472502230 1472502230 IN IP4 192.168.96.230
22:23:45.66 ZGS_SIP: s=session
22:23:45.66 ZGS_SIP: c=IN IP4 192.168.96.230
22:23:45.66 ZGS_SIP: t=0 0
22:23:45.66 ZGS_SIP: m=audio 44104 RTP/AVP 8 101
22:23:45.66 ZGS_SIP: a=rtpmap:8 PCMA/8000
22:23:45.66 ZGS_SIP: a=rtpmap:101 telephone-event/8000
22:23:45.66 ZGS_SIP: a=fmtp:101 0-15
22:23:45.66 ZGS_SIP: a=ptime:20
22:23:45.66 ZGS_SIP: a=silenceSupp:off - - - -
22:23:45.66 ZGS_SIP: a=sendrecv

Asterisk sends 183 Session Progress.

–> Hang up phone.

CANCEL:

22:24:22.44 ZGS_SIP: CANCEL sip:015112345678@sip.example.com SIP/2.0
22:24:22.44 ZGS_SIP: Via: SIP/2.0/UDP 192.168.96.230:10670;branch=z9hG4bK11553_INVITE;rport
22:24:22.44 ZGS_SIP: From: <sip:sip329892@sip.example.com>;tag=9fxced2231sl
22:24:22.44 ZGS_SIP: To: <sip:015112345678@sip.example.com>
22:24:22.44 ZGS_SIP: Call-ID: 1346-0-1978-1998d58@csip
22:24:22.44 ZGS_SIP: CSeq: 11553 CANCEL
22:24:22.44 ZGS_SIP: Contact: <sip:sip329892@123.123.123.123:10670;transport=udp>
22:24:22.44 ZGS_SIP: Authorization: XXXXXXXXXXXXX
22:24:22.44 ZGS_SIP: Max-Forwards: 70
22:24:22.44 ZGS_SIP: User-Agent: OpenCom X320 (R 1.576.19.1 mitel-ocx)
22:24:22.44 ZGS_SIP: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY, PRACK
22:24:22.45 ZGS_SIP: Content-Length: 0

Response from Asterisk (481):

22:24:22.51 ZGS_SIP: SIP/2.0 481 Call/Transaction Does Not Exist
22:24:22.51 ZGS_SIP: Via: SIP/2.0/UDP 192.168.96.230:10670;rport=10670;received=123.123.123.123;branch=z9hG4bK11553_INVITE
22:24:22.51 ZGS_SIP: Call-ID: 1346-0-1978-1998d58@csip
22:24:22.51 ZGS_SIP: From: <sip:sip329892@sip.example.com>;tag=9fxced2231sl
22:24:22.51 ZGS_SIP: To: <sip:015112345678@sip.example.com>;tag=z9hG4bK11553_INVITE
22:24:22.52 ZGS_SIP: CSeq: 11553 CANCEL
22:24:22.52 ZGS_SIP: Server: Asterisk PBX 13.10.0
22:24:22.52 ZGS_SIP: Content-Length:  0

I don’t see any mistakes in the CANCEL request. The mitel PBX just finishes the call but the backbone is still calling which results in silence when the call is taken.

I have tested Asterisk 13.8-cert1, cert2 and 13.10 with PJSIP. Problem only occours with mitel PBXs. I just checked with X-Lite and Phoner and both can successfully end the call with CANCEL.

So, what is the problem?

jcolp · August 29, 2016, 9:17pm

Can you also provide the 183 Session Progress?

dumblebee · August 29, 2016, 9:23pm

Sure

22:23:48.24 ZGS_SIP: SIP/2.0 183 Session Progress
22:23:48.24 ZGS_SIP: Via: SIP/2.0/UDP 192.168.96.230:10670;rport=10670;received=123.123.123.123;branch=z9hG4bK11553_INVITE
22:23:48.24 ZGS_SIP: Call-ID: 1346-0-1978-1998d58@csip
22:23:48.24 ZGS_SIP: From: <sip:sip329892@sip.example.com>;tag=9fxced2231sl
22:23:48.25 ZGS_SIP: To: <sip:015112345678@sip.example.com>;tag=037f38c4-b89b-4f2b-bcd4-22261dc180e2
22:23:48.25 ZGS_SIP: CSeq: 11553 INVITE
22:23:48.25 ZGS_SIP: Server: Asterisk PBX 13.10.0
22:23:48.25 ZGS_SIP: Contact: <sip:100.100.100.100:5060>
22:23:48.25 ZGS_SIP: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSA
22:23:48.25 ZGS_SIP: GE, REFER
22:23:48.25 ZGS_SIP: P-Asserted-Identity: <sip:+4915112345678@sip.example.com>
22:23:48.25 ZGS_SIP: Remote-Party-ID: <sip:+4915112345678@sip.example.com>;privacy=off;screen=no
22:23:48.25 ZGS_SIP: Content-Type: application/sdp
22:23:48.25 ZGS_SIP: Content-Length:   613
22:23:48.25 ZGS_SIP: v=0
22:23:48.25 ZGS_SIP: o=- 1472502230 1472502232 IN IP4 100.100.100.100 # Public AST Server IP
22:23:48.25 ZGS_SIP: s=Asterisk
22:23:48.25 ZGS_SIP: c=IN IP4 100.100.100.100
22:23:48.25 ZGS_SIP: t=0 0
22:23:48.25 ZGS_SIP: m=audio 15886 RTP/AVP 8 101
22:23:48.25 ZGS_SIP: a=ice-ufrag:xxxxxxxxxxxxxxx
22:23:48.26 ZGS_SIP: a=ice-pwd:xxxxxxxxxxxxxxx
22:23:48.26 ZGS_SIP: a=candidate:Hb976c494 1 UDP 2130706431 100.100.100.100 15886 typ host
22:23:48.26 ZGS_SIP: a=candidate:Hc0a81e2b 1 UDP 2130706431 192.168.30.43 15886 typ  # Upstream SIP Server
22:23:48.26 ZGS_SIP: a=candidate:Hb976c494 2 UDP 2130706430 100.100.100.100 15887 typ host
22:23:48.26 ZGS_SIP: a=candidate:Hc0a81e2b 2 UDP 2130706430 192.168.30.43 15887 typ host
22:23:48.26 ZGS_SIP: a=rtpmap:8 PCMA/8000
22:23:48.26 ZGS_SIP: a=rtpmap:101 telephone-event/8000
22:23:48.26 ZGS_SIP: a=fmtp:101 0-16
22:23:48.26 ZGS_SIP: a=ptime:20
22:23:48.26 ZGS_SIP: a=maxptime:150
22:23:48.26 ZGS_SIP: a=sendrecv
22:23:48.26 ZGS_SIP: sipte_alert_ind(183) State:9 Callid:681 Trid:CI/0x0116
22:23:48.27 ZGS_SIP: OA_STATE(TX=INVITE_WITH_SDP_LOCAL, RX=IDLE)
22:23:48.27 ZGS_SIP: SIPU_filter_attributes(dont_filter=FALSE), Profil:
22:23:48.27 ZGS_SIP: 0:             PCMA/8000
22:23:48.27 ZGS_SIP: 1:  telephone-event/8000
22:23:48.27 ZGS_SIP: 2:                     ?
22:23:48.27 ZGS_SIP: 3:                     ?
22:23:48.27 ZGS_SIP: 4:                     ?
22:23:48.27 ZGS_SIP: 5:                     ?
22:23:48.27 ZGS_SIP: 6:                     ?
22:23:48.27 ZGS_SIP: 7:                     ?
22:23:48.28 ZGS_SIP: 8:                     ?
22:23:48.28 ZGS_SIP: 9:                     ?
22:23:48.28 ZGS_SIP: vor Filterung:
22:23:48.28 ZGS_SIP:  0:    RM_CODECTYPE_G711A, PT:  8, RTP:(100.100.100.100:15886, sendrecv)
22:23:48.28 ZGS_SIP:  1:  RM_CODECTYPE_RFC4733, PT:101, RTP:(100.100.100.100:15886, sendrecv)
22:23:48.28 ZGS_SIP:  2:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  3:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  4:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  5:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  6:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  7:           PSEUDOCODEC
22:23:48.28 ZGS_SIP:  8:           PSEUDOCODEC
22:23:48.28 ZGS_SIP: nach Filterung:
22:23:48.28 ZGS_SIP:  0:    RM_CODECTYPE_G711A, PT:  8, RTP:(100.100.100.100:15886, sendrecv)
22:23:48.28 ZGS_SIP:  1:  RM_CODECTYPE_RFC4733, PT:101, RTP:(100.100.100.100:15886, sendrecv)
22:23:48.28 ZGS_SIP:  2:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  3:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  4:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  5:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  6:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  7:           PSEUDOCODEC
22:23:48.29 ZGS_SIP:  8:           PSEUDOCODEC
22:23:48.29 ZGS_SIP: rm100_rmid_set_media_data() liefert local_answer=TRUE

jcolp · August 29, 2016, 9:35pm

The issue appears to be that the CANCEL has the wrong branch. It should be “z9hG4bK11552_INVITE” but is “z9hG4bK11553_INVITE” which is causing it to not find the INVITE to cancel it.

From the RFC:
The branch parameter value MUST be unique across space and time for
all requests sent by the UA. The exceptions to this rule are CANCEL
and ACK for non-2xx responses. As discussed below, a CANCEL request
will have the same value of the branch parameter as the request it
cancels.

dumblebee · August 29, 2016, 9:46pm

Oh, I did not spot this difference. I will talk to mitel support for a fix as it seems this is a firmware defect / bug.
Thanks for your help, it would have taken a lot more time for me to notice this!

jcolp · August 29, 2016, 9:48pm

You’re welcome! Good luck.

dumblebee · September 1, 2016, 5:45pm

Hi!

Is there a workaround to skip validation of branch?
I just checked a hand full of hardware appliances (mostly proprietary software) which most of suffer from this bug.

jcolp · September 1, 2016, 6:01pm

There’s nothing in PJSIP to enable to disable checking of this. I also just now noticed that the CSeq value is incorrect. It should be the same as the INVITE as well. Are you sure you aren’t missing traffic from these logs, and that nothing has manipulated the SIP communication in between?

Topic		Replies	Views
PJSIP Transaction Error Asterisk Support	3	599	February 12, 2016
ATA Recieves SIP CANCEL Asterisk Support	5	655	January 6, 2016
Remote host can't match request CANCEL to call Asterisk Support	5	2260	December 18, 2014
Problems callingout from Asterisk Asterisk Support	3	281	August 6, 2015
Asterisk does accept cancel request: 481 Call does not exist Asterisk Support	6	1247	March 1, 2013

PJSIP: Could not find matching INVITE transaction for CANCEL request

Related topics