Summary:	ASTERISK-25237: stasis_cache.c:845 caching_topic_exec: - misleading ERROR message
Reporter:	Smirnov Aleksey (limpsobaka)	Labels:
Date Opened:	2015-07-08 11:01:42	Date Closed:	2017-03-15 05:12:18
Priority:	Minor	Regression?
Status:	Closed/Complete	Components:	Core/Stasis Documentation
Versions:	13.4.0	Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) ASTERISK-25237-dant20150716-debug.log
Description:	If turn off in sip.conf rtcachefriends=yes there are many messages: {noformat} [Jul  8 18:54:39] ERROR[27925]: stasis_cache.c:845 caching_topic_exec: Attempting to remove an item from the SIP/4304-cached cache that isn't there: ast_endpoint_snapshot_type SIP/4304 [Jul  8 18:54:39] ERROR[27925]: stasis_cache.c:845 caching_topic_exec: Attempting to remove an item from the SIP/4403-cached cache that isn't there: ast_endpoint_snapshot_type SIP/4403 [Jul  8 18:54:39] ERROR[27925]: stasis_cache.c:845 caching_topic_exec: Attempting to remove an item from the SIP/4309-cached cache that isn't there: ast_endpoint_snapshot_type SIP/4309 {noformat} If the option is rtcachefriends=yes then realtime info about peers and users is in cache, no errors, but after sip reload command the errors come in the CLI. [Edit by Rusty - adding comment from MMichelson below] Hi, I think I see what is happening here. Internally, when a realtime peer is retrieved, Asterisk creates an {{ast_endpoint}} structure. When that peer is destroyed, the {{ast_endpoint}} is destroyed as well. Part of the destruction of the {{ast_endpoint}} involves clearing the Stasis cache of all information about that endpoint. The problem here is that the act of creating the {{ast_endpoint}} is not enough to actually put any information in the Stasis cache. Instead, something has to happen, such as a state change, in order for the Stasis cache to have any information about that endpoint. When a device registers, chan_sip creates an {{ast_endpoint}} structure, processes the REGISTER, and then destroys the {{ast_endpoint}}. When the {{ast_endpoint}} is destroyed, there is nothing to destroy in the Stasis cache, so an error message is emitted. When you use rtcachefriends, {{ast_endpoint}} structures persist for the lifetime of the module and so you do not see this error message. As it stands, this error message is noisy but it should not negatively affect operation. I think the proper fix here is to downgrade that message from an error message to a debug message.
Comments:	By: Asterisk Team (asteriskteam) 2015-07-08 11:01:43.626-0500 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: Rusty Newton (rnewton) 2015-07-08 16:20:18.595-0500 We require additional debug to continue with triage of your issue. Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information By: dant (dant) 2015-07-16 10:28:47.536-0500 Sample debug output around one pair of these messages... One after the REGISTER 401 unauthorised response, one after the REGISTER 200 OK response. By: dant (dant) 2015-07-16 10:33:54.650-0500 Please see attached debug output. By: Mark Michelson (mmichelson) 2015-07-16 15:49:27.453-0500 Hi, I think I see what is happening here. Internally, when a realtime peer is retrieved, Asterisk creates an {{ast_endpoint}} structure. When that peer is destroyed, the {{ast_endpoint}} is destroyed as well. Part of the destruction of the {{ast_endpoint}} involves clearing the Stasis cache of all information about that endpoint. The problem here is that the act of creating the {{ast_endpoint}} is not enough to actually put any information in the Stasis cache. Instead, something has to happen, such as a state change, in order for the Stasis cache to have any information about that endpoint. When a device registers, chan_sip creates an {{ast_endpoint}} structure, processes the REGISTER, and then destroys the {{ast_endpoint}}. When the {{ast_endpoint}} is destroyed, there is nothing to destroy in the Stasis cache, so an error message is emitted. When you use rtcachefriends, {{ast_endpoint}} structures persist for the lifetime of the module and so you do not see this error message. As it stands, this error message is noisy but it should not negatively affect operation. I think the proper fix here is to downgrade that message from an error message to a debug message. By: Bastien LE REST (blerest) 2016-03-11 06:25:57.433-0600 Please note that I have the same issue with the following configuration: rtcachefriends=no rtsavesysname=yes rtupdate=yes rtautoclear=no ignoreregexpire=no When I changed rtcachefriends to yes, I don't have the error anymore. By: Friendly Automation (friendly-automation) 2017-03-15 05:12:20.048-0500 Change 5184 merged by zuul: main/stasis_cache: Demote the ERROR message when removing a nonexistent item [https://gerrit.asterisk.org/5184|https://gerrit.asterisk.org/5184] By: Friendly Automation (friendly-automation) 2017-03-15 05:20:42.206-0500 Change 5185 merged by Joshua Colp: main/stasis_cache: Demote the ERROR message when removing a nonexistent item [https://gerrit.asterisk.org/5185|https://gerrit.asterisk.org/5185] By: Friendly Automation (friendly-automation) 2017-03-15 05:20:54.414-0500 Change 5183 merged by Joshua Colp: main/stasis_cache: Demote the ERROR message when removing a nonexistent item [https://gerrit.asterisk.org/5183|https://gerrit.asterisk.org/5183]