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

[Matt Jordan]

> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/contrib/scripts/refcounter.py, lines 114-116
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56242#file56242line114>
> >
> >     Can we get an option for output filename?  I'd prefer we have --input and --output rather than --file.
> >     
> >     Would be nice if both options supported '-' for STDIO.

I'd prefer not to. This is why we use *nix: you can simply redirect to a file if you feel like it - or pipe to grep, etc.


> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, line 235
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56243#file56243line235>
> >
> >     I think we should not check for destructor_fn != NULL.  Consider the following:
> >     ao2_ref(ao2_alloc(50, NULL), -1);
> >     
> >     This would not print "**call destructor**", causing refcounter.py to report a leak.  
> >     
> >     Also I think we should change this to "**destructor**", since we will print the line for all objects to reach 0 refs.  Since we're already making changes to the format we might as well make all the desired tweaks now.

Agreed; changed.


> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, line 344
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56243#file56243line344>
> >
> >     Should this be "%p,+1,..." to be consistent with the way ao2_ref increments?

I was kind of sticking slightly with the original nomenclature, but I'd rather let the delta be the delta. +1 it is.


> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, lines 1146-1152
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56243#file56243line1146>
> >
> >     What about ao2 objects created before astobj2_init?  I know that storing refs in astlogdir was my idea/request, but I'm concerned this will cause an unfixable issue with initialization order.  If we open the file too early, ast_config_AST_LOG_DIR will be the compiled value instead of the value in asterisk.conf.  If we open too late, startup messages are lost.  Further it's impossible to read astlogdir from asterisk.conf before __attribute__((constructor)).
> >     
> >     What if we allow an environmental variable to override /tmp/refs?  My goal with using astlogdir was to allow multiple instances of asterisk to run without causing conflicts in /tmp/refs.  This would be essential for the testsuite to check refs after tests.
> >     
> >     I don't think we can (safely) avoid opening/closing the refs file for every output.  Doing so would require us to open ref_log before any other __attribute__((constructor)) and closing it after all other __attribute__((destructor)), I think this would be impossible without starting to use constructor/destructor priorities.

If you create an ao2 object before astobj2_init, then you have broken the module load order. You should *not* ever create an ao2 object before that point.

This may mean that astobj2_init has to move higher in the module load order. I've gone ahead and moved it up to being initialized immediately after reading the asterisk.conf file, as the CLI is initialized by that point as well. I'd rather not try to work around things that violate the order: if you try to access something in the core prior to it being initialized, that's an error.

Note that astlogdir is read from asterisk.conf via read_config_maps. This happens immediately after printing out the intro message and registering the basic CLI functions. Again, if you create an ao2 object prior to reading asterisk.conf, you're violating the initialization order of the core and that's an error. Don't do that. :-)

An environment variable that overrides the refs file is fine, but I'd consider that a separate feature from this patch.

I don't think we need to open/close the refs file. That still feels like overkill, as fflush will write all data to disk. As astobj2 is initialized prior to any modules being loaded into memory, the ref_log file will be created before any constructor/destructor calls - which typically do not create ao2 objects as well (as they are used to set up module information).


> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/contrib/scripts/refcounter.py, line 76
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56242#file56242line76>
> >
> >     This should check parsed_line['state'] == '**constructor**', produce a warning and add obj to a list of errors if it's not.  The previous refcounter would inform us of objects that were never created.

I added this option, although it isn't necessary for the same reasons that it was necessary before.

If you don't get a constructor notification, then something has gone horribly, terribly wrong (more on that later). This occurred previously because the REF_DEBUG macro would miss object creation when it occurred outside of where it was defined. It resulted in a lot of false errors/warnings.

What is more likely is that a use after free error will occur where someone attempts to change the ref count of a destroyed object. This will now flag those errors.

In the prior version of this patch, the command line options let you dump only leaks; however, with the addition of another type of object, it makes sense to instead suppress these types as opposed to only dumping a single type. I've inverted the option for leaked objects and added one for skewed lifetime objects, as well as 'normal' objects.


> On March 20, 2014, 4:12 a.m., Corey Farrell wrote:
> > /branches/1.8/main/astobj2.c, lines 228-233
> > <https://reviewboard.asterisk.org/r/3377/diff/2/?file=56243#file56243line228>
> >
> >     Can we deduplicate the ref_log writes into a macro?  I'm suggesting a macro so we can pass "%d" or "%s" for the format of the 'state' field, and let the compiler join the const strings.
> >     
> >     This would make it easier to append additional fields if desired, and ensure consistent output.  For example it is sometimes useful to add the current thread id to all ref_log messages.

I'm not sure how a macro is going to simplify this here. The state field in particular seems like it would necessitate at least two macros; at the end of the day, something has to provide a format string ("%d" or "%s"), and having two macros for three logging statements feels like overkill.


- Matt


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


On March 19, 2014, 1:22 p.m., Matt Jordan wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviewboard.asterisk.org/r/3377/
> -----------------------------------------------------------
> 
> (Updated March 19, 2014, 1:22 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/contrib/scripts/refcounter.py PRE-CREATION 
>   /branches/1.8/build_tools/cflags-devmode.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/20140327/406dec71/attachment-0001.html>