[asterisk-bugs] [JIRA] (ASTERISK-30011) Testsuite: notify race in resource list subscription

Kevin Harwell (JIRA) noreply at issues.asterisk.org
Mon Apr 4 13:15:57 CDT 2022 

Kevin Harwell created ASTERISK-30011:
----------------------------------------

             Summary: Testsuite: notify race in resource list subscription
                 Key: ASTERISK-30011
                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-30011
             Project: Asterisk
          Issue Type: Bug
      Security Level: None
          Components: Tests/testsuite
    Affects Versions: GIT
            Reporter: Kevin Harwell


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 at 127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp at 127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-3611 at 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 at 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 at 127.0.0.1:5061" version="3" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice at 127.0.0.1:5061">
  <name>alice</name>
  <instance id="ukgvh" state="active" cid="hciuw at 127.0.0.1" />
 </resource>
 <resource uri="sip:bob at 127.0.0.1:5061">
  <name>bob</name>
  <instance id="tprqv" state="active" cid="gupto at 127.0.0.1" />
 </resource>
</list>

--fqkki
Content-ID: <hciuw at 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 at 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 at 127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp at 127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611 at 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 at 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 at 127.0.0.1:5062>;tag=3611SIPpTag001
To: sut <sip:mail_list at 127.0.0.1:5061>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
Call-ID: 1-3611 at 127.0.0.1
CSeq: 24691 SUBSCRIBE
Contact: sip:sipp at 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 at 127.0.0.1
[Mar 29 20:16:24] DEBUG[3548] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:sipp at 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 at 127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp at 127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-3611 at 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 at 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 at 127.0.0.1:5061" version="3" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice at 127.0.0.1:5061">
  <name>alice</name>
  <instance id="ukgvh" state="active" cid="hciuw at 127.0.0.1" />
 </resource>
 <resource uri="sip:bob at 127.0.0.1:5061">
  <name>bob</name>
  <instance id="tprqv" state="active" cid="gupto at 127.0.0.1" />
 </resource>
</list>

--fqkki
Content-ID: <hciuw at 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 at 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.



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

More information about the asterisk-bugs mailing list