Summary:	ASTERISK-25811: Unable to delete object from sorcery cache
Reporter:	Ross Beer (rossbeer)	Labels:
Date Opened:	2016-02-25 09:28:56.000-0600	Date Closed:	2016-02-29 13:18:23.000-0600
Priority:	Major	Regression?
Status:	Closed/Complete	Components:	Core/Sorcery
Versions:	13.7.2	Frequency of Occurrence	Constant
Related Issues:
Environment:	Centos 7	Attachments:
Description:	Sorcery cache throws an error on unregister: {quote} [2016-02-25 13:47:02] ERROR[17353]: res_sorcery_memory_cache.c:1559 sorcery_memory_cache_delete: Unable to delete object '<ENDPOINT>;@115bb1375dae1799c68048e7abef7e05' from sorcery cache Contact <ENDPOINT>/sip:<ENDPOINT>@<IP Address>:39212;transport=TLS has been deleted    -- Added contact 'sip:<ENDPOINT>@<IP Address>:39212;transport=TLS' to AOR '<ENDPOINT>' with expiration of 60 seconds Contact <ENDPOINT>/sip:<ENDPOINT>@<IP Address>:39212;transport=TLS has been created Contact <ENDPOINT>/sip:<ENDPOINT>@<IP Address>:39212;transport=TLS is now Unknown.  RTT: 0.000 msec {quote} The device had previously registered and therefore the device should have been in the cache. When this issue occurs it blocks the registration of an endpoint causing it to go offline. I can replicate this issue by pressing 'Re-register' within the Snom interface. Sourcery is configured in the following way: {quote} contact/cache=memory_cache,object_lifetime_stale=3600,object_lifetime_maximum=28800,expire_on_reload=yes,full_backend_cache=yes contact=config,pjsip.conf,criteria=type=contact contact=realtime,ps_contacts {quote} Looking at the real-time database the ID is present, all be it encoded with <ENDPOINT>^3B which is the encoding for a semicolon. Therefore it looks like the cache isn't matching the object correctly or not being inserted in the first place.
Comments:	By: Asterisk Team (asteriskteam) 2016-02-25 09:28:57.417-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]. By: George Joseph (gjoseph) 2016-02-25 15:24:41.054-0600 Hi Ross, If you look under Gerrit Reviews, there's a patch (2132 for 13.7.x) that should fix this.  Can you test? Also, just a nit on your config... Contacts can never come from pjsip.conf so you can remove the "contact=config,pjsip.conf,criteria=type=contact" line from your sorcery.conf file. By: Ross Beer (rossbeer) 2016-02-26 03:46:03.140-0600 Hi George, We are now patching our test box to see if this resolves the issue, I will update you with how we get on. I am also seeing a lot of these types of error: {quote} [2016-02-26 09:04:12] ERROR[31560]: res_pjsip_registrar.c:541 rx_task: Failed to update contact 'sip:<End Point 1>@<IP ADD 1>:6110' expiration time to 60 seconds. [2016-02-26 09:05:08] ERROR[31659]: res_pjsip_registrar.c:541 rx_task: Failed to update contact 'sip:<End Point 2>@<IP ADD 2>:6040' expiration time to 60 seconds. [2016-02-26 09:05:08] ERROR[4735]: res_pjsip_registrar.c:541 rx_task: Failed to update contact 'sip:<End Point 3>@<IP ADD 3>:6070' expiration time to 60 seconds. [2016-02-26 09:05:08] WARNING[31659]: pjsip:0 <?>:      sip_transactio Unable to register REGISTER transaction (key exists) [2016-02-26 09:05:08] WARNING[4735]: pjsip:0 <?>:       sip_transactio Unable to register REGISTER transaction (key exists) [2016-02-26 09:05:08] WARNING[4735]: pjsip:0 <?>:       sip_transactio Unable to register REGISTER transaction (key exists) {quote} Looking at the source code this looks to be related to the contact lookup also, will the patch also fix this issue? By: Ross Beer (rossbeer) 2016-02-26 08:14:38.938-0600 Ok, the original issues appears to be resolved. However I have now got another interesting issue with 'stale' entries. When an entry becomes stale after 3600 seconds, the object is removed from cache which causes a phone de-registration. Sourcery configuration is as follows: {quote} [res_pjsip] ; auth/cache=memory_cache,object_lifetime_stale=3600,object_lifetime_maximum=28800,expire_on_reload=yes,full_backend_cache=yes auth=config,pjsip.conf,criteria=type=auth auth=realtime,ps_auths aor/cache=memory_cache,object_lifetime_stale=3600,object_lifetime_maximum=28800,expire_on_reload=yes,full_backend_cache=yes aor=config,pjsip.conf,criteria=type=aor aor=realtime,ps_aors domain_alias/cache=memory_cache,object_lifetime_stale=3600,object_lifetime_maximum=28800,expire_on_reload=yes,full_backend_cache=yes domain_alias=config,pjsip.conff,criteria=type=domain_alias domain_alias=realtime,ps_domain_aliases endpoint/cache=memory_cache,object_lifetime_stale=3600,object_lifetime_maximum=28800,expire_on_reload=yes,full_backend_cache=yes endpoint=config,pjsip.conf,criteria=type=endpoint endpoint=realtime,ps_endpoints contact=realtime,ps_contacts {quote} Exactly at the point of the 'stale' marking each device states 'Removed contact' and 'Endpoint is now Unreachable' messages are outputted to the CLI. Removing the 'object_lifetime_stale=3600,object_lifetime_maximum=28800' options resolves the issue.