[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
[ https://issues.asterisk.org/jira/browse/ASTERISK-27765?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kevin Harwell updated ASTERISK-27765:
-------------------------------------
Attachment: presencestate_repeat_okay.tar.gz
> 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: 13.20.0, 15.3.0
> Reporter: Kevin Harwell
> Severity: Minor
> Labels: pjsip
> Attachments: presencestate_repeat_okay.tar.gz
>
>
> 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