[Catalyst] Catalyst::Log::Log4perl log duplicates

[Jason Kohles]

On Jan 7, 2008, at 3:27 PM, Adam Jacob wrote:

> On 1/7/08, Marius Kjeldahl <mariusauto-catalyst at kjeldahl.net> wrote:
>> I tried briefly looking into the source, when I ran into this:
>>
>>                # I really have no idea why the correct subroutine
>>                # is on a different call stack
>>                $caller{subroutine} = ( caller(1) )[3];    #wtf?
>>
>> Does anybody want to comment on the maturity of the Catalyst log4perl
>> module?
>
> Besides the smarty-pants comment, it's pretty mature. :)
>
It's also kind of a pain.  I use log4perl with Catalyst, but without  
the plugin, primarily for three reasons:

1. The support for ->abort() means all the logs are saved up and then  
pushed out at the end of the request, which makes debugging anything  
time related a pain.
2. The funkiness pasted above, where it fakes a bunch of the cspecs in  
order to work around the fact that isn't logging in real time, and  
which has caused me problems every time I've tried to use it.
3. The way support for ->abort() was implemented makes it all-or- 
nothing, I wanted to suppress Static::Simple output on the console,  
but have it show up in the logs.

This is the approach I took, which solves these problems.  I'm  
probably going to encapsulate this into a catalyst component at some  
point, when I have some free time...


package MyApp::Web::Logger;
use strict;
use warnings;
use Log::Log4perl;

BEGIN {
     my @levels = qw( fatal error warn info debug trace );
     for ( @levels ) {
         my $level = $_;
         no strict 'refs';
         *{ $level } = sub {
             my $self = shift;
             local $Log::Log4perl::caller_depth += 1;
             my $caller = caller( 1 );
             return Log::Log4perl->get_logger( $caller )->$level( @_ );
         };
         $level = "is_".$level;
         *{ $level } = sub {
             local $Log::Log4perl::caller_depth += 1;
             my $caller = caller( 1 );
             return Log::Log4perl->get_logger( $caller )->$level();
         };
     }
};

sub levels { }
sub enable { }
sub disable { }
sub abort {
     my $self = shift;
     if ( @_ ) { Log::Log4perl::MDC->put( '_abort_request_log' =>  
shift() ) }
     return Log::Log4perl::MDC->get( '_abort_request_log' );
}

So now Catalyst just stores the abort flag in the MDC, which makes it  
easy enough to have a filter to skip logging when the request aborted.

package Log::Log4perl::Filter::CatalystAbort;
use strict;
use warnings;
use base qw( Log::Log4perl::Filter );

sub ok {
     my ( $self, %param ) = @_;
     return ! Log::Log4perl::MDC->get( '_abort_request_log' );
}

To use the filter, you just add it as a filter to your log4perl  
configuration file...

log4perl.rootLogger=TRACE,ColorScreen,RollingFile

# ColorScreen appender, good choice for debugging
log4perl 
.appender.ColorScreen=Log::Log4perl::Appender::ScreenColoredLevels
log4perl.appender.ColorScreen.stderr=1
log4perl 
.appender.ColorScreen.layout=Log::Log4perl::Layout::PatternLayout
log4perl.appender.ColorScreen.layout.ConversionPattern=%d{HH:mm}  
%p[%c] %m%n
log4perl.appender.ColorScreen.color.FATAL=bold red
log4perl.appender.ColorScreen.color.DEBUG=white
log4perl.appender.ColorScreen.Filter = CatalystAbort

# RollingFile appender, keeps a logfile
log4perl.appender.RollingFile=Log::Dispatch::FileRotate
log4perl.appender.RollingFile.filename=debug.log
log4perl.appender.RollingFile.max=10000
log4perl 
.appender.RollingFile.layout=Log::Log4perl::Layout::PatternLayout
log4perl.appender.RollingFile.layout.ConversionPattern=%d{HH:mm}  
%p[%c] %m%n

# Filter to support Catalyst::Log->abort(1)
log4perl.filter.CatalystAbort = Log::Log4perl::Filter::CatalystAbort


Now the aborted log entries are skipped for the ColorScreen appender,  
but included in the RollingFile appender, so that if something does go  
wrong with Static::Simple, then I can look at the log to see what it  
was, but the rest of the time I don't get swamped with the static file  
output.

The only downside to doing it this way is that things that use ->abort  
may not do it early enough to really supress all the logging for that  
component.  For Static::Simple, for example, I still get the first two  
lines of output, but that is much less annoying than the alternative  
(IMHO):

17:32 DEBUG[Catalyst] "GET" request for "static/reset-fonts-grids.css"  
from "127.0.0.1"
17:32 DEBUG[Catalyst] Arguments are "static/reset-fonts-grids.css"

-- 
Jason Kohles, RHCA RHCDS RHCE
email at jasonkohles.com - http://www.jasonkohles.com/
"A witty saying proves nothing."  -- Voltaire