Re: [log4perl-devel] Change in behavior when upgrading to 1.26 and perl 5.10.0

[Mike S. <m...@pe...>]

Thanks for the detailed description, here's what's happening:

This change in behavior was caused by a patch introduced with
Log-Log4perl-1.19 in

     http://github.com/mschilli/log4perl/commit/35d86ae53859424ea3ac357eaf0f15d9e69f4bed

in September 2008. A detailed description of the issue at the time 
is available in

     http://rt.cpan.org/Ticket/Display.html?id=38356

on the request tracker. It fixed problems with the caller_depth, but it
also introduced a change to get_logger() which bumped up the caller()
level to obtain the category (aka package name) of the calling package.

This is probably a good opportunity to rethink how Log4perl wrapper
classes should be implemented.

To implement a L4p wrapper class correctly, it needs to provide the
following four methods:

     1 Wrap::get_logger()
     2 Wrap::get_logger( $package )
     3 Wrap->get_logger()
     4 Wrap->get_logger( $package )

Calls #1 and #3 are supposed to obtain a logger with the category of the
calling package, not the category of the wrapper package. This is
especially difficult in case #3, as Log4perl doesn't know if "Wrap" is
a Log4perl wrapper or if it's the #2 signature where "$package" is an
application package called "Wrap".

Another complication is that we don't know how "Wrap" is implemented.
Is it relaying the get_logger() call to Log4perl by implementing its own
get_logger function? Or is it simply inheriting from Log4perl?

I've put together a fix to resolve this, please check out the
documentation:

     http://github.com/mschilli/log4perl/commit/8ad3fbae60a4667aba848eb545c66339aeff161a

As this might break backward compatibility with earlier versions of
Log4perl, I'm interested in hearing what you think about it, feedback
definitely welcome. If I don't hear anything back, it'll go out with the
next release.

You can play around with the new implementation, here's the tarball:

      http://github.com/mschilli/log4perl/tarball/wrapper_fix

Also, I've opened a bug on RT to track this issue:

     https://rt.cpan.org/Ticket/Display.html?id=52913

Give it a spin!

-- Mike

Mike Schilli 
m...@pe...

On Wed, 9 Dec 2009, Martin Evans wrote:

> Mike Schilli wrote:
>> On Wed, 9 Dec 2009, Martin Evans wrote:
>>
>>> Since the upgrade we are getting no logging in one of the files we
>>> expected to get it. After a bit of searching around I discovered the
>>> module we were using was doing this:
>>>
>>> local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
>>> $h{logger} = Log::Log4perl->get_logger();
>>> and the fix was to change the order of those lines.
>>
>> Thanks for reporting this, although I have a hard time imaginining how
>> increasing the caller_depth and then getting a logger would be different
>> from what you'd get if you did it in the reverse order. Not to mention
>> that it's puzzling why this would change the logging behavior, as
>> caller_depth is used mainly for cosmetic reasons in certain features
>> of the pattern layout.
>>
>> Can you provide a snippet of code that reproduces the problem in full?
>> That would really help track down the root of the problem.
>>
>> Thanks!
>>
>> -- Mike
>>
>> Mike Schilli
>> m...@pe...
>>
>>
>
> It was ending up with "main" and the category in the following code
> instead of DBIx::Log4perl.
>
>
> sub get_logger {  # Get an instance (shortcut)
> ##################################################
>    # get_logger() can be called in the following ways:
>    #
>    #   (1) Log::Log4perl::get_logger()     => ()
>    #   (2) Log::Log4perl->get_logger()     => ("Log::Log4perl")
>    #   (3) Log::Log4perl::get_logger($cat) => ($cat)
>    #
>    #   (5) Log::Log4perl->get_logger($cat) => ("Log::Log4perl", $cat)
>    #   (6)   L4pSubclass->get_logger($cat) => ("L4pSubclass", $cat)
>
>    # Note that (4) L4pSubclass->get_logger() => ("L4pSubclass")
>    # is indistinguishable from (3) and therefore can't be allowed.
>    # Wrapper classes always have to specify the category explicitely.
>
>    my $category;
>
>    if(@_ == 0) {
>          # 1
>        $category = scalar caller($Log::Log4perl::caller_depth);
>    } elsif(@_ == 1) {
>          # 2, 3
>        if($_[0] eq __PACKAGE__) {
>              # 2
>            $category = scalar caller($Log::Log4perl::caller_depth);
>        } else {
>            $category = $_[0];
>        }
>    } else {
>          # 5, 6
>        $category = $_[1];
>    }
>
>    # Delegate this to the logger module
>    return Log::Log4perl::Logger->get_logger($category);
> }
>
>
> Here is an example:
>
> 1.pl
> ====
>
> use Log::Log4perl qw(get_logger :levels);
> use DBIx::Log4perl;
>
> Log::Log4perl->init_and_watch('x.conf', 60);
>
> my $a = DBIx::Log4perl->new();
>
> Log4perl.pm (put this in a dir called DBIx)
> ===========
>
> package DBIx::Log4perl;
>
> sub new
> {
>
>    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
>    $h = Log::Log4perl->get_logger();
>
>    $h->debug("log msg");
>
> }
> 1;
>
> x.conf
> ======
>
> log4perl.logger=ERROR
> log4perl.logger.Server = INFO
> log4perl.logger.DBIx.Log4perl=DEBUG, X1
> log4perl.appender.X1=Log::Log4perl::Appender::File
> log4perl.appender.X1.filename=dbix.log
> log4perl.appender.X1.mode=append
> log4perl.appender.X1.utf8 = 1
> log4perl.appender.X1.umask = sub { 0002 }
> log4perl.appender.X1.layout=Log::Log4perl::Layout::PatternLayout
> log4perl.appender.X1.layout.ConversionPattern=%d %p> %F{1}:%L %M - %m%n
>
> then run
> perl -I/dir_where_DBIx_dir_is 1.pl
>
> nothing comes out in log. Change the depth after get_logger and it works.
>
> Martin
> --
> Martin J. Evans
> Easysoft Limited
> http://www.easysoft.com
>
> ------------------------------------------------------------------------------
> Return on Information:
> Google Enterprise Search pays you back
> Get the facts.
> http://p.sf.net/sfu/google-dev2dev
> _______________________________________________
> log4perl-devel mailing list
> log...@li...
> https://lists.sourceforge.net/lists/listinfo/log4perl-devel
>