Summary:	ASTERISK-26708: res_pjsip: ARI interface does not correctly indicate de-registrations
Reporter:	Andreas Rottmann (rotty)	Labels:
Date Opened:	2017-01-09 08:00:52.000-0600	Date Closed:
Priority:	Major	Regression?
Status:	Open/New	Components:	Channels/chan_pjsip Resources/res_pjsip
Versions:	14.0.0 14.2.1	Frequency of Occurrence	Constant
Related Issues:
Environment:	Debian GNU/Linux stretch	Attachments:
Description:	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@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@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@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@10.200.0.10:5060 has been created  == Endpoint rotty01 is now Reachable  == Contact rotty01/sip:rotty01@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.
Comments:	By: Asterisk Team (asteriskteam) 2017-01-09 08:00:53.097-0600 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].