[Home]

Summary:ASTERISK-27765: res_pjsip_pubsub/exten_state: two state change result in one presence notification
Reporter:Kevin Harwell (kharwell)Labels:pjsip
Date Opened:2018-03-22 15:15:17Date Closed:2018-07-25 06:12:10
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_pjsip_exten_state Resources/res_pjsip_pubsub
Versions:13.20.0 15.3.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Attachments:( 0) presencestate_repeat_okay.tar.gz
Description:Jenkins occasionally reports the following test failure (note test is failing in both 13 and 15):
{noformat}
Running ['./lib/python/asterisk/test_runner.py', 'tests/channels/pjsip/subscriptions/presence/presencestate_repeat_okay'] ...
[Mar 20 11:07:22] WARNING[21265]: test_case:531 _reactor_timeout: Reactor timeout: '30' seconds

[Mar 20 11:07:22] WARNING[21265]: sipp:488 kill: Killing SIPp Scenario subscribe.xml

[Mar 20 11:07:22] ERROR[21265]: test_case:676 evaluate_results: Fail token present: Reactor timed out. Test Failed.
{noformat}
Not terribly helpful, but it indicates the test was probably waiting for something like a SIP message. And that's the case here. From the log file:
{noformat}
Event: PresenceStateChange
Privilege: call,all
Presentity: CustomPresence:Eggs
Status: away
Subtype: scrambled
Message: feeling a bit sick


[Mar 20 11:06:52] DEBUG[21371] manager.c: Examining AMI event:
Event: PresenceStatus
Privilege: call,all
Exten: presence
Context: default
Hint: ,CustomPresence:Eggs
Status: away
Subtype: scrambled
Message: feeling a bit sick


[Mar 20 11:06:52] VERBOSE[21307] res_pjsip_logger.c: <--- Received SIP request (431 bytes) from UDP:127.0.0.1:5061 --->
SUBSCRIBE sip:presence@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-21374-1-0
From: "alice" <sip:alice@127.0.0.1:5061>;tag=21374SIPpTag001
To: <sip:presence@127.0.0.1:5060>
Call-ID: 1-21374@127.0.0.1
CSeq: 1 SUBSCRIBE
Contact: "alice" <sip:alice@127.0.0.1:5061>
Expires: 3600
Max-Forwards: 70
Event: presence
Accept: application/pidf+xml
User-Agent: Digium Sandwich Spigot
Content-Length: 0


[Mar 20 11:06:52] DEBUG[21307] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=1 (rdata0x3bd1898)
[Mar 20 11:06:52] DEBUG[21307] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg SUBSCRIBE/cseq=1 (rdata0x3bd1898)
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'alice' domain '127.0.0.1'
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_endpoint_identifier_user.c: Identified by From username 'alice' domain '127.0.0.1'
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_pubsub.c: Body generator 0x7efec78a7160 found for accept type application/pidf+xml
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_pubsub.c: Subscription 'alice->presence' is not to a list
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg SUBSCRIBE/cseq=1 (rdata0x7eff780039e8)
[Mar 20 11:06:52] DEBUG[21308] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 20 11:06:52] DEBUG[21308] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 20 11:06:52] DEBUG[21308] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 20 11:06:52] DEBUG[21308] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Mar 20 11:06:52] DEBUG[21371] manager.c: Running action 'Setvar'
[Mar 20 11:06:52] DEBUG[21308] res_pjsip_pubsub.c: Updating persistence for 'alice->presence'  prune on restart: no
[Mar 20 11:06:52] DEBUG[21371] manager.c: Running action 'Setvar'
[Mar 20 11:06:52] DEBUG[21371] manager.c: Examining AMI event:
Event: PresenceStatus
Privilege: call,all
Exten: presence
Context: default
Hint: ,CustomPresence:Eggs
Status: away
Subtype: poached
Message: feeling a bit sick


[Mar 20 11:06:52] DEBUG[21371] manager.c: Examining AMI event:
Event: PresenceStateChange
Privilege: call,all
Presentity: CustomPresence:Eggs
Status: away
Subtype: poached
Message: feeling a bit sick


[Mar 20 11:06:52] DEBUG[21371] manager.c: Examining AMI event:
Event: PresenceStatus
Privilege: call,all
Exten: presence
Context: default
Hint: ,CustomPresence:Eggs
Status: away
Subtype: poached
Message: the horses could not put me back together


[Mar 20 11:06:52] DEBUG[21371] manager.c: Examining AMI event:
Event: PresenceStateChange
Privilege: call,all
Presentity: CustomPresence:Eggs
Status: away
Subtype: poached
Message: the horses could not put me back together


[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:presence@127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
[Mar 20 11:06:52] VERBOSE[21308] res_pjsip_logger.c: <--- Transmitting SIP response (543 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-21374-1-0
Call-ID: 1-21374@127.0.0.1
From: "alice" <sip:alice@127.0.0.1>;tag=21374SIPpTag001
To: <sip:presence@127.0.0.1>;tag=ad48aa3b-2e73-4728-be78-20f87ecba4d0
CSeq: 1 SUBSCRIBE
Expires: 3600
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-82bdc8a
Content-Length:  0


[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '127.0.0.1'
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_resolver.c: Transport type for target '127.0.0.1' is 'UDP'
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_resolver.c: Target '127.0.0.1' is an IP address, skipping resolution
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing Request: sip:alice@127.0.0.1:5061
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:presence@127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice@127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing Contact header: sip:127.0.0.1:5060
[Mar 20 11:06:52] VERBOSE[21308] res_pjsip_logger.c: <--- Transmitting SIP request (1154 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=z9hG4bKPje6d41c7a-da72-4048-bff8-69c596052ee2
From: <sip:presence@127.0.0.1>;tag=ad48aa3b-2e73-4728-be78-20f87ecba4d0
To: "alice" <sip:alice@127.0.0.1>;tag=21374SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-21374@127.0.0.1
CSeq: 15744 NOTIFY
Event: presence
Subscription-State: active;expires=3599
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: Asterisk PBX GIT-15-82bdc8a
Content-Type: application/pidf+xml
Content-Length:   580

<?xml version="1.0" encoding="UTF-8"?>
<presence entity="sip:presence@127.0.0.1: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>Unavailable</note>
<tuple id="presence">
 <status>
  <basic>closed</basic>
 </status>
 <contact priority="1">sip:alice@127.0.0.1</contact>
</tuple>
<tuple id="digium-presence">
 <status>
  <digium_presence type="away" subtype="poached">the horses could not put me back together</digium_presence>
 </status>
</tuple>
<dm:person />
</presence>
{noformat}
The test initializes the presence state correctly and subscribes. The test then expects NOTIFY's associated with two state changes. In the log you can see the two state change events, but only the one NOTIFY being sent out (the second one).

It appears if two state changes happen in quick enough succession only the second notification of the change is sent out.
Comments: