[asterisk-bugs] [JIRA] (ASTERISK-26708) ARI interface does not correctly indicate de-registrations

Mon Jan 9 08:02:10 CST 2017

    [ https://issues.asterisk.org/jira/browse/ASTERISK-26708?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=234525#comment-234525 ] 

Asterisk Team commented on ASTERISK-26708:
------------------------------------------

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

> ARI interface does not correctly indicate de-registrations
> ----------------------------------------------------------
>
>                 Key: ASTERISK-26708
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-26708
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_pjsip
>    Affects Versions: 14.0.0
>         Environment: Debian GNU/Linux stretch
>            Reporter: Andreas Rottmann
>
> When a SIP user agent deregisters from Asterisk, the event that is sent out via ARI does *not* indicate that the endpoint is no longer available, in fact, it is undistinguishable from the event that is sent out when a UA registers. 
> This is a real issue when multiple endpoints are connected to a single peer, as it is no longer possible to reliably detect de-registrations. If there is only a single endpoint, one can work around the issue by processing the 
> {{PeerStatusChange}} message.
> More specifically, the endpoint is indicated as "online", even though the event is published during de-registration. The CLI log (correctly) notes the endpoint as unreachable.
> The following logs are taken with the following sequence of actions:
> - Asterisk running with a CLI console. No endpoints are registered.
> - A single endpoint is registered, and de-registered again. I'm using pjsua as user agent here.
> - wscat is registered as a "Stasis Application".
> The following output shows that, upon deregistration, ARI reports "contact_status" being "online" in the {{ContactStatus}} message. The following {{PeerStatusChange}} seems OK ("offline"), but this is not suitable for tracking individual endpoints.
> {noformat}
> % wscat -c 'ws://stretch-amd64-dev:8088/ari/events?api_key=asterisk:secret&app=rotty&subscribeAll=true'
> < {"type":"ContactStatusChange","timestamp":"2017-01-09T12:07:20.089+0000","endpoint":{"technology":"PJSIP","resource":"rotty01","state":"offline","channel_ids":[]},"contact_info":{"uri":"sip:rotty01 at 10.200.0.10:5060","contact_status":"Created","aor":"rotty01","roundtrip_usec":"0"},"asterisk_id":"00:16:3e:08:f0:11","application":"rotty"}
> < {"type":"PeerStatusChange","timestamp":"2017-01-09T12:07:20.116+0000","endpoint":{"technology":"PJSIP","resource":"rotty01","state":"online","channel_ids":[]},"peer":{"peer_status":"Reachable"},"asterisk_id":"00:16:3e:08:f0:11","application":"rotty"}
> < {"type":"DeviceStateChanged","application":"rotty","timestamp":"2017-01-09T12:07:20.117+0000","device_state":{"name":"PJSIP/rotty01","state":"NOT_INUSE"},"asterisk_id":"00:16:3e:08:f0:11"}
> < {"type":"ContactStatusChange","timestamp":"2017-01-09T12:07:20.121+0000","endpoint":{"technology":"PJSIP","resource":"rotty01","state":"online","channel_ids":[]},"contact_info":{"uri":"sip:rotty01 at 10.200.0.10:5060","contact_status":"Reachable","aor":"rotty01","roundtrip_usec":"3921"},"asterisk_id":"00:16:3e:08:f0:11","application":"rotty"}
> [---- client disconnects here ----]
> < {"type":"ContactStatusChange","timestamp":"2017-01-09T12:07:30.219+0000","endpoint":{"technology":"PJSIP","resource":"rotty01","state":"online","channel_ids":[]},"contact_info":{"uri":"sip:rotty01 at 10.200.0.10:5060","contact_status":"Reachable","aor":"rotty01","roundtrip_usec":"3921"},"asterisk_id":"00:16:3e:08:f0:11","application":"rotty"}
> < {"type":"PeerStatusChange","timestamp":"2017-01-09T12:07:30.247+0000","endpoint":{"technology":"PJSIP","resource":"rotty01","state":"offline","channel_ids":[]},"peer":{"peer_status":"Unreachable"},"asterisk_id":"00:16:3e:08:f0:11","application":"rotty"}
> < {"type":"DeviceStateChanged","application":"rotty","timestamp":"2017-01-09T12:07:30.247+0000","device_state":{"name":"PJSIP/rotty01","state":"UNAVAILABLE"},"asterisk_id":"00:16:3e:08:f0:11"}
> {noformat}
> The CLI output, as mentioned, looks reasonable:
> {noformat}
>   == Contact rotty01/sip:rotty01 at 10.200.0.10:5060 has been created
>   == Endpoint rotty01 is now Reachable
>   == Contact rotty01/sip:rotty01 at 10.200.0.10:5060 has been deleted
>   == Endpoint rotty01 is now Unreachable
> {noformat}
> I've started digging into this in the Asterisk codebase; I'll summarize what I've gathered so far. The following is to be taken with several grains of salt, as this is the first serious look I took into the Asterisk code.
> - Asterisk does not send the event with the proper contact status; the contact is indicated as "reachable". It does not seem the endpoint status is even updated during deregistration (verified by inserting a debug message into {{update_contact_status()}} in {{res/res_pjsip/pjsip_options.c}}.
> - During deregistration {{persistent_endpoint_contact_deleted_observer()}} in {{res/res_pjsip/pjsip_configuration.c}} is invoked, which seems to be responsible for pushing the update out. However, {{contact_status->status}} is {{AVAILABLE}} at that point.
> - Backtrace from {{contactstatus_to_json()}}, which emits the faulty event (line numbers may be off due to debugging statements I inserted in the code).
> {noformat}
> #0  contactstatus_to_json (msg=0x7fca28008d98, sanitize=0x7fca4e3358f0 <app_sanitizer>) at stasis_endpoints.c:253
> #1  0x00005555b6b092a3 in stasis_message_to_json (msg=0x7fca28008d98, sanitize=0x7fca4e3358f0 <app_sanitizer>) at stasis_message.c:195
> #2  0x00007fca4e123467 in sub_default_handler (data=0x7fc9d8001b38, sub=0x7fc9d8002508, message=0x7fca28008d98) at stasis/app.c:348
> #3  0x00005555b6b09a1e in router_dispatch (data=0x7fc9d8002458, sub=0x7fc9d8002508, message=0x7fca28008d98) at stasis_message_router.c:201
> #4  0x00005555b6af4644 in subscription_invoke (sub=0x7fc9d8002508, message=0x7fca28008d98) at stasis.c:434
> #5  0x00005555b6af544d in dispatch_exec_async (local=0x7fc9e4c44c20) at stasis.c:715
> #6  0x00005555b6b1729f in ast_taskprocessor_execute (tps=0x7fc9d8002668) at taskprocessor.c:965
> #7  0x00005555b6b1519f in default_tps_processing_function (data=0x7fc9d80025e8) at taskprocessor.c:185
> #8  0x00005555b6b2dbf3 in dummy_start (data=0x7fc9d8002750) at utils.c:1230
> #9  0x00007fcadd752464 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
> #10 0x00007fcadc35e9df in clone () from /lib/x86_64-linux-gnu/libc.so.6
> {noformat}
> The contact needs to be updated during de-registration, but exactly how is not clear to me. I'm aware it's almost certainly wrong to just change the {{status}} field, both due to the multithreaded nature of Asterisk and from an architectural standpoint.
> The {{update_contact_status()}}  in {{res_pjsip/pjsip_options.c}} function seems to perform the update, but:
> - The function is in another file, marked as {{static}}.
> - It is not clear if the way that function performs the update is applicable in the context of de-registration.

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