Log4perl

1
Log4perl

• Mike Schilli, Yahoo!
• OSCON, 07/24/2008

2
Logging why?

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

3
Why Log4perl and not one of the 20 Logging
modules on CPAN?

• No CPAN dependencies
• Easy to use, but scales with complexity
• Unique Features

4
LogLog4perl Availability

• cpangt install LogLog4perl
• (Only requires core modules)
• Included in major Linux distros
• sudo apt-get install liblog-log4perl
• Requires Perl 5.00503 or better
• Windows ppm package available in ActiveState
  archives or from log4perl.com

5
Use Log4perl as a Remote Control to your System.
6
LogLog4perl Remote Controls
Levels
Loggers
Layouts
Appenders
7
LogLog4perl Remote Controls
Levels
Log/Suppress Priority/Level
Loggers
Locate it in the system
Layouts
Format it
Appenders
Write it out
8
LogLog4perl Remote Controls
DEBUG Starting up ERROR Cannot open
file
Levels
Loggers
Turn logging on in main or NetAmazon
Layouts
Starting up gt 2007-06-21 073033 Foo.pm-123
Starting up

Appenders
Log File
Database
9
Sounds complicated?

• Actually, its easy

10
Easy Log4perl

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(easy)
• DEBUG Starting up

11
Dont like macros? Use get_logger()

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(get_logger)
• my logger get_logger()
• logger-gtdebug(Starting up)

12
Like it clean? Use Moose!

• package Ferrari
• use Moose
• with MooseXLogLog4perl
• sub drive
• my(self) _at__
• self-gtlog-gtdebug(Wroom!!)

13
Easy Log4perl

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(easy)
• DEBUG Starting up

14
Easy Log4perl

• ./hello

15
Easy Log4perl

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(easy)
• LogLog4perl-gteasy_init( DEBUG )
• DEBUG Starting up

16
Easy Log4perl

• ./hello
• 2008/07/08 183712 Starting up

17
Easy Log4perl

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(easy)
• LogLog4perl-gteasy_init( DEBUG )
• DEBUG Starting up
• something happens
• ERROR Horrible error!

18
Easy Log4perl

• ./hello
• 2008/07/08 183712 Starting up
• 2008/07/08 183712 Horrible error!

19
Easy Log4perl

• !/usr/bin/perl w
• use strict
• use LogLog4perl qw(easy)
• LogLog4perl-gteasy_init( ERROR )
• DEBUG Starting up
• ERROR Horrible error!

20
Easy Log4perl

• ./hello
• 2008/07/08 183712 Horrible error!

21
Remote Control 1 Levels
22
You get the concept
FATAL ERROR WARNING INFO DEBUG TRACE
FATAL ERROR WARNING INFO DEBUG TRACE
Log Level Configured
Message Priority
23
Chatty configuration
FATAL ERROR WARNING INFO DEBUG TRACE
TRACE
Log Level Configured
Message Priority
24
Silent configuration

• ERROR

FATAL ERROR WARNING INFO DEBUG TRACE
Log Level Configured
Message Priority
25
Log Levels

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

26
Remote Control 2 Layouts
27
Location-Awareness

• Log4perls Loggers are aware of their location
• package Foo
• use LogLog4perl qw(easy)
• sub foo
• DEBUG Starting up

28
Location-Awareness

• package Foo
• use LogLog4perl qw(easy)
• sub foo
• DEBUG Starting up
• ./hello
• 2008/07/13 193239 Starting up

29
Location-Awareness

• package Foo
• use LogLog4perl qw(easy)
• sub foo
• DEBUG Starting up
• ./hello
• 637 Foofoo ./Foo.pm-4gt Starting up

30
Location-Awareness

• package main
• use LogLog4perl (easy)
• LogLog4perl-gteasy_init(
• level gt DEBUG,
• layout gt r M F-Lgt mn,
• )
• Foofoo() unchanged!
• ./hello
• 637 Foofoo ./Foo.pm-4gt Starting up

31
Configuration Files

• If this becomes unwieldy
• LogLog4perl-gteasy_init(
• level gt DEBUG,
• layout gt r M F-Lgtmn,
• )

