[asterisk-bugs] [JIRA] (ASTERISK-27765) res_pjsip_pubsub/exten_state: two state change result in one presence notification
Kevin Harwell (JIRA)
noreply at issues.asterisk.org
Thu Mar 22 15:15:39 CDT 2018
Kevin Harwell created ASTERISK-27765:
----------------------------------------
Summary: res_pjsip_pubsub/exten_state: two state change result in one presence notification
Key: ASTERISK-27765
URL: https://issues.asterisk.org/jira/browse/ASTERISK-27765
Project: Asterisk
Issue Type: Bug
Security Level: None
Components: Resources/res_pjsip_exten_state, Resources/res_pjsip_pubsub
Affects Versions: 15.3.0, 13.20.0
Reporter: Kevin Harwell
Severity: Minor
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 at 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 at 127.0.0.1:5061>;tag=21374SIPpTag001
To: <sip:presence at 127.0.0.1:5060>
Call-ID: 1-21374 at 127.0.0.1
CSeq: 1 SUBSCRIBE
Contact: "alice" <sip:alice at 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 at 127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:presence at 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 at 127.0.0.1
From: "alice" <sip:alice at 127.0.0.1>;tag=21374SIPpTag001
To: <sip:presence at 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 at 127.0.0.1:5061
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:presence at 127.0.0.1
[Mar 20 11:06:52] DEBUG[21308] res_pjsip/pjsip_message_filter.c: Sanitizing From/To header: sip:alice at 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 at 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 at 127.0.0.1>;tag=ad48aa3b-2e73-4728-be78-20f87ecba4d0
To: "alice" <sip:alice at 127.0.0.1>;tag=21374SIPpTag001
Contact: <sip:127.0.0.1:5060>
Call-ID: 1-21374 at 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 at 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 at 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.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list