Smart Logging With Log4perl

1
Smart Logging With Log4perl

• Mike Schilli, Yahoo!
• YAPC, 06/27/2007

Grab A T-Shirt!
2
Smart Logging With Log4perl

• Mike Schilli, Yahoo!
• YAPC, 06/27/2007

3
Logging why?

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

4
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

5
Log4perl 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,
  NetAmazon, )

6
Log4perl Release History
7
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

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

• Write once, and L4p-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
• Log4perl is aimed to be the last logging module
  youll ever install

9
LogLog4perl for Simple Scripts
!/usr/bin/perl w use strict use LogLog4perl
qw(easy) LogLog4perl-gteasy_init(INFO) DEBU
G "Won't make it" INFO "Will go through" ERROR
"Will also go through"
easy.pl 2004/10/19 105656 Will go
through 2004/10/19 105656 Will also go through
10
LogLog4perl for CPAN Modules
use strict use YourCPANModule use LogLog4perl
qw(easy) LogLog4perl-gteasy_init( INFO
) YourCPANModulesomefunc()
package YourCPANModule use strict use
LogLog4perl qw(easy) sub somefunc DEBUG
"Won't make it" INFO "Will go through"
11
LogLog4perl for CPAN Modules
use strict use YourCPANModule YourCPANModule
somefunc()
package YourCPANModule use strict use
LogLog4perl qw(easy) sub somefunc DEBUG
"Won't make it" INFO "Wont make it"
12
LogLog4perl Building Blocks
Loggers
Layouts
Appenders
13
LogLog4perl Building Blocks
Loggers
Log it or suppress it
Layouts
Format it
Appenders
Write it out
14
LogLog4perl Building Blocks
DEBUG Starting up) or my log
get_logger() log-gtdebug(Starting up)
Loggers
Layouts
Starting up gt 2007-06-21 073033 Foo.pm-123
Starting up

Appenders
Log File
Database
15
Easy vs. Standard Mode
use LogLog4perl qw(easy) sub somefunc
DEBUG Debug Message INFO Info Message
use LogLog4perl qw(get_logger) sub somefunc
my logger get_logger()
logger-gtdebug(Debug message)
logger-gtinfo(Info message)
16
Log4perl Operation

• Initialize once, at startup
• Define which loggers should fire base on
• message priority (DEBUG, INFO, )
• location (FooBar, )
• Define where messages should end up at
• Loggers planted in program code get activated

17
Easy Init vs. Standard Init
use LogLog4perl qw(easy) LogLog4perl-gteasy_
init(INFO)
use LogLog4perl LogLog4perl-gtinit(l4p.conf
)
l4p.conf log4perl.category INFO,
Screen log4perl.appender.Screen \
LogLog4perlAppenderScreen
log4perl.appender.Screen.stderr 1
log4perl.appender.Logfile.layout \
LogLog4perlLayoutSimpleLayout
18
MixMatch Standard Init with Easy Functions
use LogLog4perl qw(easy) LogLog4perl-gtinit(
l4p.conf) DEBUG Debug Message INFO Info
Message
l4p.conf log4perl.category WARN, Logfile
log4perl.appender.Logfile \
LogLog4perlAppenderFile log4perl.appender.L
ogfile.filename test.log log4perl.appender.Logf
ile.layout \ LogLog4perlLayoutSimpleL
ayout
19
Mix and Match
Easy Mode DEBUG() Standard Mode get_logger()
easy_init() OK OK
init() OK OK
20
Categories or What the hell does this logo mean?
21
Categories Areas of your App
package BarTwix use LogLog4perl
qw(get_logger) sub eat Gets a
BarTwix logger my logger get_logger()
logger-gtdebug(Debug Message)
l4p.conf log4perl.category.Bar.Twix WARN,
Logfile log4perl.appender.Logfile \
LogLog4perlAppenderFile log4perl.appender.L
ogfile.filename test.log log4perl.appender.Logf
ile.layout \ LogLog4perlLayoutSimpleL
ayout
22
Categories (Easy Mode)
package BarTwix use LogLog4perl
qw(easy) sub eat Has a BarTwix
logger DEBUG Debug Message
l4p.conf log4perl.category.Bar.Twix WARN,
Logfile log4perl.appender.Logfile \
LogLog4perlAppenderFile log4perl.appender.L
ogfile.filename test.log log4perl.appender.Logf
ile.layout \ LogLog4perlLayoutSimpleL
ayout
23
Loggers

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

24
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

25
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)

26
Log Levels

• Levels
• TRACE
• DEBUG
• INFO
• WARN
• ERROR
• FATAL
• OFF

27
Log Levels

