Re: [log4perl-devel] log4perl enhancement request ?

[Pete S. <si...@uc...>]

Thanks for the replies (see below).  Basically, Mike Schilli and Kevin
Goess provided the same solution, based on using the "caller" function.
This solution works perfectly for me.  Jim Cromie answered in depth, and
expressed concern that the solution would be prohibitively expensive.  I
tested the expense and found it to be minor (see below).

Thanks again, guys!  I got just what I wanted.


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


  Mike> If you don't mind the expense of a bunch of caller() calls per
  Mike> logged message, here's a solution:
  Mike>
  Mike> use Log::Log4perl qw(get_logger);
  Mike>
  Mike> ####################
  Mike> sub level {
  Mike> ####################
  Mike>      my $i = 0;
  Mike>      $i++ while caller($i);
  Mike>      return $i-6;
  Mike> }
  Mike>
  Mike> my $conf = q(
  Mike> log4perl.PatternLayout.cspec.Y = sub { "  " x level() }
  Mike> log4perl.category                  = WARN, Logfile
  Mike> log4perl.appender.Logfile          = Log::Log4perl::Appender::Screen
  Mike> log4perl.appender.Logfile.layout   = PatternLayout
  Mike> log4perl.appender.Logfile.layout.ConversionPattern = %Y%m%n
  Mike> );
  Mike>
  Mike> Log::Log4perl::init(\$conf);
  Mike>
  Mike> my $logger = get_logger("");
  Mike> $logger->error("first");
  Mike> bar();
  Mike> $logger->error("first");
  Mike>
  Mike> sub bar { $logger->error("second"); foo(); }
  Mike> sub foo { $logger->error("third"); }
  Mike>
  Mike> __END__
  Mike>
  Mike> The $i-6 expression might need to be adapted if caller_level is
  Mike> set to anything but 0. Here's the output:
  Mike>
  Mike> first
  Mike>    second
  Mike>      third
  Mike> first
  Mike>
  Mike> -- Mike

Thanks!

  Kevin> | sub level {
  Kevin> |      my $i = 0;
  Kevin> |      $i++ while caller($i);
  Kevin> |      return $i-6;
  Kevin> | }
  Kevin> 
  Kevin> The $i-6 expression might need to be adapted if caller_level is
  Kevin> set to anything but 0.
  Kevin>
  Kevin> It seems like we should make that magic number 6 a log4perl
  Kevin> constant or something, doesn't it?  It's the number of levels
  Kevin> between an application and a cspec, is it?
  Kevin>
  Kevin> Kevin M. Goess

I agree that the "6" should be a constant.  I suggest that the above
subroutine be added to the documentation of Log4perl as an example of
how to use custom cspecs.

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

Within reason, I don't care if the application slows down when I turn on
logging.

I wrote a small test: 100000 calls to a function that logs a message and
calls a second function that logs a message.  I used a
"Log::Dispatch::File" appender and a PatternLayout of "%m%n".  It took
58 seconds on my 1.2Ghz Pentium under Linux with Perl 5.6.1.  To make
the same program use caller, I changed the PatternLayout to "%Z%m%n" and
added

Log::Log4perl::Layout::PatternLayout::add_global_cspec('Z',
						       sub {
							 my $lvl = 0;
							 $lvl++ while caller($lvl);
							 return '  ' x ($lvl-6);
						       }
						      );

The output file had the indentation, and it took only 62 seconds to run.
A surprisingly small hit!

  Jim> 2. I didn't really like that answer, but it was true.  So I went
  Jim>    digging into optimizer.pm, and eventually wrote
  Jim>    Log::Log4perl::Autocategorize.  In this package, AUTOLOAD
  Jim>    catches all logging calls, uses caller() to figure out who
  Jim>    called, consults L4perl to determine whether to log it, and
  Jim>    does so.
  Jim>
  Jim>      my $predicate = "is_$level";
  Jim>      eval { $runnable = $log->$predicate() };
  Jim>
  Jim>    Now, here's the tricky part - because I used optimizer to
  Jim>    munge the method-name into a new, unique name (ex: from debug
  Jim>    to debug_$somevalue), I could create a custom subroutine to do
  Jim>    the right thing FOR THAT CALL-POINT.  Thereafter - calls to
  Jim>    that subroutine (ie FROM THAT CALLER) were handled at
  Jim>    full-speed, and with full customized behavior.
  Jim>
  Jim>    It would not be hard to extend to accommodate your desires,
  Jim>    WITH SOME CAVEATS
  Jim>
  Jim>    a. Depth must be perfectly correlated to the invoker.
  Jim>
  Jim>       The simplest explanation is by way of a counter-example: a
  Jim>       debug_print() utility would likely be used from dozens of
  Jim>       places, and from different depths of the code.  These
  Jim>       differences would not be seen by my package, since the
  Jim>       logging call is coming from debug_print, not from its many
  Jim>       users. To amplify this point - indent-level could easily be
  Jim>       wrong, and undetectably so.

I don't think this is a scheme to pursue, especially since "caller"
seems efficient enough.  This adds even more complexity to an
already-complex system.

  Jim>    b. L4P has no way to express filtering based on call-stack.
  Jim>
  Jim>       I extended the meaning of 'logging category' to carry all
  Jim>       the info that caller() provides, thus you can filter on
  Jim>       class, subroutine, line number.
  Jim>
  Jim>     log4perl.category.Frob.nicate.debug = INFO        # 2
  Jim>     log4perl.category.Frob.nicate.debug.118 = DEBUG    # 3
  Jim>     #log4perl.category.Frob.Vernier.twiddle.debug = DEBUG    # 4
  Jim>
  Jim>       But this runs out of gas after 1st caller level.  There's
  Jim>       no obvious/clean way to extend this to operate on results
  Jim>       of caller(N).  I discuss some options in my POD, please
  Jim>       read there, but here's a strawman:
  Jim>
  Jim>     log4perl.caller(2).Frob.nicate.debug = INFO        # 2
  Jim>
  Jim>       There are problems with this - its hard (impossible?) to
  Jim>       know whether is_debug() says yes/no due to an exact match
  Jim>       or a bubble-up match, hence its hard to know whether a
  Jim>       level-N filter is even pertinent.  And it would be silly to
  Jim>       invoke caller(42) to check for filters speced at that level
  Jim>       - on average, there won't be.

I don't think this is a path to pursue.

  Jim>    c. your idea could/should extend to nested lexical scopes
  Jim>       within subroutines, but that's a whole nuther can of worms.

I disagree that it could/should be extended, and I agree that to do so
would be a whole nuther can of worms.  Lexical scopes are not a runtime
thing, so I think it would get confusing fast.

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

Actually, this brings up a problem for me.  I have big Java projects and
big Perl projects.  I hope to standardize on a logging framework that I
can use in both languages.  I have no idea (yet) whether L4J can be
coaxed to offer indented log messages.

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

I got/unpacked it, and I confess it's deeper magic than I want to
use.  I am still struggling with the OO paradigm!

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

I used Log::Agent for a while before I learned about Log4perl.
Log::Agent worked fine, and I could do the indenting, but I still had to
manage a $CallDepth variable.  Log::Agent has the advantage that it has
simple numeric levels, which I miss in Log4perl - I haven't yet learned
how to translate a simple numeric command-line option into Log4perl
categories.  Log::Agent made me think about the difference between
tracing messages, debug messages and log messages, which was good.  I'm
now investing in Log4perl because I want to use the same logging
framework in Perl and Java.  And there's a book about log4j, which
applies to Log4perl.  And it's powerful.

Thanks again!

-- Pete