Smart Logging With Log 4 perl Mike Schilli

Smart Logging With Log 4 perl Mike Schilli, Yahoo! YAPC, 06/27/2007 Grab A T-Shirt!

Smart Logging With Log 4 perl Mike Schilli, Yahoo! YAPC, 06/27/2007

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

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. 11 (06/2007) 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, …)

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

Why Log 4 perl and not one of the 20 Logging modules on CPAN? • Write once, and L 4 p-enabled scripts/modules can be used – with any logging configuration you desire – by changing loggers, appenders and layouts independently • Target specific areas of your application only • No need to change your source code to change the logging behaviour • Log 4 perl is aimed to be the last logging module you’ll ever install

Log: : Log 4 perl for Simple Scripts #!/usr/bin/perl –w use strict; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init($INFO); DEBUG "Won't make it"; INFO "Will go through"; ERROR "Will also go through"; $ easy. pl 2004/10/19 10: 56 Will go through 2004/10/19 10: 56 Will also go through

Log: : Log 4 perl for CPAN Modules use strict; use Your. CPANModule; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init( $INFO ); Your. CPANModule: : somefunc(); package Your. CPANModule; use strict; use Log: : Log 4 perl qw(: easy); sub somefunc { DEBUG "Won't make it"; INFO "Will go through"; }

Log: : Log 4 perl for CPAN Modules use strict; use Your. CPANModule; Your. CPANModule: : somefunc(); package Your. CPANModule; use strict; use Log: : Log 4 perl qw(: easy); sub somefunc { DEBUG "Won't make it"; INFO "Won’t make it"; }

Log: : Log 4 perl Building Blocks Loggers Layouts Appenders

Log: : Log 4 perl Building Blocks Loggers Log it or suppress it Layouts Format it Appenders Write it out

Log: : Log 4 perl Building Blocks Loggers DEBUG “Starting up”); or my $log = get_logger(); $log->debug(“Starting up”); Layouts Appenders “Starting up” => 2007 -06 -21 07: 30: 33 Foo. pm-123 Starting up Log File Database …

Easy vs. Standard Mode use Log: : Log 4 perl qw(: easy); sub somefunc { DEBUG “Debug Message”; INFO “Info Message”; } use Log: : Log 4 perl qw(get_logger); sub somefunc { my $logger = get_logger(); $logger->debug(“Debug message”); $logger->info(“Info message”); }

Log 4 perl Operation • Initialize once, at startup: – Define which loggers should fire base on • message priority (DEBUG, INFO, …) • location (Foo: : Bar, …) – Define where messages should end up at • Loggers planted in program code get activated

Easy Init vs. Standard Init use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init($INFO); use Log: : Log 4 perl; Log: : Log 4 perl->init(“l 4 p. conf”); #l 4 p. conf log 4 perl. category = INFO, Screen log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen log 4 perl. appender. Screen. stderr = 1 log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Mix&Match: Standard Init with Easy Functions use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Debug Message”; INFO “Info Message”; #l 4 p. conf log 4 perl. category = WARN, Logfile log 4 perl. appender. Logfile = Log: : Log 4 perl: : Appender: : File log 4 perl. appender. Logfilename = test. log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Mix and Match Easy Mode Standard DEBUG(…) Mode get_logg er() easy_ini OK t() OK init() OK OK

Categories or: What the hell does this logo mean?

