[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:
-------------------------------------
Status: Open (was: Triage)
> 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