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 mschilli_at_yahoo-inc.com

77
Dont forget to submit a Review!

• Go to the OSCON schedule, click on this talk and
  then rate this talk
• Thanks!

78
Bonus Slides
79
Advanced Trickery
80
Infiltrating LWP

• Ever wondered what LWP is doing behind the scenes?

use LWPUserAgent use HTTPRequestCommon us
e LogLog4perl qw(easy) LogLog4perl-gteasy_in
it(DEBUG) LogLog4perl-gtinfiltrate_lwp() my
ua LWPUserAgent-gtnew() my resp
ua-gtrequest(GET "http//www.yahoo.com")
81
Infiltrating LWP

• Getting LWP to use Log4perl for logging

2004/10/20 183643 () 2004/10/20 183643
() 2004/10/20 183643 GET http//www.yahoo.com 20
04/10/20 183643 Not proxied 2004/10/20 183643
() 2004/10/20 183643 read 634 bytes 2004/10/20
183643 read 4096 bytes 2004/10/20 183643
read 2488 bytes 2004/10/20 183643 Simple
response OK
82
Pitfalls
Beginners Pitfalls
83
Beginners 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 loggers appenders.

84
Beginners Pitfalls

• Appender Additivity (with dupes)

log4perl.category FATAL, Screen log4perl.categor
y.Net.Amazon DEBUG, Screen log4perl.appender.Sc
reen \ LogLog4perlAppenderScreen log4p
erl.appender.Screen.layout SimpleLayout
package NetAmazon DEBUG(Debugging!)
DEBUG - Debugging! DEBUG - Debugging!
85
Appender Additivity
File Appender
root
FATAL
Screen Appender
Net
NetAmazon
DEBUG
86
Beginners Pitfalls

• Appender Additivity (no dupes)

log4perl.category ERROR,
Screen log4perl.category.Net.Amazon DEBUG,
Screen log4perl.additivity.Net.Amazon 0
log4perl.appender.Screen \
LogLog4perlAppenderScreen log4perl.appender.
Screen.layout SimpleLayout
package NetAmazon DEBUG(Debugging!)
Q
DEBUG Debugging!
87
Write Your Own Appender (1)
package ColorScreenAppender our _at_ISA
qw(LogLog4perlAppender) use
TermANSIColor sub new my(class,
options) _at__ my self options,
bless self, class sub log my(self,
params) _at__ print colored(paramsmessage,
self-gtcolor)
88
Write Your Own Appender (2)
log4perl.logger INFO, ColorApp
log4perl.appender.ColorAppColorScreenAppender
log4perl.appender.ColorApp.color red
log4perl.appender.ColorApp.layout SimpleLayout
89
Filters

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

90
Filters
log4perl.category INFO, Screen
log4perl.filter.MyFilter \
LogLog4perlFilterStringMatch log4perl.filter
.M1.StringToMatch let this through log4perl.app
ender.Screen \ LogLog4perlAppenderScree
n log4perl.appender.Screen.Filter MyFilter
log4perl.appender.Screen.layout \
LogLog4perlLayoutSimpleLayout
91
Filters
log4perl.filter.M1 LogLog4perlFilterString
Match log4perl.filter.M1.StringToMatch let this
through log4perl.filter.M1.AcceptOnMatch true
log4perl.filter.M1 LogLog4perlFilterLevelM
atch log4perl.filter.M1.LevelToMatch INFO
log4perl.filter.M1.AcceptOnMatch true
92
Best Practices

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

93
What you should log

• Program starting up, shutting down
• Function parameters
• Milestones in request processing
• Start/end of lenghty operations (e.g. DB access)
• result of called function (logged in calling
  function)

94
What you shouldnt log

• Function/method names (although you want
  parameters)
• Date
• Process ID
• everything else provided by the layout

95
Error Handling

• use LogLog4perl qw(easy)
• do_something or
• LOGDIE Horrible error!
• LOGCARP, LOGCLUCK, LOGCONFESS etc. also available.

96
Best Practices

• Rolling out new L4p-enabled Modules

package MyModule use LogLog4perl
qw(easy) sub new sub foo DEBUG Im
here sub bar INFO Now Im here
Use w/o Log4perl use MyModule o
MyModule-gtnew() o-gtfoo()
Log4perl enabled use MyModule use
LogLog4perl qw(easy) LogLog4perl-gteasy_init(
DEBUG) o MyModule-gtnew() o-gtfoo()
97
Gotchas

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

98
mod_perl

• Init() in startup handler
• Current limitation One init().
• Use init_once() if youre not sure who inits
  first.

99
Combat overlapping Messages

• Either live with it or
• Use the Synchronized appender
• Use Appender.File.syswrite1

100
Driving LogLog4perl further

• Bug Fixes
• Submit to log4perl-devel_at_sourceforge.net
• New Features
• Propose features or send patches
• New Appenders
• Release separately as a module in the
  LogLog4perlAppenderxx namespace on CPAN
• or contact me mschilli_at_yahoo-inc.com

101
Easy Mode Init with Files

• use LogLog4perl qw(easy)
• LogLog4perl-gteasy_init(
• level gt DEBUG,
• file gt gtfile.log,
• category gt BarTwix,
• )

102
Multiline Layout

• Instead of
• 2007/04/04 235901 This is
• a message with
• multiple lines
• get this
• 2007/04/04 235901 This is
• 2007/04/04 235901 a message with
• 2007/04/04 235901 multiple lines
• with PatternLayoutMultiline
• log4perl.appender.Logfile. layout \
• LogLog4perlLayoutPatternLayoutMult
  iline
• log4perl.appender.Logfile.layout.ConversionPattern
  d m n

103
Perl Hooks

• Add parameters known at init() time
• log4perl.appender.Logfile.filename sub \
• mylog..log

104
Loggers

• Have a
• category (e.g. NetAmazon )
• priority (e.g. DEBUG )
• Take a message (e.g. Starting )

105
Loggers

• Pass on their message if
• logging has been configured for
• their category ( NetAmazon) 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

106
Limit Throughput Levels and Categories

• Categories determine which parts of the system
  are addressed.
• my log get_logger(NetAmazon)
• or simply
• package NetAmazon
• DEBUG
• Levels indicate the message priority.
• log-gtdebug(Request sent (bytes bytes)

107
Displaying Logs with Chainsaw

• Log4j features an XML layout and a socket
  appender
• XML output is displayed in a nice GUI called
  Chainsaw
• LogLog4perl also features an XML layout and a
  socket appender
• XML output is also displayed in a nice GUI
  called Chainsaw!

108
Displaying Logs with Chainsaw
LogLog4perl enabled Perl Script
LogLog4perlLayoutXML
LogLog4perlAppenderSocket
Java / log4j Program
109
Displaying Logs with Chainsaw