[asterisk-dev] [Code Review] 3377: ref count logs: Redo structure of log file, provide a python debugging tool

[Matt Jordan]

> On March 27, 2014, 7:27 p.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, line 35
> > <https://reviewboard.asterisk.org/r/3377/diff/3/?file=56815#file56815line35>
> >
> >     #ifdef REF_DEBUG
> >     
> >     To take this suggestion we would need to put all "if (ref_log) {}" blocks in #ifdef sections.  I believe this would be correct, as those blocks of code are unreachable if REF_DEBUG isn't defined during compile of astobj2.c (ref_log cannot be initialized).  Previously this wasn't the case since modules could have REF_DEBUG enabled without astobj2.c enabling it.
> >     
> >     We also need to declare static FILE *ref_log = NULL, otherwise it can be used uninitialized.

This should be surrounded by #ifdef REF_DEBUG. Fixed.

It doesn't not need to be initialized to NULL. static variables are automatically initialized to 0.


> On March 27, 2014, 7:27 p.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, lines 1141-1142
> > <https://reviewboard.asterisk.org/r/3377/diff/3/?file=56815#file56815line1141>
> >
> >     I think this can cause a race, especially during non-graceful shutdowns.  This should only be possible when someone enables REF_DEBUG and shuts down with a kill signal or "core stop now", but it could also happen if "core stop gracefully" fails to stop an ao2 using thread.
> >     
> >     From the view of other threads that are not running astobj2_cleanup, ref_log is closed but not NULL for a brief moment.  if (ref_log) { fprintf(ref_log, ...); } races against this.  This could cause fprintf(ref_log, ...) to be called with ref_log==NULL, or with ref_log pointing to an already closed FILE*.
> >     
> >     I don't think it makes a difference when we fclose ref_log.  Not with Asterisk, but I've seen leaked threads cause a segfault while the main thread is running __attribute__((destructor)) functions.

astobj2_cleanup is called in the order that it is registered. As it is registered first (because it is higher in the load order), it won't be called until all other registered cleanup handlers have been called. Thus, all ao2 objects should be reclaimed by this point.

It is the responsibility of a module or some part of the core to join on their threads in their clean up functions when they are unloaded/destroyed/cleaned up/etc. All resources should be cleaned up before this is hit. If a module fails to do that, that's a bug in that module, and not here.

Destructor attributes that are scoped at the file level are only used for module initialization/registration, which does not use an ao2 object.


> On March 27, 2014, 7:27 p.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, line 1162
> > <https://reviewboard.asterisk.org/r/3377/diff/3/?file=56815#file56815line1162>
> >
> >     This is needed when defined(REF_DEBUG) || defined(AO2_DEBUG).  I'm not against registering astobj2_cleanup unconditionally, and just having the procedure do nothing when no debug modes are enabled.

I agree; I prefer to always register it now that multiple conditionals use it.


> On March 27, 2014, 7:27 p.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, line 1156
> > <https://reviewboard.asterisk.org/r/3377/diff/3/?file=56815#file56815line1156>
> >
> >     logger.c is not initialized yet.  What fun start-up ordering is!

Yup, but I knew that when I added that here. It is actually okay to use ast_log (or any of the variants thereof) prior to calling the logger module's initialization method. logger is one of the few (if only) modules that is smart enough to look at its initialization and handle things appropriately.

When you hit ast_logger_full (which ast_log maps to), if there is no logger thread (due to the initialization not having been kicked off), you'll get dropped into logger_print_normal. This references only statically initialized lists and is generally safe to call any time. In particular, this will iterate over the verbosers/log channels and attempt to print to them. As there won't be any verbosers or log channels added to the list yet, this will just get printed to stdout.

Note: I've run into this before when mucking with the load ordering. You can test it out by forcing the condition to true and exiting in asterisk.c if the initialization function fails.


- Matt


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


On March 27, 2014, 4:08 p.m., Matt Jordan wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviewboard.asterisk.org/r/3377/
> -----------------------------------------------------------
> 
> (Updated March 27, 2014, 4:08 p.m.)
> 
> 
> Review request for Asterisk Developers, Corey Farrell and wdoekes.
> 
> 
> Repository: Asterisk
> 
> 
> Description
> -------
> 
> Note: while an improvement to Asterisk, this patch only affects Asterisk when compiled in -dev-mode. Since it has benefit only for developers looking to fix bugs, I'm proposing it for Asterisk 1.8+. The removal of refcounter should be done in trunk only.
> 
> Asterisk uses reference counted objects. A lot. As their use has spread, the bugs related to reference counting errors has grown as well. Central to resolving reference counting issues is the usage of REF_DEBUG; unfortunately, REF_DEBUG has had several problems:
> (1) It could not be enabled through menuselect
> (2) When not enabled globally, updates to objects were often lost, resulting in insufficient data to resolve problems
> (3) The format of the ref debug log file was not suitable for parsing
> 
> This patch changes REF_DEBUG in the following ways:
> (1) It makes REF_DEBUG a meneselect item when Asterisk is compiled with --enable-dev-mode
> (2) The ref debug log file is now created in the AST_LOG_DIR directory. Every run will now blow away the previous run (as large ref files sometimes caused issues). We now also no longer open/close the file on each write, instead relying on fflush to make sure data gets written to the file (in case the ao2 call being performed is about to cause a crash)
> (3) It goes with a comma delineated format for the ref debug file. This makes parsing much easier.
> (4) It throws out the refcounter utility and goes with a python script instead.
> 
> 
> Diffs
> -----
> 
>   /branches/1.8/utils/refcounter.c 410891 
>   /branches/1.8/utils/Makefile 410891 
>   /branches/1.8/main/astobj2.c 410891 
>   /branches/1.8/main/asterisk.c 410891 
>   /branches/1.8/include/asterisk/astobj2.h 410891 
>   /branches/1.8/contrib/scripts/refcounter.py PRE-CREATION 
>   /branches/1.8/channels/chan_sip.c 410891 
>   /branches/1.8/build_tools/cflags.xml 410891 
> 
> Diff: https://reviewboard.asterisk.org/r/3377/diff/
> 
> 
> Testing
> -------
> 
> Things spit out ref logs and the script parses them. Example below:
> 
> ==== Object 0x21ed9b8 history ====
> features.c[5427]:create_parkinglot 1  - [**constructor**]
> features.c[5707]:build_parkinglot +1  - [1]
> features.c[5392]:parkinglot_unref -1  - [2]
> features.c[6358]:build_dialplan_useage_map +1  - [1]
> features.c[6358]:build_dialplan_useage_map -1  - [2]
> features.c[4985]:find_parkinglot +1  - [1]
> features.c[5392]:parkinglot_unref -1  - [2]
> features.c[6358]:build_dialplan_useage_map +1  - [1]
> features.c[6358]:build_dialplan_useage_map -1  - [2]
> features.c[4955]:do_parking_thread +1  - [1]
> features.c[4957]:do_parking_thread -1  - [2]
> astobj2.c[955]:cd_cb_debug -1 deref object via container destroy - [1]
> astobj2.c[955]:cd_cb_debug -1 deref object via container destroy - [**call destructor**]
> 
> 
> Thanks,
> 
> Matt Jordan
> 
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140328/87b1672c/attachment.html>