From: Martin E. <mar...@ea...> - 2009-12-09 10:28:55
|
Hi, I'm only sending this on the off chance someone here might be interested - I've sorted the problem out at my end. We've been using Log::Log4perl 1.25 and previous versions for ages but moved to a new development machine. The old one was perl 5.8.8 and Log::Log4perl 1.25 and the new one is perl 5.10.0 and Log::Log4perl 1.26 (I'm not sure the Perl version matters but I have not tested that). 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. I've no idea why it works on one machine and not the other but I thought someone might be interested. The module in question was DBIx::Log4perl. Martin -- Martin J. Evans Easysoft Limited http://www.easysoft.com |
From: Mike S. <m...@pe...> - 2009-12-09 16:34:25
|
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... |
From: Martin E. <mar...@ea...> - 2009-12-09 16:59:16
|
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 |
From: Mike S. <m...@pe...> - 2009-12-19 21:21:07
|
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 > |
From: Martin J. E. <mar...@ea...> - 2009-12-20 09:59:07
|
Mike Schilli wrote: > 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... > Thanks Mike, I'm on holiday now and I doubt I'll get a chance to try this properly until the first week on January - if I do I'll let you know. Hope this fits in with your timescales - I will try it out as soon as I can. Martin > 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 >> > > |
From: Martin J. E. <mar...@ea...> - 2010-01-06 12:01:40
|
Mike Schilli wrote: > 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... Thank you Mike. I've tried this now and it appears to fix the change in behaviour I reported and does not appear to break anything else I can see. I am now using the tarball you provided and will report if I see anything. I will also update the rt later today. Thanks again Martin -- Martin J. Evans Easysoft Limited http://www.easysoft.com > 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 >> > > > |