Summary: | ASTERISK-27764: res_pjsip_pubsub: possible race condition when refreshing a subscription | ||
Reporter: | Kevin Harwell (kharwell) | Labels: | pjsip |
Date Opened: | 2018-03-22 13:42:13 | Date Closed: | 2018-07-25 06:12:31 |
Priority: | Minor | Regression? | No |
Status: | Closed/Complete | Components: | Resources/res_pjsip_pubsub |
Versions: | 15.3.0 | Frequency of Occurrence | Occasional |
Related Issues: | |||
Environment: | Attachments: | ( 0) ast_restart.tar.gz | |
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@127.0.0.1': while expecting '200' (index 12), received 'NOTIFY sip:alice@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@127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599 To: "alice" <sip:alice@127.0.0.1>;tag=59918SIPpTag001 Contact: <sip:127.0.0.1:5060> Call-ID: 1-59918@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@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@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@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@127.0.0.1:5061>;tag=59918SIPpTag001 To: <sip:alice@127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599 Call-ID: 1-59918@127.0.0.1 CSeq: 2 SUBSCRIBE Contact: "alice" <sip:alice@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@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@127.0.0.1 [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@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@127.0.0.1 From: "alice" <sip:alice@127.0.0.1>;tag=59918SIPpTag001 To: <sip:alice@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@127.0.0.1:5061 [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@127.0.0.1 [Mar 20 08:50:53] DEBUG[59949] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@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@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@127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599 To: "alice" <sip:alice@127.0.0.1>;tag=59918SIPpTag001 Contact: <sip:127.0.0.1:5060> Call-ID: 1-59918@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@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@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@127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599 To: "alice" <sip:alice@127.0.0.1>;tag=59918SIPpTag001 Call-ID: 1-59918@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@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@127.0.0.1:5061>;tag=59918SIPpTag001 To: <sip:alice@127.0.0.1:5060>;tag=741636d3-da2e-45be-9203-d32c96d4d599 Call-ID: 1-59918@127.0.0.1 CSeq: 3 SUBSCRIBE Contact: "alice" <sip:alice@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@127.0.0.1:5061 [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@127.0.0.1 [Mar 20 08:50:53] DEBUG[59948] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@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@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@127.0.0.1>;tag=741636d3-da2e-45be-9203-d32c96d4d599 To: "alice" <sip:alice@127.0.0.1>;tag=59918SIPpTag001 Contact: <sip:127.0.0.1:5060> Call-ID: 1-59918@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@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@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. | ||
Comments: |