[Home]

Summary:ASTERISK-30011: Testsuite: notify race in resource list subscription
Reporter:Kevin Harwell (kharwell)Labels:
Date Opened:2022-04-04 13:14:42Date Closed:
Priority:MinorRegression?No
Status:Open/NewComponents:Tests/testsuite
Versions:GIT Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Attachments:( 0) archive.zip
( 1) full-asterisk.txt
( 2) full-test.txt
Description:Jenkins logged a failure for the following test:

{{tests/channels/pjsip/subscriptions/rls/lists/nominal/mwi/batched/multiple_resources_single_change}}

Based on the logs it appears Asterisk sent a re-transmission of a NOTIFY after receiving the 200 OK for it.
{noformat}
[Mar 29 20:16:23] VERBOSE[3549] res_pjsip_logger.c: <--- Transmitting SIP request (1545 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8
From: "sut" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-3611@127.0.0.1
CSeq: 24690 NOTIFY
Event: message-summary
Subscription-State: active;expires=3594
Allow-Events: presence, dialog, message-summary, refer
Require: eventlist
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-master-df22e5e
Content-Type: multipart/related;type="application/rlmi+xml";boundary=fqkki
Content-Length:   903


--fqkki
Content-ID: <baxee@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="3" fullState="false">
<name>mail_list</name>
<resource uri="sip:alice@127.0.0.1:5061">
 <name>alice</name>
 <instance id="ukgvh" state="active" cid="hciuw@127.0.0.1" />
</resource>
<resource uri="sip:bob@127.0.0.1:5061">
 <name>bob</name>
 <instance id="tprqv" state="active" cid="gupto@127.0.0.1" />
</resource>
</list>

--fqkki
Content-ID: <hciuw@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki
Content-ID: <gupto@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki--

[Mar 29 20:16:23] DEBUG[3549] res_pjsip_pubsub.c: evsub 0x7f8a2c003578 state ACTIVE event USER sub_tree 0x7f8a2c00cdd0 sub_tree state Normal
[Mar 29 20:16:23] DEBUG[3549] res_pjsip_pubsub.c: Updating persistence for 'sipp->mail_list'  prune on boot: no
[Mar 29 20:16:23] VERBOSE[3548] res_pjsip_logger.c: <--- Received SIP response (353 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=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8
From: "sut" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq: 24690 NOTIFY
Contact: <sip:127.0.0.1:5062;transport=UDP>
Content-Length: 0


[Mar 29 20:16:23] DEBUG[3548] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8a2c006c48 for Response msg 200/NOTIFY/cseq=24690 (rdata0x7f8a100a66f8)
[Mar 29 20:16:23] DEBUG[3548] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002c associated with dialog dlg0x7f8a2c006c48
[Mar 29 20:16:23] VERBOSE[3548] res_pjsip_logger.c: <--- Received SIP request (553 bytes) from UDP:127.0.0.1:5061 --->
SUBSCRIBE sip:mail_list@127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-3611-1-13
From: sipp <sip:sipp@127.0.0.1:5062>;tag=3611SIPpTag001
To: sut <sip:mail_list@127.0.0.1:5061>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
Call-ID: 1-3611@127.0.0.1
CSeq: 24691 SUBSCRIBE
Contact: sip:sipp@127.0.0.1:5062
Max-Forwards: 70
Subject: Performance Test
Event: message-summary
Supported: eventlist
Accept: application/rlmi+xml
Accept: application/simple-message-summary
Accept: multipart/related
Expires: 0
Content-Length: 0


[Mar 29 20:16:23] DEBUG[3548] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f8a2c006c48 for Request msg SUBSCRIBE/cseq=24691 (rdata0x7f8a100cbd08)
[Mar 29 20:16:23] DEBUG[3548] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002c associated with dialog dlg0x7f8a2c006c48
[Mar 29 20:16:24] DEBUG[3548] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:127.0.0.1:5061
[Mar 29 20:16:24] DEBUG[3548] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:mail_list@127.0.0.1
[Mar 29 20:16:24] DEBUG[3548] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:sipp@127.0.0.1
[Mar 29 20:16:24] DEBUG[3548] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
[Mar 29 20:16:24] VERBOSE[3548] res_pjsip_logger.c: <--- Transmitting SIP request (1545 bytes) to UDP:127.0.0.1:5061 --->
NOTIFY sip:127.0.0.1:5061 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8
From: "sut" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-3611@127.0.0.1
CSeq: 24690 NOTIFY
Event: message-summary
Subscription-State: active;expires=3594
Allow-Events: presence, dialog, message-summary, refer
Require: eventlist
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-master-df22e5e
Content-Type: multipart/related;type="application/rlmi+xml";boundary=fqkki
Content-Length:   903


--fqkki
Content-ID: <baxee@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="3" fullState="false">
<name>mail_list</name>
<resource uri="sip:alice@127.0.0.1:5061">
 <name>alice</name>
 <instance id="ukgvh" state="active" cid="hciuw@127.0.0.1" />
</resource>
<resource uri="sip:bob@127.0.0.1:5061">
 <name>bob</name>
 <instance id="tprqv" state="active" cid="gupto@127.0.0.1" />
</resource>
</list>

--fqkki
Content-ID: <hciuw@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki
Content-ID: <gupto@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki--
{noformat}
It could be the re-transmission timer is not being canceled in time.
Comments: