Log 4 perl Mike Schilli Yahoo OSCON 07242008

Log 4 perl Mike Schilli, Yahoo! OSCON, 07/24/2008

Logging – why? • Debug during development • Go back in time and figure out what happened. • Measure performance • Trace activity on live systems

Why Log 4 perl and not one of the 20 Logging modules on CPAN? • No CPAN dependencies • Easy to use, but scales with complexity • Unique Features

Log: : Log 4 perl Availability • cpan> install Log: : Log 4 perl (Only requires core modules) • Included in major Linux distros sudo apt-get install liblog-log 4 perl • Requires Perl 5. 00503 or better • Windows: ppm package available in Active. State archives or from log 4 perl. com

Use Log 4 perl as a Remote Control to your System.

Log: : Log 4 perl Remote Controls Levels Loggers Layouts Appenders

Log: : Log 4 perl Remote Controls Levels Log/Suppress Priority/Level Loggers Locate it in the system Layouts Format it Appenders Write it out

Log: : Log 4 perl Remote Controls Levels Loggers Layouts Appenders DEBUG “Starting up”; ERROR “Cannot open $file”; Turn logging on in main or Net: : Amazon “Starting up” => 2007 -06 -21 07: 30: 33 Foo. pm-123 Starting up Log File Database …

Sounds complicated? Actually, it’s easy …

Easy Log 4 perl #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); DEBUG “Starting up”;

Don’t like macros? Use get_logger() #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(get_logger); my $logger = get_logger(); $logger->debug(“Starting up”);

Like it clean? Use Moose! package Ferrari; use Moose; with “Moose. X: : Log 4 perl”; sub drive { my($self) = @_; $self->log->debug(“Wroom!!”); }

Easy Log 4 perl #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); DEBUG “Starting up”;

Easy Log 4 perl $. /hello $

Easy Log 4 perl #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init( $DEBUG ); DEBUG “Starting up”;

Easy Log 4 perl $. /hello 2008/07/08 18: 37: 12 Starting up $

Easy Log 4 perl #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init( $DEBUG ); DEBUG “Starting up”; # … something happens ERROR “Horrible error!”;

Easy Log 4 perl $. /hello 2008/07/08 18: 37: 12 Starting up 2008/07/08 18: 37: 12 Horrible error! $

Easy Log 4 perl #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init( $ERROR ); DEBUG “Starting up”; ERROR “Horrible error!”;

Easy Log 4 perl $. /hello 2008/07/08 18: 37: 12 Horrible error! $

Remote Control #1: Levels

You get the concept: FATAL ERROR WARNING INFO DEBUG TRACE Message Priority Log Level Configured

Chatty configuration FATAL ERROR WARNING INFO DEBUG TRACE Message Priority TRACE Log Level Configured

Silent configuration FATAL ERROR WARNING INFO DEBUG TRACE Message Priority ERROR Log Level Configured

Log Levels • Choose them wisely – TRACE(“$bytes transferred”); – DEBUG(“HTTP get OK”); – INFO(“Starting up”); – WARN(“HTTP get failed, retrying”); – ERROR(“Out of retries!”); – FATAL(“Panic! Shutting down. ”);

Remote Control #2: Layouts

Location-Awareness • Log 4 perl’s Loggers are aware of their location: package Foo; use Log: : Log 4 perl qw(: easy); sub foo { DEBUG “Starting up”; }

Location-Awareness package Foo; use Log: : Log 4 perl qw(: easy); sub foo { DEBUG “Starting up”; } $. /hello 2008/07/13 19: 32: 39 Starting up

Location-Awareness package Foo; use Log: : Log 4 perl qw(: easy); sub foo { DEBUG “Starting up”; } $. /hello 637 Foo: : foo. /Foo. pm-4> Starting up

Location-Awareness package main; use Log: : Log 4 perl (: easy); Log: : Log 4 perl->easy_init({ level => $DEBUG, layout => “%r %M %F-%L> %m%n”, }); Foo: : foo(); # unchanged! $. /hello 637 Foo: : foo. /Foo. pm-4> Starting up

Configuration Files If this becomes unwieldy: Log: : Log 4 perl->easy_init({ level => $DEBUG, layout => “%r %M %F-%L>%m%n”, });

Configuration Files #l 4 p. conf l 4 p. logger = DEBUG, Screen l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Pattern. Layout l 4 p. appender. Screen. Layout. Conversion. Pattern = %r %M %F-%L> %m%n Log: : Log 4 perl->init( “l 4 p. conf” );

