[asterisk-dev] [Code Review] 4502: Improved and portable ast_log recursion avoidance

[rmudgett]

> On March 24, 2015, 12:52 p.m., rmudgett wrote:
> > /branches/13/main/logger.c, line 1762
> > <https://reviewboard.asterisk.org/r/4502/diff/1/?file=72474#file72474line1762>
> >
> >     Why couldn't the log safe recursion check be done all the time by ast_log_full()?
> >     
> >     Relying on users to know which log function should be used seems unreasonable for something as low level as logging.  This seems more like an implementation detail that doesn't need to be exposed.
> >
> 
> Corey Farrell wrote:
>     Quoting Matt Jordan on ASTERISK-24833:
>     "I would say that any improvement that gets made should be subject to performance issues as well. Checking a threadlocal variable on every logging statement could get expensive."
>     
>     
>     I do not know what the performance hit of a threadlocal is, nor how to test for it.  The idea with the separate function is that it's very rarely needed, compared to ast_log_full which is run constantly.  I looked at this as the logger is responsible for ensuring it doesn't recurse by ensuring functions it calls only use ast_log_safe.  There aren't many, and we shouldn't allow logger.c to start using more parts of Asterisk.
>     
>     Additionally for Asterisk 11/13, it would be ineffective to check for recursion in ast_log_full.  We would need to protect ast_log, along with all publicly reachable functions that can retreive the callid AO2 from threadstorage.  Some functions would need to be split into a public function which checks recursion, and a private function that gets calls when recursion has already been checked.
> 
> rmudgett wrote:
>     ast_log_full() is the common base function that all logging paths get to so everything would be protected.
>     
>     But since performance could be an issue then limiting which messages get blocked is more important than limiting recursion.  The OOM and invalid ao2 object messages definitely need to be blocked.  However, I'm not sure any others would need to be blocked even if called by the logging_thread.
> 
> Corey Farrell wrote:
>     The problem with checking from ast_log_full (besides performance) is that any check in that function comes after ast_log has already retreived the AO2 callid.  So a recursive loop can happen before ast_log_full is called.
>     
>     The change to utils.c is not needed, I'll remove it on the next update.  I still believe the change to strings.c is needed as it is effectively an OOM message which can be caused by calls ast_str_set/ast_str_append (logger routines use this).

Ok, I see that now.


- rmudgett


-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviewboard.asterisk.org/r/4502/#review14802
-----------------------------------------------------------


On March 24, 2015, 3:31 p.m., Corey Farrell wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviewboard.asterisk.org/r/4502/
> -----------------------------------------------------------
> 
> (Updated March 24, 2015, 3:31 p.m.)
> 
> 
> Review request for Asterisk Developers.
> 
> 
> Bugs: ASTERISK-24155
>     https://issues.asterisk.org/jira/browse/ASTERISK-24155
> 
> 
> Repository: Asterisk
> 
> 
> Description
> -------
> 
> This introduces a new logger routine ast_log_safe.  This routine should be used for all error messages in code that can be run as a result of ast_log.  ast_log_safe does nothing if run recursively or from the logger thread.  All error logging in astobj2.c, strings.c and utils.h have been switched to ast_log_safe.  One ast_log from stringfields code in utils.c was also changed.
> 
> I've also added support for raw threadstorage.  This provides direct access to the void* pointer in threadstorage.  In ast_log_safe I use NULL to signify that this thread is not already running ast_log_safe, (void*)1 when it is already running.  This was done since it's critical that ast_log_safe do nothing that could log during recursion checking.
> 
> This review shows the version 13 patch.  Version 11 didn't have the backtrace check for MALLOC_FAILURE_MSG, and trunk uses 'ast_callid' instead of 'struct ast_callid *'.  Patches for each version are on JIRA.
> 
> The idea to use threadstorage to protect certain error logging came from the patch posted by Timo Teräs.
> 
> 
> Diffs
> -----
> 
>   /branches/13/main/utils.c 433360 
>   /branches/13/main/strings.c 433360 
>   /branches/13/main/logger.c 433360 
>   /branches/13/main/hashtab.c 433360 
>   /branches/13/main/astobj2.c 433360 
>   /branches/13/include/asterisk/utils.h 433360 
>   /branches/13/include/asterisk/threadstorage.h 433360 
>   /branches/13/include/asterisk/logger.h 433360 
> 
> Diff: https://reviewboard.asterisk.org/r/4502/diff/
> 
> 
> Testing
> -------
> 
> Verified with 'nm -g main/astobj2.o' that ast_log_safe was being used.
> 
> Tested by further modifying Asterisk with added calls to ast_log_safe().
> * In main() after fully booted.
> * In ast_log_safe() after setting in_safe_log.
> * From the logger thread.
> 
> Only the message after fully booted was shown in the logs, all others were ignored.
> 
> 
> Thanks,
> 
> Corey Farrell
> 
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20150324/9ce3ced1/attachment-0001.html>