[asterisk-bugs] [JIRA] (ASTERISK-27764) res_pjsip_pubsub: possible race condition when refreshing a subscription

Kevin Harwell (JIRA) noreply at issues.asterisk.org
Thu Mar 22 13:46:39 CDT 2018


     [ https://issues.asterisk.org/jira/browse/ASTERISK-27764?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Kevin Harwell updated ASTERISK-27764:
-------------------------------------

    Description: 
Jenkins occasionally reports the following test failing:

tests/channels/pjsip/subscriptions/ast_restart

{noformat}
Running ['./lib/python/asterisk/test_runner.py', 'tests/channels/pjsip/subscriptions/ast_restart'] ...
[Mar 20 08:50:53] WARNING[59813]: sipp:523 processEnded: Resolving remote host '127.0.0.1'... Done.

[Mar 20 08:50:53] WARNING[59813]: sipp:523 processEnded: 2018-03-20	08:50:53.855930	1521553853.855930: Aborting call on unexpected message for Call-Id '1-59918 at 127.0.0.1': while expecting '200' (index 12), received 'NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Event: presence
Subscription-State: active;expires=599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-58eb7f8403
Content-Type: application/pidf+xml
Content-Length:   498

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
 <note>Ready</note>
 <tuple id="alice">
  <status>
   <basic>open</basic>
  </status>
  <contact priority="1">sip:alice at 127.0.0.1</contact>
 </tuple>
 <tuple id="digium-presence">
  <status>
   <digium_presence type="not_set" />
  </status>
 </tuple>
 <dm:person />
</presence>
'.

[Mar 20 08:50:53] WARNING[59813]: sipp:627 __scenario_callback: SIPp Scenario subscribe.xml Failed [1]

[Mar 20 08:50:53] WARNING[59813]: sipp:636 __evaluate_scenario_results: SIPp Scenario subscribe.xml Failed
{noformat}

It appears that in Asterisk after receiving a subscription refresh a race condition occurs between receiving the NOTIFY's (send out by Asterisk in response to the refresh) 200 OK and re-transmission of that NOTIFY. From the log file:
{noformat}
SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-7
From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
Call-ID: 1-59918 at 127.0.0.1
CSeq: 2 SUBSCRIBE
Contact: "alice" <sip:alice at 127.0.0.1:5061>
Expires: 600
Max-Forwards: 70
Event: presence
Accept: application/pidf+xml
User-Agent: Digium D40
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=2 (rdata0x7f5ce800cd98)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Cancelling timer: alice->alice/presence 1-59918 at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
[Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP response (542 bytes) to UDP:127.0.0.1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5061;rport=5061;received=127.0.0.1;branch=z9hG4bK-59918-1-7
Call-ID: 1-59918 at 127.0.0.1
From: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
CSeq: 2 SUBSCRIBE
Expires: 600
Contact: <sip:127.0.0.1:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX GIT-15-58eb7f8403
Content-Length:  0


[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
[Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Event: presence
Subscription-State: active;expires=599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-58eb7f8403
Content-Type: application/pidf+xml
Content-Length:   498

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
 <note>Ready</note>
 <tuple id="alice">
  <status>
   <basic>open</basic>
  </status>
  <contact priority="1">sip:alice at 127.0.0.1</contact>
 </tuple>
 <tuple id="digium-presence">
  <status>
   <digium_presence type="not_set" />
  </status>
 </tuple>
 <dm:person />
</presence>

[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 state ACTIVE event USER sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP response (347 bytes) from UDP:127.0.0.1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Contact: <sip:127.0.0.1:5061;transport=UDP>
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Response msg 200/NOTIFY/cseq=11552 (rdata0x7f5ce80214b8)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP request (452 bytes) from UDP:127.0.0.1:5061 --->
SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-11
From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
Call-ID: 1-59918 at 127.0.0.1
CSeq: 3 SUBSCRIBE
Contact: "alice" <sip:alice at 127.0.0.1:5061>
Expires: 0
Max-Forwards: 70
Event: presence
Accept: application/pidf+xml
User-Agent: Digium D40
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=3 (rdata0x7f5ce8035508)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Event: presence
Subscription-State: active;expires=599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-58eb7f8403
Content-Type: application/pidf+xml
Content-Length:   498

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
 <note>Ready</note>
 <tuple id="alice">
  <status>
   <basic>open</basic>
  </status>
  <contact priority="1">sip:alice at 127.0.0.1</contact>
 </tuple>
 <tuple id="digium-presence">
  <status>
   <digium_presence type="not_set" />
  </status>
 </tuple>
 <dm:person />
</presence>
{noformat}
Here you can see the NOTIFY goes out, a 200 OK is immediately received for it, but then the message is re-transmitted again.

  was:
Jenkins occasionally reports the following test failing:

tests/channels/pjsip/subscriptions/ast_restart

It appears that in Asterisk after receiving a subscription refresh a race condition occurs between receiving the NOTIFY's (send out by Asterisk in response to the refresh) 200 OK and re-transmission of that NOTIFY. From the log file:
{noformat}
SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-7
From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
Call-ID: 1-59918 at 127.0.0.1
CSeq: 2 SUBSCRIBE
Contact: "alice" <sip:alice at 127.0.0.1:5061>
Expires: 600
Max-Forwards: 70
Event: presence
Accept: application/pidf+xml
User-Agent: Digium D40
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=2 (rdata0x7f5ce800cd98)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Cancelling timer: alice->alice/presence 1-59918 at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
[Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP response (542 bytes) to UDP:127.0.0.1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5061;rport=5061;received=127.0.0.1;branch=z9hG4bK-59918-1-7
Call-ID: 1-59918 at 127.0.0.1
From: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
CSeq: 2 SUBSCRIBE
Expires: 600
Contact: <sip:127.0.0.1:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX GIT-15-58eb7f8403
Content-Length:  0


[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
[Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Event: presence
Subscription-State: active;expires=599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-58eb7f8403
Content-Type: application/pidf+xml
Content-Length:   498

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
 <note>Ready</note>
 <tuple id="alice">
  <status>
   <basic>open</basic>
  </status>
  <contact priority="1">sip:alice at 127.0.0.1</contact>
 </tuple>
 <tuple id="digium-presence">
  <status>
   <digium_presence type="not_set" />
  </status>
 </tuple>
 <dm:person />
</presence>

[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 state ACTIVE event USER sub_tree 0x7f5c800150a8 sub_tree state Normal
[Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP response (347 bytes) from UDP:127.0.0.1:5061 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Contact: <sip:127.0.0.1:5061;transport=UDP>
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Response msg 200/NOTIFY/cseq=11552 (rdata0x7f5ce80214b8)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP request (452 bytes) from UDP:127.0.0.1:5061 --->
SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-11
From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
Call-ID: 1-59918 at 127.0.0.1
CSeq: 3 SUBSCRIBE
Contact: "alice" <sip:alice at 127.0.0.1:5061>
Expires: 0
Max-Forwards: 70
Event: presence
Accept: application/pidf+xml
User-Agent: Digium D40
Content-Length: 0


[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=3 (rdata0x7f5ce8035508)
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
[Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
[Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-59918 at 127.0.0.1
CSeq: 11552 NOTIFY
Event: presence
Subscription-State: active;expires=599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-58eb7f8403
Content-Type: application/pidf+xml
Content-Length:   498

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
 <note>Ready</note>
 <tuple id="alice">
  <status>
   <basic>open</basic>
  </status>
  <contact priority="1">sip:alice at 127.0.0.1</contact>
 </tuple>
 <tuple id="digium-presence">
  <status>
   <digium_presence type="not_set" />
  </status>
 </tuple>
 <dm:person />
</presence>
{noformat}
Here you can see the NOTIFY goes out, a 200 OK is immediately received for it, but then the message is re-transmitted again.


> res_pjsip_pubsub: possible race condition when refreshing a subscription
> ------------------------------------------------------------------------
>
>                 Key: ASTERISK-27764
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27764
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Resources/res_pjsip_pubsub
>    Affects Versions: 15.3.0
>            Reporter: Kevin Harwell
>            Severity: Minor
>              Labels: pjsip
>         Attachments: ast_restart.tar.gz
>
>
> Jenkins occasionally reports the following test failing:
> tests/channels/pjsip/subscriptions/ast_restart
> {noformat}
> Running ['./lib/python/asterisk/test_runner.py', 'tests/channels/pjsip/subscriptions/ast_restart'] ...
> [Mar 20 08:50:53] WARNING[59813]: sipp:523 processEnded: Resolving remote host '127.0.0.1'... Done.
> [Mar 20 08:50:53] WARNING[59813]: sipp:523 processEnded: 2018-03-20	08:50:53.855930	1521553853.855930: Aborting call on unexpected message for Call-Id '1-59918 at 127.0.0.1': while expecting '200' (index 12), received 'NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
> Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
> From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
> Contact: <sip:127.0.0.1:5060>
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 11552 NOTIFY
> Event: presence
> Subscription-State: active;expires=599
> Allow-Events: message-summary, presence, dialog, refer
> Max-Forwards: 70
> User-Agent: Asterisk PBX GIT-15-58eb7f8403
> Content-Type: application/pidf+xml
> Content-Length:   498
> <?xml version="1.0" encoding="UTF-8"?>
> <presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
>  <note>Ready</note>
>  <tuple id="alice">
>   <status>
>    <basic>open</basic>
>   </status>
>   <contact priority="1">sip:alice at 127.0.0.1</contact>
>  </tuple>
>  <tuple id="digium-presence">
>   <status>
>    <digium_presence type="not_set" />
>   </status>
>  </tuple>
>  <dm:person />
> </presence>
> '.
> [Mar 20 08:50:53] WARNING[59813]: sipp:627 __scenario_callback: SIPp Scenario subscribe.xml Failed [1]
> [Mar 20 08:50:53] WARNING[59813]: sipp:636 __evaluate_scenario_results: SIPp Scenario subscribe.xml Failed
> {noformat}
> It appears that in Asterisk after receiving a subscription refresh a race condition occurs between receiving the NOTIFY's (send out by Asterisk in response to the refresh) 200 OK and re-transmission of that NOTIFY. From the log file:
> {noformat}
> SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
> Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-7
> From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
> To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 2 SUBSCRIBE
> Contact: "alice" <sip:alice at 127.0.0.1:5061>
> Expires: 600
> Max-Forwards: 70
> Event: presence
> Accept: application/pidf+xml
> User-Agent: Digium D40
> Content-Length: 0
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=2 (rdata0x7f5ce800cd98)
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 sub_tree 0x7f5c800150a8 sub_tree state Normal
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Cancelling timer: alice->alice/presence 1-59918 at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
> [Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP response (542 bytes) to UDP:127.0.0.1:5061 --->
> SIP/2.0 200 OK
> Via: SIP/2.0/UDP 127.0.0.1:5061;rport=5061;received=127.0.0.1;branch=z9hG4bK-59918-1-7
> Call-ID: 1-59918 at 127.0.0.1
> From: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
> To: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> CSeq: 2 SUBSCRIBE
> Expires: 600
> Contact: <sip:127.0.0.1:5060>
> Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
> Supported: 100rel, timer, replaces, norefersub
> Server: Asterisk PBX GIT-15-58eb7f8403
> Content-Length:  0
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: sub_tree 0x7f5c800150a8 sub_tree state Normal
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:10.19.137.219:5060
> [Mar 20 08:50:53] VERBOSE[59949] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
> NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
> Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
> From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
> Contact: <sip:127.0.0.1:5060>
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 11552 NOTIFY
> Event: presence
> Subscription-State: active;expires=599
> Allow-Events: message-summary, presence, dialog, refer
> Max-Forwards: 70
> User-Agent: Asterisk PBX GIT-15-58eb7f8403
> Content-Type: application/pidf+xml
> Content-Length:   498
> <?xml version="1.0" encoding="UTF-8"?>
> <presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
>  <note>Ready</note>
>  <tuple id="alice">
>   <status>
>    <basic>open</basic>
>   </status>
>   <contact priority="1">sip:alice at 127.0.0.1</contact>
>  </tuple>
>  <tuple id="digium-presence">
>   <status>
>    <digium_presence type="not_set" />
>   </status>
>  </tuple>
>  <dm:person />
> </presence>
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: evsub 0x7f5c80018d08 state ACTIVE event USER sub_tree 0x7f5c800150a8 sub_tree state Normal
> [Mar 20 08:50:53] DEBUG[59949] res_pjsip_pubsub.c: Updating persistence for 'alice->alice'  prune on restart: no
> [Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP response (347 bytes) from UDP:127.0.0.1:5061 --->
> SIP/2.0 200 OK
> Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
> From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 11552 NOTIFY
> Contact: <sip:127.0.0.1:5061;transport=UDP>
> Content-Length: 0
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Response msg 200/NOTIFY/cseq=11552 (rdata0x7f5ce80214b8)
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
> [Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Received SIP request (452 bytes) from UDP:127.0.0.1:5061 --->
> SUBSCRIBE sip:alice at 127.0.0.1:5060 SIP/2.0
> Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-59918-1-11
> From: "alice" <sip:alice at 127.0.0.1:5061>;tag=59918SIPpTag001
> To: <sip:alice at 127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 3 SUBSCRIBE
> Contact: "alice" <sip:alice at 127.0.0.1:5061>
> Expires: 0
> Max-Forwards: 70
> Event: presence
> Accept: application/pidf+xml
> User-Agent: Digium D40
> Content-Length: 0
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f5c800167e8 for Request msg SUBSCRIBE/cseq=3 (rdata0x7f5ce8035508)
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000001d associated with dialog dlg0x7f5c800167e8
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice at 127.0.0.1:5061
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 127.0.0.1
> [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
> [Mar 20 08:50:53] VERBOSE[59948] res_pjsip_logger.c: <--- Transmitting SIP request (1071 bytes) to UDP:127.0.0.1:5061 --->
> NOTIFY sip:alice at 127.0.0.1:5061 SIP/2.0
> Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPja3d81bf0-73e3-40de-a443-a4890a8a8e5b
> From: <sip:alice at 127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599
> To: "alice" <sip:alice at 127.0.0.1>;tag=59918SIPpTag001
> Contact: <sip:127.0.0.1:5060>
> Call-ID: 1-59918 at 127.0.0.1
> CSeq: 11552 NOTIFY
> Event: presence
> Subscription-State: active;expires=599
> Allow-Events: message-summary, presence, dialog, refer
> Max-Forwards: 70
> User-Agent: Asterisk PBX GIT-15-58eb7f8403
> Content-Type: application/pidf+xml
> Content-Length:   498
> <?xml version="1.0" encoding="UTF-8"?>
> <presence entity="sip:alice at 10.19.137.219:5060" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
>  <note>Ready</note>
>  <tuple id="alice">
>   <status>
>    <basic>open</basic>
>   </status>
>   <contact priority="1">sip:alice at 127.0.0.1</contact>
>  </tuple>
>  <tuple id="digium-presence">
>   <status>
>    <digium_presence type="not_set" />
>   </status>
>  </tuple>
>  <dm:person />
> </presence>
> {noformat}
> Here you can see the NOTIFY goes out, a 200 OK is immediately received for it, but then the message is re-transmitted again.



--
This message was sent by Atlassian JIRA
(v6.2#6252)



More information about the asterisk-bugs mailing list