32
Configuration Files
l4p.conf l4p.logger DEBUG, Screen l4p.appender
.Screen LogLog4perlAppenderScreen l4p.appe
nder.Screen.Layout PatternLayout l4p.appender.Sc
reen.Layout.ConversionPattern \
r M F-Lgt mn
LogLog4perl-gtinit( l4p.conf )
33
Advantages of Config Files

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

34
Remote Control 3 Categories (Loggers)
35
Turn on Logging Everywhere
Script
l4p.logger DEBUG, Screen
Modules
36
Using Categories
Script
l4p.logger.Net.Amazon \
DEBUG, Screen
Modules
NetAmazon
37
Using Categories
Script
main
l4p.logger.main \ DEBUG,
Screen
Modules
NetAmazon
38
Using Categories
l4p.logger.main DEBUG, Screen l4p.logger.Net.Ama
zon \ DEBUG, Screen
Modules
39
Categories
l4p.conf l4p.logger.main DEBUG,
Screen l4p.logger.Net.Amazon DEBUG,
Screen l4p.appender.Screen LogLog4perlAppen
derScreen l4p.appender.Screen.Layout
PatternLayout l4p.appender.Screen.Layout.Conversio
nPattern \
r M F-Lgt mn
40
Category Inheritance
l4p.conf l4p.logger.Net DEBUG,
Screen l4p.appender.Screen LogLog4perlAppen
derScreen l4p.appender.Screen.Layout
PatternLayout l4p.appender.Screen.Layout.Conversio
nPattern \
r M F-Lgt mn
41
Remote Control 5 Appenders
42
Root Logger
l4p.conf l4p.logger DEBUG, Screen l4p.appender
.Screen LogLog4perlAppenderScreen l4p.appe
nder.Screen.Layout PatternLayout l4p.appender.Sc
reen.Layout.ConversionPattern \
r M F-Lgt mn
43
Multiple Appenders
l4p.conf l4p.logger.main DEBUG,
Screen l4p.logger.Net.Amazon DEBUG,
File l4p.appender.Screen LogLog4perlAppende
rScreen l4p.appender.Screen.Layout
SimpleLayout l4p.appender.File
LogLog4perlAppenderFile l4p.appender.File.fi
lename /var/log/myapp.log l4p.appender.File.Layo
ut PatternLayout l4p.appender.File.Layout.Conver
sionPattern \
r M F-Lgt mn
44
Multiple Appenders (different log levels)
l4p.conf l4p.logger.main DEBUG,
Screen l4p.logger.Net.Amazon ERROR,
File l4p.appender.Screen LogLog4perlAppende
rScreen l4p.appender.Screen.Layout
SimpleLayout l4p.appender.File
LogLog4perlAppenderFile l4p.appender.File.fi
lename /var/log/myapp.log l4p.appender.File.Layo
ut PatternLayout l4p.appender.File.Layout.Conver
sionPattern \
r M F-Lgt mn
45
Multiple Appenders
l4p.conf l4p.logger.main DEBUG, Screen,
File l4p.appender.Screen LogLog4perlAppende
rScreen l4p.appender.Screen.Layout
SimpleLayout l4p.appender.File
LogLog4perlAppenderFile l4p.appender.File.fi
lename /var/log/myapp.log l4p.appender.File.Layo
ut PatternLayout l4p.appender.File.Layout.Conver
sionPattern \
r M F-Lgt mn
Screen
File
46
Log4perl Flow
Application sends a log message (Category,
Priority)
Log4perl Configuration decides go/no go, based on
Category and Priority
?
Layout
47
Log4perl and Log4j

• LogLog4perl ports Log4j to Perl
• Log4j de facto Java logging standard, by Ceki
  Gülcü
• Latest development logback
• http//logging.apache.org/log4j
• LogLog4perl adds perlisms demanded by users

48
Log4perl 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,
  NetAmazon, )
• Every major Linux distro has it (Ubuntu, Suse,
  Fedora )

49
Log4perl Release History
50
Design Goals

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