Advantages of Config Files • Can be edited – indepentently of the script – while the script runs – by people without access to the code

Remote Control #3: Categories (Loggers)

Turn on Logging Everywhere Script l 4 p. logger = DEBUG, Screen Modules

Using Categories Script l 4 p. logger. Net. Amazon = DEBUG, Screen Modules Net: : Amazon

Using Categories main Script l 4 p. logger. main = Modules DEBUG, Screen Net: : Amazon

Using Categories main Script l 4 p. logger. main = DEBUG, Screen l 4 p. logger. Net. Amazon = DEBUG, Screen Modules Net: : Amazon

Categories #l 4 p. conf l 4 p. logger. main = DEBUG, Screen l 4 p. logger. Net. Amazon = DEBUG, Screen l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Pattern. Layout l 4 p. appender. Screen. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Net: : Amazon

Category Inheritance #l 4 p. conf l 4 p. logger. Net = DEBUG, Screen l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Pattern. Layout l 4 p. appender. Screen. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Net: : Google Net: : Amazon

Remote Control #5: Appenders

Root Logger #l 4 p. conf l 4 p. logger = DEBUG, Screen l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Pattern. Layout l 4 p. appender. Screen. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Net: : Google Net: : Amazon

Multiple Appenders #l 4 p. conf l 4 p. logger. main = DEBUG, Screen l 4 p. logger. Net. Amazon = DEBUG, File l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Simple. Layout l 4 p. appender. File = Log: : Log 4 perl: : Appender: : File l 4 p. appender. File. filename = /var/log/myapp. log l 4 p. appender. File. Layout = Pattern. Layout l 4 p. appender. File. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Screen Net: : Amazon File

Multiple Appenders (different log levels) #l 4 p. conf l 4 p. logger. main = DEBUG, Screen l 4 p. logger. Net. Amazon = ERROR, File l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Simple. Layout l 4 p. appender. File = Log: : Log 4 perl: : Appender: : File l 4 p. appender. File. filename = /var/log/myapp. log l 4 p. appender. File. Layout = Pattern. Layout l 4 p. appender. File. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Screen Net: : Amazon File

Multiple Appenders #l 4 p. conf l 4 p. logger. main = DEBUG, Screen, File l 4 p. appender. Screen = Log: : Log 4 perl: : Appender: : Screen l 4 p. appender. Screen. Layout = Simple. Layout l 4 p. appender. File = Log: : Log 4 perl: : Appender: : File l 4 p. appender. File. filename = /var/log/myapp. log l 4 p. appender. File. Layout = Pattern. Layout l 4 p. appender. File. Layout. Conversion. Pattern = %r %M %F-%L> %m%n main Screen Net: : Amazon File

Log 4 perl Flow Application sends a log message (Category, Priority) Log 4 perl Configuration decides go/no go, based on Category and Priority ? Layout Appender

Log 4 perl and Log 4 j • Log: : Log 4 perl ports Log 4 j to Perl • Log 4 j: de facto Java logging standard, by Ceki Gülcü – Latest development: ‘logback’ • http: //logging. apache. org/log 4 j • Log: : Log 4 perl adds perlisms demanded by users

Log 4 perl History • • 0. 01 release 2002 Current release 1. 17 (07/2008) Authors: Mike Schilli, Kevin Goess Used by major banks, target. com, fedex. com, Yahoo!, Google, … • Several CPAN modules support it (e. g. Catalyst, Net: : Amazon, …) • Every major Linux distro has it (Ubuntu, Suse, Fedora …)

Log 4 perl Release History

Design Goals • Easy to use in small scripts • Scales easily with growing architecture • Log 4 perl-enabled CPAN modules can be used with and without Log 4 perl initialization • Optimized for Speed • Open Architecture, extensible

Combine Remote Controls • Write code once, and L 4 p-enabled scripts/modules can be used – with any logging configuration you desire – by changing loggers, appenders and layouts independently – similar to dtrace probes • No need to change your source code to change the logging behavior

Init and Watch • Log: : Log 4 perl->init(“l 4 p. conf”); • Log: : Log 4 perl->init($conf_string); • Log: : Log 4 perl->init_and_watch(“l 4 p. conf”, 30); • Log: : Log 4 perl->init_and_watch(“l 4 p. conf”, ‘HUP’ );