• Methods
• log-gttrace(bytes bytes transferred)
• log-gtdebug(HTTP get OK)
• log-gtinfo(Starting up)
• log-gtwarn(HTTP get failed, retrying)
• log-gterror(Out of retries!)
• log-gtfatal(Panic! Shutting down.)

28
Log Levels

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

29
Remote Control via Categories

• l4p.conf

log4perl.category DEBUG, Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Makes it
through! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Makes it through
30
Remote Control via Categories

• l4p.conf

Log4perl.category ERROR, Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Gets
blocked! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Gets blocked
31
Remote Control via Categories

• l4p.conf

Log4perl.category FATAL, Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Gets
blocked! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Gets blocked! DEBUG
Gets blocked
32
Remote Control via Categories

• l4p.conf

Log4perl.category.main DEBUG,
Screen Log4perl.category.Net.Amazon ERROR,
Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Makes it
through! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Gets blocked
33
Remote Control via Categories

• l4p.conf

Log4perl.category.main ERROR,
Screen Log4perl.category.Net.Amazon DEBUG,
Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Gets
blocked my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Makes it through!
34
Category Inheritance (1)

• l4p.conf

Log4perl.category.main DEBUG,
Screen Log4perl.category.Net ERROR, Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Makes it
through! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Gets blocked
35
Category Inheritance (2)

• l4p.conf

Log4perl.category.main DEBUG,
Screen Log4perl.category ERROR, Screen
!/usr/bin/perl use NetAmazon
LogLog4perl-gtinit(l4p.conf) DEBUG Makes it
through! my amzn NetAmazon-gtnew()
package NetAmazon ERROR Makes it
through! DEBUG Gets blocked
36
Log4perl Flow
Application sends a log message (Category,
Priority)
Log4perl Configuration decides go/no go, based on
Category and Priority
?
Layout
37
l4p.conf Screen Appender
log4perl.category.main DEBUG, Screen
Log4perl.category.Net.Amazon INFO, Screen
log4perl.appender.Screen \
LogLog4perlAppenderScreen
38
l4p.conf File Appender
log4perl.category.main DEBUG,
Logfile Log4perl.category.Net.Amazon INFO,
Logfile log4perl.appender.Logfile \
LogLog4perlAppenderFile log4perl.appender.Lo
gfile.filename test.log
39
l4p.conf Two appenders
log4perl.category.main DEBUG,
Logfile Log4perl.category.Net.Amazon INFO,
Screen log4perl.appender.Logfile \
LogLog4perlAppenderFile log4perl.appender.Lo
gfile.filename test.log log4perl.appender.Screen
\ LogLog4perlAppenderScreen
40
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
  )

41
Demo
42
Appenders

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

43
Appenders

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

44
LogDispatch Appenders

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

45
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
46
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

47
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)
48
Write Your Own Appender (2)
log4perl.logger INFO, ColorApp
log4perl.appender.ColorAppColorScreenAppender
log4perl.appender.ColorApp.color red
log4perl.appender.ColorApp.layout SimpleLayout
49
Layouts

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

log4perl.appender.Screen \
LogLog4perlAppenderScreen log4perl.appender.
Screen.layout SimpleLayout
50
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
51
Layouts

• PatternLayout

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
52
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
53
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

54
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
55
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
56
Speed
57
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")
58
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.

59
Advanced Trickery
60
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")
61
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
62
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

63
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!

64
Pitfalls
Beginners Pitfalls
65
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.

66
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!
67
Appender Additivity
File Appender
root
FATAL
Screen Appender
Net
NetAmazon
DEBUG
68
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!
69
LogLog4perl Availability

• Cpangt install LogLog4perl
• Only requires core modules
• Requires Perl 5.00503 or better
• Included in major Linux distros
• Windows ppm package available in ActiveState
  archives or from log4perl.sf.net

70
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.

71
What you should log

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

72
What you shouldnt log

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

73
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()
74
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

75
mod_perl

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

76
Combat overlapping Messages

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

77
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

78
Q A

• Q A

79
Thank You!

• LogLog4perl Project Page
• http//log4perl.sourceforge.net
• Email me
• Mike Schilli
• mschilli_at_yahoo-inc.com
• Post to the List
• log4perl-devel_at_sourceforge.net

80
Bonus Slides
81
Error Handling

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

82
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!

83
Displaying Logs with Chainsaw
LogLog4perl enabled Perl Script
LogLog4perlLayoutXML
LogLog4perlAppenderSocket
Java / log4j Program
84
Displaying Logs with Chainsaw
85
The Future

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

86
Easy Mode Init with Files

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

87
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

88
Perl Hooks

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