51
Combine Remote Controls

• Write code once, and L4p-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

52
Init and Watch

• LogLog4perl-gtinit(l4p.conf)
• LogLog4perl-gtinit(\conf_string)
• LogLog4perl-gtinit_and_watch(l4p.conf, 30)
• LogLog4perl-gtinit_and_watch(l4p.conf, HUP
  )

53
Demo
54
Appenders

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

55
Appenders

• LogLog4perlAppenderScreen
  LogLog4perlAppenderFile LogLog4perlAppen
  derSocket LogLog4perlAppenderDBI
  LogLog4perlAppenderSynchronized
  LogLog4perlAppenderRRDs
• LogDispatch provides even more

56
LogDispatch Appenders

• LogDispatchApacheLog LogDispatchDBI,
  LogDispatchEmail, LogDispatchEmailMIMELi
  te LogDispatchFile LogDispatchFileRotate
  LogDispatchScreen LogDispatchSyslog,
  LogDispatchTk

57
Example Rotating Log File Appender

• Keep 5 days of logfiles, then delete

log4perl.category WARN, Logfile
log4perl.appender.Logfile LogDispatchFileRo
tate log4perl.appender.Logfile.filename
test.log log4perl.appender.Logfile.max
5 log4perl.appender.Logfile.DatePattern
yyyy-MM-dd log4perl.appender.Logfile.TZ
PST log4perl.appender.Logfile.layout \
LogLog4perlLayoutSimpleLayout
58
Rotating Files

• Rotating File Appender
• LogDispatchFileRotate
• 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

59
Layouts

• SimpleLayout
• log-gtdebug(Sending Mail)
• DEBUG Sending Mail

log4perl.appender.Screen \
LogLog4perlAppenderScreen log4perl.appender.
Screen.layout SimpleLayout
60
Layouts

• PatternLayout
• log-gtdebug(Sending Mail)
• 2004/10/17 184725 l4ptest.pl25gt Sending Mail

log4perl.appender.Logfile.layout \
LogLog4perlLayoutPatternLayout
log4perl.appender.Logfile.layout.ConversionPatter
n \ d
F1Lgt m n
61
Layouts

• PatternLayout

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
hhmmss 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 Xkey The entry 'key' of the
MDC A literal percent () sign
62
Layouts

• Still not enough? Write your own

log4perl.PatternLayout.cspec.U sub return
"UID lt" log4perl.appender.Logfile.layout
\ LogLog4perlLayoutPatternLayout
log4perl.appender.Logfile.layout.ConversionPatter
n \ d Ugt
m n
63
Speed
64
Benchmarks

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

65
Avoid Wasting Cycles
for (_at_super_long_array) logger-gtdebug("Ele
ment _\n")
if(logger-gtis_debug()) for
(_at_super_long_array) logger-gtdebug("Ele
ment _\n")
66
Dirty Tricks
67
Resurrect in a Single File

• The resurrect target uncomments lines starting
  with l4p
• use Log4perl qw(easy resurrect)
• sub foo
• l4p DEBUG foo was here

68
Resurrect L4p in all Modules

• The LogLog4perlResurrector touches all
  subsequently loaded modules (experimental!)
• use Log4perl qw(easy)
• use LogLog4perlResurrector
• use FooBar
• Deploy a module without requiring L4p at all!
• package FooBar
• l4p use Log4perl qw(easy)
• sub foo
• l4p DEBUG This will be resurrected!

69
The Future
70
Wouldnt it be nice

• if all modules on CPAN had a standard logging
  interface?

71
Log4perl-enable a CPAN Module

• package Foo
• sub foo
• do something
• 1

72
Log4perl-enable a CPAN Module

• package Foo
• use LogLog4perl qw(easy)
• sub foo
• do something
• DEBUG Fooing bar
• 1

73
and voila, your CPAN module has a built-in
remote.
74
Be Open

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

75
Q A

• Q A

76
Thank You!

• LogLog4perl Project Page (includes slides of
  this talk)
• http/log4perl.com
• Email me
• Mike Schilli cpan_at_perlmeister.com