[asterisk-bugs] [JIRA] (ASTERISK-25237) stasis_cache.c:845 caching_topic_exec: - misleading ERROR message

[Rusty Newton (JIRA)]

     [ https://issues.asterisk.org/jira/browse/ASTERISK-25237?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Rusty Newton updated ASTERISK-25237:
------------------------------------

    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]
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.

  was:
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.


>  stasis_cache.c:845 caching_topic_exec: - misleading ERROR message
> ------------------------------------------------------------------
>
>                 Key: ASTERISK-25237
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-25237
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/Stasis, Documentation
>    Affects Versions: 13.4.0
>            Reporter: Smirnov Aleksey
>            Assignee: Rusty Newton
>            Severity: Minor
>         Attachments: ASTERISK-25237-dant20150716-debug.log
>
>
> 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]
> 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.



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