Categories: Areas of your App package Bar: : Twix; use Log: : Log 4 perl qw(get_logger); sub eat { # Gets a Bar: : Twix logger my $logger = get_logger(); $logger->debug(“Debug Message”); } #l 4 p. conf log 4 perl. category. Bar. Twix = WARN, Logfile log 4 perl. appender. Logfile = Log: : Log 4 perl: : Appender: : File log 4 perl. appender. Logfilename = test. log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Categories (Easy Mode) package Bar: : Twix; use Log: : Log 4 perl qw(: easy); sub eat { # Has a Bar: : Twix logger DEBUG “Debug Message”; } #l 4 p. conf log 4 perl. category. Bar. Twix = WARN, Logfile log 4 perl. appender. Logfile = Log: : Log 4 perl: : Appender: : File log 4 perl. appender. Logfilename = test. log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Loggers • Have a – category (e. g. “Net: : Amazon” ) – priority (e. g. $DEBUG ) • Take a message (e. g. “Starting” )

Loggers • Pass on their message if – logging has been configured for • their category ( “Net: : Amazon”) or • a parent category ( “Net”, “” ) – and (!) the message priority (e. g. $DEBUG) is greater or equal than the configured log level (e. g. $DEBUG) for the category

Limit Throughput: Levels and Categories • Categories determine which parts of the system are addressed. my $log = get_logger(“Net: : Amazon”); or simply package Net: : Amazon; DEBUG “…”; • Levels indicate the message priority. $log->debug(“Request sent ($bytes)”;

Log Levels • Levels – – – – $TRACE $DEBUG $INFO $WARN $ERROR $FATAL $OFF

Log Levels • Methods – – – $log->trace(“$bytes transferred”); $log->debug(“HTTP get OK”); $log->info(“Starting up”); $log->warn(“HTTP get failed, retrying”); $log->error(“Out of retries!”); $log->fatal(“Panic! Shutting down. ”);

Log Levels • Macros – 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 via Categories l 4 p. conf log 4 perl. category = DEBUG, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Makes it through!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Makes it through”;

Remote Control via Categories l 4 p. conf Log 4 perl. category = ERROR, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Gets blocked!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Gets blocked”;

Remote Control via Categories l 4 p. conf Log 4 perl. category = FATAL, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Gets blocked!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Gets blocked!”; DEBUG “Gets blocked”;

Remote Control via Categories l 4 p. conf Log 4 perl. category. main = DEBUG, Screen Log 4 perl. category. Net. Amazon = ERROR, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Makes it through!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Gets blocked”;

Remote Control via Categories l 4 p. conf Log 4 perl. category. main = ERROR, Screen Log 4 perl. category. Net. Amazon = DEBUG, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Gets blocked”; my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Makes it through!”;

Category Inheritance (1) l 4 p. conf Log 4 perl. category. main Log 4 perl. category. Net = DEBUG, Screen = ERROR, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Makes it through!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Gets blocked”;

Category Inheritance (2) l 4 p. conf Log 4 perl. category. main = DEBUG, Screen Log 4 perl. category = ERROR, Screen #!/usr/bin/perl use Net: : Amazon; Log: : Log 4 perl->init(“l 4 p. conf”); DEBUG “Makes it through!” my $amzn = Net: : Amazon->new(); package Net: : Amazon; ERROR “Makes it through!”; DEBUG “Gets blocked”;

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

l 4 p. conf: Screen Appender log 4 perl. category. main = DEBUG, Screen Log 4 perl. category. Net. Amazon = INFO, Screen log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen …

l 4 p. conf: File Appender log 4 perl. category. main = DEBUG, Logfile Log 4 perl. category. Net. Amazon = INFO, Logfile log 4 perl. appender. Logfile = Log: : Log 4 perl: : Appender: : File log 4 perl. appender. Logfilename = test. log …

l 4 p. conf: Two appenders log 4 perl. category. main = DEBUG, Logfile Log 4 perl. category. Net. Amazon = INFO, Screen log 4 perl. appender. Logfile = Log: : Log 4 perl: : Appender: : File log 4 perl. appender. Logfilename = test. log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen …

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

Write Your Own Appender (1) package Color. Screen. Appender; our @ISA = qw(Log: : Log 4 perl: : Appender); use Term: : ANSIColor; sub new { my($class, %options) = @_; my $self = {%options, …}; bless $self, $class; } sub log { my($self, %params) = @_; print colored($params{message}, $self->{color}); }

Write Your Own Appender (2) log 4 perl. logger = INFO, Color. App log 4 perl. appender. Color. App=Color. Screen. Appender log 4 perl. appender. Color. App. color = red log 4 perl. appender. Color. App. layout = Simple. Layout

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 %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

Filters • Last minute chance for Appenders to block • More expensive than Level/Category blocking • Text/Level Match comes with L 4 p • Write your own custom filters

Filters log 4 perl. category = INFO, Screen log 4 perl. filter. My. Filter = Log: : Log 4 perl: : Filter: : String. Match log 4 perl. filter. M 1. String. To. Match = let this through log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen log 4 perl. appender. Screen. Filter = My. Filter log 4 perl. appender. Screen. layout = Log: : Log 4 perl: : Layout: : Simple. Layout

Filters log 4 perl. filter. M 1 = Log: : Log 4 perl: : Filter: : String. Match log 4 perl. filter. M 1. String. To. Match = let this through log 4 perl. filter. M 1. Accept. On. Match = true log 4 perl. filter. M 1 = Log: : Log 4 perl: : Filter: : Level. Match log 4 perl. filter. M 1. Level. To. Match = INFO log 4 perl. filter. M 1. Accept. On. Match = true

Speed

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

Performance • On a Pentium 4 Linux box at 2. 4 GHz, you'll get through – 500, 000 suppressed log statements per second – 30, 000 logged messages per second (using an in-memory appender) – init_and_watch delay mode: 300, 000 suppressed, 30, 000 logged. – init_and_watch signal mode: 450, 000 suppressed, 30, 000 logged.

Advanced Trickery

Infiltrating LWP • Ever wondered what LWP is doing behind the scenes? use LWP: : User. Agent; use HTTP: : Request: : Common; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init($DEBUG); Log: : Log 4 perl->infiltrate_lwp(); my $ua = LWP: : User. Agent->new(); my $resp = $ua->request(GET "http: //www. yahoo. com");

Infiltrating LWP • Getting LWP to use Log 4 perl for logging: 2004/10/20 18: 36: 43 () 2004/10/20 18: 36: 43 GET http: //www. yahoo. com 2004/10/20 18: 36: 43 Not proxied 2004/10/20 18: 36: 43 () 2004/10/20 18: 36: 43 read 634 bytes 2004/10/20 18: 36: 43 read 4096 bytes … 2004/10/20 18: 36: 43 read 2488 bytes 2004/10/20 18: 36: 43 Simple response: OK

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!”; }

Pitfalls Beginner’s Pitfalls

Beginner’s Pitfalls • Appender Additivity: – Once a lower level logger decides to fire, it will forward the message to its appenders. – It will also forward the message unconditionally to all of its parent logger’s appenders.

Beginner’s Pitfalls • Appender Additivity (with dupes) log 4 perl. category = FATAL, Screen log 4 perl. category. Net. Amazon = DEBUG, Screen log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen log 4 perl. appender. Screen. layout = Simple. Layout package Net: : Amazon; DEBUG(“Debugging!”); DEBUG - Debugging!

Appender Additivity File Appender root FATAL Screen Appender Net: : Amazon DEBUG

Beginner’s Pitfalls • Appender Additivity (no dupes) log 4 perl. category = ERROR, Screen log 4 perl. category. Net. Amazon = DEBUG, Screen log 4 perl. additivity. Net. Amazon = 0 log 4 perl. appender. Screen = Log: : Log 4 perl: : Appender: : Screen log 4 perl. appender. Screen. layout = Simple. Layout package Net: : Amazon; DEBUG(“Debugging!”); DEBUG – Debugging! Q

Log: : Log 4 perl Availability • Cpan> install Log: : Log 4 perl – Only requires core modules • Requires Perl 5. 00503 or better • Included in major Linux distros • Windows: ppm package available in Active. State archives or from log 4 perl. sf. net

Best Practices • Don’t provide program name, function name in the message. Use Layouts instead. • Log plenty. Don’t worry about space, use rotating log files for chatty output.

What you should log • • Program starting up, shutting down Function parameters Milestones in request processing Start/end of lenghty operations (e. g. DB access)

What you shouldn’t log • Function/method names (although you want parameters) • Date • Process ID • … everything else provided by the layout

Best Practices • Rolling out new L 4 p-enabled Modules package My: : Module; use Log: : Log 4 perl qw(: easy); sub new { # … } sub foo { DEBUG “I’m here”; # … } sub bar { INFO “Now I’m here”; # … } # Use w/o Log 4 perl use My: : Module; $o = My: : Module->new(); $o->foo(); # Log 4 perl enabled use My: : Module; use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init($DEBUG); $o = My: : Module->new(); $o->foo();

Gotchas • Avoid ‘append’ on NFS (creating lots of ‘read’ traffic) • Don’t put expensive operations into the logger call which are executed before the logger decides • Permission issues with rotating file appenders

mod_perl • Init() in startup handler • Current limitation: One init(). • Use init_once() if you’re not sure who inits first.

Combat overlapping Messages • Either live with it or – Use the Synchronized appender – Use Appender. File. syswrite=1

Driving Log: : Log 4 perl further • Bug Fixes: Submit to log 4 perl-devel@sourceforge. net • New Features: Propose features or send patches • New Appenders: Release separately as a module in the Log: : Log 4 perl: : Appender: : xx namespace on CPAN • … or contact me: mschilli@yahoo-inc. com

Q&A

Thank You! Log: : Log 4 perl Project Page: http: //log 4 perl. sourceforge. net Email me: Mike Schilli mschilli@yahoo-inc. com Post to the List: log 4 perl-devel@sourceforge. net

Bonus Slides

Error Handling use Log: : Log 4 perl qw(: easy); do_something or LOGDIE “Horrible error!”; • LOGCARP, LOGCLUCK, LOGCONFESS etc. also available.

Displaying Logs with Chainsaw • Log 4 j features an XML layout and a socket appender • XML output is displayed in a nice GUI called Chainsaw • Log: : Log 4 perl also features an XML layout and a socket appender • … XML output is also displayed in a nice GUI called Chainsaw!

Displaying Logs with Chainsaw Log: : Log 4 perl enabled Perl Script Log: : Log 4 perl: : Layout: : XML Log: : Log 4 perl: : Appender: : Socket Java / log 4 j Program

Displaying Logs with Chainsaw

The Future • Allow multiple configurations within the same process (e. g. for mod_perl)

Easy Mode Init with Files use Log: : Log 4 perl qw(: easy); Log: : Log 4 perl->easy_init({ level => $DEBUG, file => “>file. log”, category => “Bar: : Twix”, });

Multiline Layout Instead of 2007/04/04 23: 59: 01 This is a message with multiple lines get this: 2007/04/04 23: 59: 01 This is 2007/04/04 23: 59: 01 a message with 2007/04/04 23: 59: 01 multiple lines with Pattern. Layout: : Multiline: log 4 perl. appender. Logfile. layout = Log: : Log 4 perl: : Layout: : Pattern. Layout: : Multiline log 4 perl. appender. Logfile. layout. Conversion. Pattern = %d %m %n

Perl Hooks • Add parameters known at init() time log 4 perl. appender. Logfilename = sub { “mylog. $$. log” }