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 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/20110407/9d664de1/attachment-0001.html>
