pjsua mwi problems: cseq ack problem - patch included

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



This is a patch for a problem I described back in April, but didn't see any 
response.  My previous messages describing the problem are below (including 
packet trace and analysis), after the patch.

I'm not sure the solution is the right one, but it does fix the problem I was 
observing (MWI notifications not calling pjsua's on_mwi_info, due to problems 
low in the sip stack).

The patch is for 1.8.5, but applies cleanly to 1.10.

Patch:

Index: pjproject-1.8.5/pjsip/src/pjsip/sip_transaction.c
===================================================================
--- pjproject-1.8.5/pjsip/src/pjsip/sip_transaction.c    (revision 32446)
+++ pjproject-1.8.5/pjsip/src/pjsip/sip_transaction.c    (revision 32607)
@@ -360,14 +360,15 @@
                                 pj_str_t *key,
                                 pjsip_role_e role,
                                 const pjsip_method *method,
-                                const pj_str_t *branch)
+                                const pj_str_t *branch, 
+                                        int cseq)
 {
     char *p;
 
     PJ_ASSERT_RETURN(pool && key && method && branch, PJ_EINVAL);
 
     p = key->ptr = (char*) 
-               pj_pool_alloc(pool, branch->slen + method->name.slen + 4 );
+               pj_pool_alloc(pool, branch->slen + method->name.slen + 4 + 25 );
     
     /* Add role. */
     *p++ = (char)(role==PJSIP_ROLE_UAC ? 'c' : 's');
@@ -384,6 +385,11 @@
     pj_memcpy(p, branch->ptr, branch->slen);
     p += branch->slen;
 
+    if (0==pj_strcmp2(&method->name, "NOTIFY")) {
+        *p = '-' ;
+        p += pj_utoa((pj_uint32_t)cseq, p) ;
+    }
+
     /* Set length */
     key->slen = p - key->ptr;
 
@@ -412,8 +418,9 @@
 
     if (pj_strncmp(branch,&rfc3261_branch,PJSIP_RFC3261_BRANCH_LEN)==0) {
 
+        int cseq = rdata->msg_info.cseq->cseq ;
     /* Create transaction key. */
-    return create_tsx_key_3261(pool, key, role, method, branch);
+    return create_tsx_key_3261(pool, key, role, method, branch, cseq);
 
     } else {
     /* Create the key for the message. This key will be matched up 
@@ -1277,7 +1284,7 @@
    /* Generate transaction key. */
     create_tsx_key_3261( tsx->pool, &tsx->transaction_key,
              PJSIP_ROLE_UAC, &tsx->method, 
-             &via->branch_param);
+             &via->branch_param, cseq->cseq);
 
     /* Calculate hashed key value. */
 #ifdef PRECALC_HASH






________________________________
From: Matt DiMeo <mattdimeo@xxxxxxxxx>
To: pjsip at lists.pjsip.org
Sent: Thu, April 7, 2011 1:22:44 PM
Subject: Re: pjsua mwi problems: cseq ack problem


Regarding my previous message about problems with incorrect CSeq on responses to 
mwi notify....

I think I've figured out what's going on, but could use advice on how to fix it.

What seems to be happening is that mod-tsx-layer is deciding that the incoming 
notifies are just retransmittals of the previous CSeq, and just resending the 
200 response to the previous notify.

This happens because the branch tag in the via header is the same across 
mulitple NOTIFY messages from the same SUBSCRIBE, so that when mod-tsx-layer 
calls pjsip_tsx_create_key, it comes up with the same value as the previous 
transaction.

mod-tsx-layer then consumes the message, so the message never makes it to 
mod-evsub.

My plan to solve my problem is to change create_tsx_key_3261() such that, when  
the method is NOTIFY, it will include the CSeq id as part of the key string 
created.  I'm not at all sure that that is correct behavior, however.  


Any opinions on this solution?

Thanks in advance,
-m@





________________________________
From: Matt DiMeo <mattdimeo@xxxxxxxxx>
To: pjsip at lists.pjsip.org
Sent: Wed, April 6, 2011 1:58:35 PM
Subject: pjsua mwi problems: cseq ack problem


I'm seeing multiple problems with pjsua MWI handling.  I've looked into where to 
fix it, but got lost in the layers of code and could use suggestions on where to 
focus my debugging.

I've seen this in both 1.8.5 and 1.8.10

Problem 1:  apparently incorrect cseq on ACK of mwi notify

In this problem, the mwi subscription will sometimes get into a state where it 
will send ACKs with an incorrect cseq value, generally a cseq from the previous 
MWI notify.

This state continues (with broken MWI) until some other sip transaction occurs 
(such as a reregistration), which seem to clear the error state.

In the following pjsip output, you'll see
1. notify with cseq 105 (notification of 2/4 new/old voice message) from 
asterisk (10.10.3.77)
2. correct 200 OK response  with cseq 105 from pjsip (10.10.3.150)
3. notify with cseq 106  (1/5 new/old messages)
4. INCORRECT 200 OK response with cseq 105 (should be 106)
5. asterisk retries notify with cseq 106
6. INCORRECT 200 OK response with cseq 105
7.... asterisk retries about six more times, and keeps getting incorrect 
responses.
8. Asterisk eventually gives up retrying.  We never get an on_mwi_info response.

Any suggestions would be very welcome.


 13:44:48.229   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=105 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 105 NOTIFY
User-Agent: Asterisk PBX  (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 2/4 (0/0)

--end msg--
 13:44:48.230   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:   0


--end msg--
 13:44:48.230 evsub0x7f20640  Subscription state changed ACTIVE --> ACTIVE
 13:44:48.230   pjsua_pres.c  MWI subscription for sip:321 at 10.10.3.77 is ACTIVE
 13:44:58.233   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account:  sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:44:58.233   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
 13:44:59.236   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060  SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:44:59.236   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown"  <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
 13:45:00.236   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event:  message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:45:00.236   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end  msg--
 13:45:02.235   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:45:02.235   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP  10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
 13:45:06.236   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To:  <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:45:06.236   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105  NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
 13:45:10.237   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP 10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length:  92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:45:10.237   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
 13:45:14.234   pjsua_core.c  RX 607 bytes Request msg NOTIFY/cseq=106 
(rdata0x7f2064000908) from UDP  10.10.3.77:5060:
NOTIFY sip:321 at 10.10.3.150:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.3.77:5060;branch=z9hG4bK259bf4a5;rport
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150:5060>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
Contact: <sip:unknown at 10.10.3.77>
Call-ID: 4ab61803-46e1-40e1-98be-a78db0194774
CSeq: 106 NOTIFY
User-Agent: Asterisk PBX (digium)
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 92

Messages-Waiting: yes
Message-Account: sip:voicemail at 10.10.3.77
Voice-Message: 1/5 (0/0)

--end msg--
 13:45:14.235   pjsua_core.c  TX 497 bytes Response msg 200/NOTIFY/cseq=105 
(tdta0x7f20640048b0) to UDP 10.10.3.77:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
10.10.3.77:5060;rport=5060;received=10.10.3.77;branch=z9hG4bK259bf4a5
Call-ID:  4ab61803-46e1-40e1-98be-a78db0194774
From: "unknown" <sip:unknown@10.10.3.77>;tag=as6f7c1371
To: <sip:sip:321 at 10.10.3.150>;tag=3b9c5916-6bdb-45d6-b666-15a37784047d
CSeq: 105 NOTIFY
Contact: <sip:321 at 10.10.3.150:5060>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, 
MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Content-Length:  0


--end msg--
^C
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20110707/5803c729/attachment-0001.html>


[Index of Archives]     [Asterisk Users]     [Asterisk App Development]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Security]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [Linux API]
  Powered by Linux