[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:43:39 CDT 2018 

Kevin Harwell created ASTERISK-27764:
----------------------------------------

             Summary: 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
         Attachments: ast_restart.tar.gz

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.



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

More information about the asterisk-bugs mailing list