Re: [log4perl-devel] log4perl enhancement request ?

[Jim C. <jc...@di...>]

Pete Siemsen wrote:

>I'd like log4perl to indent messages to show caller depth in the call
>stack.  A sample of this style is
>
>  main: starting
>    function1: called with arg1, arg2
>    function1: returning value1
>    function2: called
>      function3: called
>        function4: called with arg4
>        function4: returning
>      function3: returning
>    function2: returning
>  main: ending
>
>For years, I've been doing this by passing around a scalar named
>$CallDepth, and incrementing/decrementing it at function entry/exit.  I
>pass around a second scalar named $DbgLevel that works sorta like the
>levels in log4perl, but with more levels.
>


I have several reactions:

1. Not gonna happen - using caller() on every invocation would bethe 
only way to get stack depth,
and is horrifically expensive for an application-wide logging facility.  
I once proposed that
caller(1) be used to provide more info to filtering operations, and that 
was deemed infeasable
due to efficiency concerns.  Your idea would require N times as many 
(log2(N) if youre clever)
uses of caller in order to get the depth of the stack.

2. I didnt really like that answer, but it was true.  So I went digging 
into optimizer.pm, and eventually
wrote Log::Log4perl::Autocategorize.  In this package, AUTOLOAD catches 
all logging calls,
uses caller() to figure out who called, consults L4perl to determine 
whether to log it, and does so.

     my $predicate = "is_$level";
     eval { $runnable = $log->$predicate() };

Now, heres the tricky part - because I used optimizer to munge the 
method-name into a new, unique
name (ex: from debug to debug_$somevalue), I could create a custom 
subroutine to do the right thing
FOR THAT CALL-POINT.  Thereafter - calls to that subroutine (ie FROM 
THAT CALLER)
were handled at full-speed, and with full customized behavior.

It would not be hard to extend to accommodate your desires, WITH SOME 
CAVEATS

a. Depth must be perfectly correlated to the invoker.

The simplest explanation is by way of a counter-example:  a 
debug_print() utility would likely be
used from dozens of places, and from different depths of the code.  
These differences would
not be seen by my package, since the logging call is coming from 
debug_print, not from its
many users. To amplify this point - indent-level could easily be wong, 
and undetectably so.

b. L4P has no way to express filtering based on call-stack.

I extended the meaning of 'logging category' to carry all the info that 
caller() provides,
thus you can filter on class, subroutine, line number.

    log4perl.category.Frob.nicate.debug = INFO        # 2
    log4perl.category.Frob.nicate.debug.118 = DEBUG    # 3
    #log4perl.category.Frob.Vernier.twiddle.debug = DEBUG    # 4

But this runs out of gas after 1st caller level.  Theres no 
obvious/clean way to extend this
to operate on results of caller(N).  I discuss some options in my POD, 
please read there,
but heres a strawman:

log4perl.caller(2).Frob.nicate.debug = INFO        # 2

There are problems with this - its hard (impossibl?) to know whether 
is_debug()
says yes/no due to an exact match or a bubble-up match, hence its hard 
to know
whether a level-N filter is even pertinent.  and it would be silly to 
invoke caller(42)
to check for filters speced at that level - on average, there wont be.

c. your idea could/should extend to nested lexical scopes within 
subroutines, but
thats a whole nuther can of worms.

d. Im unwilling to extend Autocat in ways that appear to be incompatible 
with L4P.
And since L4P strives to be compatible with L4J, Id expect some 
reluctance there to
do whats needed to the configs.   Hopefully L4J has reserved some part 
of the config-space
to accomodate special needs/features (such as 'log4perl.caller(2)' above)

3.  Have you looked at Hook::Scope ?   Its more deep magic that I dont 
understand well,
but it can hang/hook actions on scope entry/exit that you could use in a 
wrapper class.

4. IIRC, Log::Agent can represent enter,exits via indentation


WRT

The $caller_level variable is especially intriguing, as it's *almost*
what I need.  Instead of being "how many levels back up the call stack
you have to go to find the caller", which isn't very useful, I want it
to be "how many levels back up the call stack you have to go to find the



do you mean caller_depth ?  If so, that doesnt mean what you think it means.
Basically, it allows a wrapper class to tell L4P that "Im just a 
middleman!, caller(N) is
the end-customer".    The levels up to main is a run-time entity - its 
always changing.

hope this helps, and creates discussion..