Demo

Appenders • Appenders are output sinks • Get called if a message passes category and level hurdles

Appenders • Log: : Log 4 perl: : Appender: : Screen Log: : Log 4 perl: : Appender: : File Log: : Log 4 perl: : Appender: : Socket Log: : Log 4 perl: : Appender: : DBI Log: : Log 4 perl: : Appender: : Synchronized Log: : Log 4 perl: : Appender: : RRDs • Log: : Dispatch provides even more:

Log: : Dispatch Appenders • Log: : Dispatch: : Apache. Log: : Dispatch: : DBI, Log: : Dispatch: : Email: : MIMELite Log: : Dispatch: : File. Rotate Log: : Dispatch: : Screen Log: : Dispatch: : Syslog, Log: : Dispatch: : Tk

Example: Rotating Log File Appender • Keep 5 days of logfiles, then delete: log 4 perl. category = WARN, Logfile log 4 perl. appender. Logfile = Log: : Dispatch: : File. Rotate log 4 perl. appender. Logfilename = test. log 4 perl. appender. Logfile. max = 5 log 4 perl. appender. Logfile. Date. Pattern = yyyy-MM-dd log 4 perl. appender. Logfile. TZ = PST log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Rotating Files • Rotating File Appender: – Log: : Dispatch: : File. Rotate – Single request pays for rotation – Rotation runs as particular user • External Rotators (e. g. newsyslog): – recreate flag makes sure file appender adjusts – recreate_check_interval saves on stat() calls

Layouts • Simple. Layout log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen log 4 perl. appender. Screen. layout = Simple. Layout $log->debug(“Sending Mail”); DEBUG – Sending Mail

Layouts • Pattern. Layout log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Pattern. Layout log 4 perl. appender. Logfile. layout. Conversion. Pattern = %d %F{1}: %L> %m %n $log->debug(“Sending Mail”); 2004/10/17 18: 47: 25 l 4 ptest. pl: 25> Sending Mail

Layouts • Pattern. Layout %T stack trace %c Category of the logging event. %C Fully qualified package (or class) name of the caller %d Current date in yyyy/MM/dd hh: mm: ss format %F File where the logging event occurred %H Hostname %l calling method + file + line %L Line number within the file where the log statement was issued %m The message to be logged %M Method or function where the logging request was issued %n Newline (OS-independent) %p Priority of the logging event %P pid of the current process %r Number of milliseconds elapsed from program start %x The elements of the NDC stack %X{key} The entry 'key' of the MDC %% A literal percent (%) sign

Layouts • Still not enough? Write your own: log 4 perl. Pattern. Layout. cspec. U = sub { return "UID $<" } … log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Pattern. Layout log 4 perl. appender. Logfile. layout. Conversion. Pattern = %d %U> %m %n

Speed

Benchmarks • 1 M/sec suppressed calls • 50 k/sec logged messages (memory appender) • No degradation with subcategories

Avoid Wasting Cycles for (@super_long_array) { $logger->debug("Element: $_n"); } if($logger->is_debug()) { for (@super_long_array) { $logger->debug("Element: $_n"); } }

Dirty Tricks

Resurrect in a Single File • The : resurrect target uncomments lines starting with ###l 4 p: use Log 4 perl qw(: easy : resurrect); sub foo { # … ###l 4 p DEBUG “foo was here”; }

Resurrect L 4 p in all Modules • The Log: : Log 4 perl: : Resurrector touches all subsequently loaded modules (experimental!): use Log 4 perl qw(: easy); use Log: : Log 4 perl: : Resurrector; use Foo: : Bar; # Deploy a module without requiring L 4 p at all! package Foo: : Bar; ###l 4 p use Log 4 perl qw(: easy); sub foo { ###l 4 p DEBUG “This will be resurrected!”; }

The Future

Wouldn’t it be nice … • … if all modules on CPAN had a standard logging interface?

Log 4 perl-enable a CPAN Module package Foo; sub foo { # … do something } 1;

Log 4 perl-enable a CPAN Module package Foo; use Log: : Log 4 perl qw(: easy); sub foo { # … do something DEBUG “Fooing $bar”; } 1;

… and voila, your CPAN module has a built-in remote.

Be Open • Let other people debug your module in a standard way.

Q&A

Thank You! Log: : Log 4 perl Project Page (includes slides of this talk): http: /log 4 perl. com Email me: Mike Schilli cpan@perlmeister. com