forked from mschilli/log4perl
-
Notifications
You must be signed in to change notification settings - Fork 0
/
README
2184 lines (1629 loc) · 87.8 KB
/
README
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
######################################################################
Log::Log4perl 1.49
######################################################################
NAME
Log::Log4perl - Log4j implementation for Perl
SYNOPSIS
# Easy mode if you like it simple ...
use Log::Log4perl qw(:easy);
Log::Log4perl->easy_init($ERROR);
DEBUG "This doesn't go anywhere";
ERROR "This gets logged";
# ... or standard mode for more features:
Log::Log4perl::init('/etc/log4perl.conf');
--or--
# Check config every 10 secs
Log::Log4perl::init_and_watch('/etc/log4perl.conf',10);
--then--
$logger = Log::Log4perl->get_logger('house.bedrm.desk.topdrwr');
$logger->debug('this is a debug message');
$logger->info('this is an info message');
$logger->warn('etc');
$logger->error('..');
$logger->fatal('..');
#####/etc/log4perl.conf###############################
log4perl.logger.house = WARN, FileAppndr1
log4perl.logger.house.bedroom.desk = DEBUG, FileAppndr1
log4perl.appender.FileAppndr1 = Log::Log4perl::Appender::File
log4perl.appender.FileAppndr1.filename = desk.log
log4perl.appender.FileAppndr1.layout = \
Log::Log4perl::Layout::SimpleLayout
######################################################
ABSTRACT
Log::Log4perl provides a powerful logging API for your application
DESCRIPTION
Log::Log4perl lets you remote-control and fine-tune the logging
behaviour of your system from the outside. It implements the widely
popular (Java-based) Log4j logging package in pure Perl.
For a detailed tutorial on Log::Log4perl usage, please read
<http://www.perl.com/pub/a/2002/09/11/log4perl.html>
Logging beats a debugger if you want to know what's going on in your
code during runtime. However, traditional logging packages are too
static and generate a flood of log messages in your log files that won't
help you.
"Log::Log4perl" is different. It allows you to control the number of
logging messages generated at three different levels:
* At a central location in your system (either in a configuration file
or in the startup code) you specify *which components* (classes,
functions) of your system should generate logs.
* You specify how detailed the logging of these components should be
by specifying logging *levels*.
* You also specify which so-called *appenders* you want to feed your
log messages to ("Print it to the screen and also append it to
/tmp/my.log") and which format ("Write the date first, then the file
name and line number, and then the log message") they should be in.
This is a very powerful and flexible mechanism. You can turn on and off
your logs at any time, specify the level of detail and make that
dependent on the subsystem that's currently executed.
Let me give you an example: You might find out that your system has a
problem in the "MySystem::Helpers::ScanDir" component. Turning on
detailed debugging logs all over the system would generate a flood of
useless log messages and bog your system down beyond recognition. With
"Log::Log4perl", however, you can tell the system: "Continue to log only
severe errors to the log file. Open a second log file, turn on full
debug logs in the "MySystem::Helpers::ScanDir" component and dump all
messages originating from there into the new log file". And all this is
possible by just changing the parameters in a configuration file, which
your system can re-read even while it's running!
How to use it
The "Log::Log4perl" package can be initialized in two ways: Either via
Perl commands or via a "log4j"-style configuration file.
Initialize via a configuration file
This is the easiest way to prepare your system for using
"Log::Log4perl". Use a configuration file like this:
############################################################
# A simple root logger with a Log::Log4perl::Appender::File
# file appender in Perl.
############################################################
log4perl.rootLogger=ERROR, LOGFILE
log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
log4perl.appender.LOGFILE.filename=/var/log/myerrs.log
log4perl.appender.LOGFILE.mode=append
log4perl.appender.LOGFILE.layout=PatternLayout
log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c - %m%n
These lines define your standard logger that's appending severe errors
to "/var/log/myerrs.log", using the format
[millisecs] source-filename line-number class - message newline
Assuming that this configuration file is saved as "log.conf", you need
to read it in the startup section of your code, using the following
commands:
use Log::Log4perl;
Log::Log4perl->init("log.conf");
After that's done *somewhere* in the code, you can retrieve logger
objects *anywhere* in the code. Note that there's no need to carry any
logger references around with your functions and methods. You can get a
logger anytime via a singleton mechanism:
package My::MegaPackage;
use Log::Log4perl;
sub some_method {
my($param) = @_;
my $log = Log::Log4perl->get_logger("My::MegaPackage");
$log->debug("Debug message");
$log->info("Info message");
$log->error("Error message");
...
}
With the configuration file above, "Log::Log4perl" will write "Error
message" to the specified log file, but won't do anything for the
"debug()" and "info()" calls, because the log level has been set to
"ERROR" for all components in the first line of configuration file shown
above.
Why "Log::Log4perl->get_logger" and not "Log::Log4perl->new"? We don't
want to create a new object every time. Usually in OO-Programming, you
create an object once and use the reference to it to call its methods.
However, this requires that you pass around the object to all functions
and the last thing we want is pollute each and every function/method
we're using with a handle to the "Logger":
sub function { # Brrrr!!
my($logger, $some, $other, $parameters) = @_;
}
Instead, if a function/method wants a reference to the logger, it just
calls the Logger's static "get_logger($category)" method to obtain a
reference to the *one and only* possible logger object of a certain
category. That's called a *singleton* if you're a Gamma fan.
How does the logger know which messages it is supposed to log and which
ones to suppress? "Log::Log4perl" works with inheritance: The config
file above didn't specify anything about "My::MegaPackage". And yet,
we've defined a logger of the category "My::MegaPackage". In this case,
"Log::Log4perl" will walk up the namespace hierarchy ("My" and then
we're at the root) to figure out if a log level is defined somewhere. In
the case above, the log level at the root (root *always* defines a log
level, but not necessarily an appender) defines that the log level is
supposed to be "ERROR" -- meaning that *DEBUG* and *INFO* messages are
suppressed. Note that this 'inheritance' is unrelated to Perl's class
inheritance, it is merely related to the logger namespace. By the way,
if you're ever in doubt about what a logger's category is, use
"$logger->category()" to retrieve it.
Log Levels
There are six predefined log levels: "FATAL", "ERROR", "WARN", "INFO",
"DEBUG", and "TRACE" (in descending priority). Your configured logging
level has to at least match the priority of the logging message.
If your configured logging level is "WARN", then messages logged with
"info()", "debug()", and "trace()" will be suppressed. "fatal()",
"error()" and "warn()" will make their way through, because their
priority is higher or equal than the configured setting.
Instead of calling the methods
$logger->trace("..."); # Log a trace message
$logger->debug("..."); # Log a debug message
$logger->info("..."); # Log a info message
$logger->warn("..."); # Log a warn message
$logger->error("..."); # Log a error message
$logger->fatal("..."); # Log a fatal message
you could also call the "log()" method with the appropriate level using
the constants defined in "Log::Log4perl::Level":
use Log::Log4perl::Level;
$logger->log($TRACE, "...");
$logger->log($DEBUG, "...");
$logger->log($INFO, "...");
$logger->log($WARN, "...");
$logger->log($ERROR, "...");
$logger->log($FATAL, "...");
This form is rarely used, but it comes in handy if you want to log at
different levels depending on an exit code of a function:
$logger->log( $exit_level{ $rc }, "...");
As for needing more logging levels than these predefined ones: It's
usually best to steer your logging behaviour via the category mechanism
instead.
If you need to find out if the currently configured logging level would
allow a logger's logging statement to go through, use the logger's
"is_*level*()" methods:
$logger->is_trace() # True if trace messages would go through
$logger->is_debug() # True if debug messages would go through
$logger->is_info() # True if info messages would go through
$logger->is_warn() # True if warn messages would go through
$logger->is_error() # True if error messages would go through
$logger->is_fatal() # True if fatal messages would go through
Example: "$logger->is_warn()" returns true if the logger's current
level, as derived from either the logger's category (or, in absence of
that, one of the logger's parent's level setting) is $WARN, $ERROR or
$FATAL.
Also available are a series of more Java-esque functions which return
the same values. These are of the format "is*Level*Enabled()", so
"$logger->isDebugEnabled()" is synonymous to "$logger->is_debug()".
These level checking functions will come in handy later, when we want to
block unnecessary expensive parameter construction in case the logging
level is too low to log the statement anyway, like in:
if($logger->is_error()) {
$logger->error("Erroneous array: @super_long_array");
}
If we had just written
$logger->error("Erroneous array: @super_long_array");
then Perl would have interpolated @super_long_array into the string via
an expensive operation only to figure out shortly after that the string
can be ignored entirely because the configured logging level is lower
than $ERROR.
The to-be-logged message passed to all of the functions described above
can consist of an arbitrary number of arguments, which the logging
functions just chain together to a single string. Therefore
$logger->debug("Hello ", "World", "!"); # and
$logger->debug("Hello World!");
are identical.
Note that even if one of the methods above returns true, it doesn't
necessarily mean that the message will actually get logged. What
is_debug() checks is that the logger used is configured to let a message
of the given priority (DEBUG) through. But after this check, Log4perl
will eventually apply custom filters and forward the message to one or
more appenders. None of this gets checked by is_xxx(), for the simple
reason that it's impossible to know what a custom filter does with a
message without having the actual message or what an appender does to a
message without actually having it log it.
Log and die or warn
Often, when you croak / carp / warn / die, you want to log those
messages. Rather than doing the following:
$logger->fatal($err) && die($err);
you can use the following:
$logger->logdie($err);
And if instead of using
warn($message);
$logger->warn($message);
to both issue a warning via Perl's warn() mechanism and make sure you
have the same message in the log file as well, use:
$logger->logwarn($message);
Since there is an ERROR level between WARN and FATAL, there are two
additional helper functions in case you'd like to use ERROR for either
warn() or die():
$logger->error_warn();
$logger->error_die();
Finally, there's the Carp functions that, in addition to logging, also
pass the stringified message to their companions in the Carp package:
$logger->logcarp(); # warn w/ 1-level stack trace
$logger->logcluck(); # warn w/ full stack trace
$logger->logcroak(); # die w/ 1-level stack trace
$logger->logconfess(); # die w/ full stack trace
Appenders
If you don't define any appenders, nothing will happen. Appenders will
be triggered whenever the configured logging level requires a message to
be logged and not suppressed.
"Log::Log4perl" doesn't define any appenders by default, not even the
root logger has one.
"Log::Log4perl" already comes with a standard set of appenders:
Log::Log4perl::Appender::Screen
Log::Log4perl::Appender::ScreenColoredLevels
Log::Log4perl::Appender::File
Log::Log4perl::Appender::Socket
Log::Log4perl::Appender::DBI
Log::Log4perl::Appender::Synchronized
Log::Log4perl::Appender::RRDs
to log to the screen, to files and to databases.
On CPAN, you can find additional appenders like
Log::Log4perl::Layout::XMLLayout
by Guido Carls <[email protected]>. It allows for hooking up Log::Log4perl
with the graphical Log Analyzer Chainsaw (see "Can I use Log::Log4perl
with log4j's Chainsaw?" in Log::Log4perl::FAQ).
Additional Appenders via Log::Dispatch
"Log::Log4perl" also supports *Dave Rolskys* excellent "Log::Dispatch"
framework which implements a wide variety of different appenders.
Here's the list of appender modules currently available via
"Log::Dispatch":
Log::Dispatch::ApacheLog
Log::Dispatch::DBI (by Tatsuhiko Miyagawa)
Log::Dispatch::Email,
Log::Dispatch::Email::MailSend,
Log::Dispatch::Email::MailSendmail,
Log::Dispatch::Email::MIMELite
Log::Dispatch::File
Log::Dispatch::FileRotate (by Mark Pfeiffer)
Log::Dispatch::Handle
Log::Dispatch::Screen
Log::Dispatch::Syslog
Log::Dispatch::Tk (by Dominique Dumont)
Please note that in order to use any of these additional appenders, you
have to fetch Log::Dispatch from CPAN and install it. Also the
particular appender you're using might require installing the particular
module.
For additional information on appenders, please check the
Log::Log4perl::Appender manual page.
Appender Example
Now let's assume that we want to log "info()" or higher prioritized
messages in the "Foo::Bar" category to both STDOUT and to a log file,
say "test.log". In the initialization section of your system, just
define two appenders using the readily available
"Log::Log4perl::Appender::File" and "Log::Log4perl::Appender::Screen"
modules:
use Log::Log4perl;
# Configuration in a string ...
my $conf = q(
log4perl.category.Foo.Bar = INFO, Logfile, Screen
log4perl.appender.Logfile = Log::Log4perl::Appender::File
log4perl.appender.Logfile.filename = test.log
log4perl.appender.Logfile.layout = Log::Log4perl::Layout::PatternLayout
log4perl.appender.Logfile.layout.ConversionPattern = [%r] %F %L %m%n
log4perl.appender.Screen = Log::Log4perl::Appender::Screen
log4perl.appender.Screen.stderr = 0
log4perl.appender.Screen.layout = Log::Log4perl::Layout::SimpleLayout
);
# ... passed as a reference to init()
Log::Log4perl::init( \$conf );
Once the initialization shown above has happened once, typically in the
startup code of your system, just use the defined logger anywhere in
your system:
##########################
# ... in some function ...
##########################
my $log = Log::Log4perl::get_logger("Foo::Bar");
# Logs both to STDOUT and to the file test.log
$log->info("Important Info!");
The "layout" settings specified in the configuration section define the
format in which the message is going to be logged by the specified
appender. The format shown for the file appender is logging not only the
message but also the number of milliseconds since the program has
started (%r), the name of the file the call to the logger has happened
and the line number there (%F and %L), the message itself (%m) and a
OS-specific newline character (%n):
[187] ./myscript.pl 27 Important Info!
The screen appender above, on the other hand, uses a "SimpleLayout",
which logs the debug level, a hyphen (-) and the log message:
INFO - Important Info!
For more detailed info on layout formats, see "Log Layouts".
In the configuration sample above, we chose to define a *category*
logger ("Foo::Bar"). This will cause only messages originating from this
specific category logger to be logged in the defined format and
locations.
Logging newlines
There's some controversy between different logging systems as to when
and where newlines are supposed to be added to logged messages.
The Log4perl way is that a logging statement *should not* contain a
newline:
$logger->info("Some message");
$logger->info("Another message");
If this is supposed to end up in a log file like
Some message
Another message
then an appropriate appender layout like "%m%n" will take care of adding
a newline at the end of each message to make sure every message is
printed on its own line.
Other logging systems, Log::Dispatch in particular, recommend adding the
newline to the log statement. This doesn't work well, however, if you,
say, replace your file appender by a database appender, and all of a
sudden those newlines scattered around the code don't make sense
anymore.
Assigning matching layouts to different appenders and leaving newlines
out of the code solves this problem. If you inherited code that has
logging statements with newlines and want to make it work with Log4perl,
read the Log::Log4perl::Layout::PatternLayout documentation on how to
accomplish that.
Configuration files
As shown above, you can define "Log::Log4perl" loggers both from within
your Perl code or from configuration files. The latter have the
unbeatable advantage that you can modify your system's logging behaviour
without interfering with the code at all. So even if your code is being
run by somebody who's totally oblivious to Perl, they still can adapt
the module's logging behaviour to their needs.
"Log::Log4perl" has been designed to understand "Log4j" configuration
files -- as used by the original Java implementation. Instead of
reiterating the format description in [2], let me just list three
examples (also derived from [2]), which should also illustrate how it
works:
log4j.rootLogger=DEBUG, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r %-5p %c %x - %m%n
This enables messages of priority "DEBUG" or higher in the root
hierarchy and has the system write them to the console.
"ConsoleAppender" is a Java appender, but "Log::Log4perl" jumps through
a significant number of hoops internally to map these to their
corresponding Perl classes, "Log::Log4perl::Appender::Screen" in this
case.
Second example:
log4perl.rootLogger=DEBUG, A1
log4perl.appender.A1=Log::Log4perl::Appender::Screen
log4perl.appender.A1.layout=PatternLayout
log4perl.appender.A1.layout.ConversionPattern=%d %-5p %c - %m%n
log4perl.logger.com.foo=WARN
This defines two loggers: The root logger and the "com.foo" logger. The
root logger is easily triggered by debug-messages, but the "com.foo"
logger makes sure that messages issued within the "Com::Foo" component
and below are only forwarded to the appender if they're of priority
*warning* or higher.
Note that the "com.foo" logger doesn't define an appender. Therefore, it
will just propagate the message up the hierarchy until the root logger
picks it up and forwards it to the one and only appender of the root
category, using the format defined for it.
Third example:
log4j.rootLogger=DEBUG, stdout, R
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p (%F:%L) - %m%n
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %c - %m%n
The root logger defines two appenders here: "stdout", which uses
"org.apache.log4j.ConsoleAppender" (ultimately mapped by "Log::Log4perl"
to Log::Log4perl::Appender::Screen) to write to the screen. And "R", a
"org.apache.log4j.RollingFileAppender" (mapped by "Log::Log4perl" to
Log::Dispatch::FileRotate with the "File" attribute specifying the log
file.
See Log::Log4perl::Config for more examples and syntax explanations.
Log Layouts
If the logging engine passes a message to an appender, because it thinks
it should be logged, the appender doesn't just write it out haphazardly.
There's ways to tell the appender how to format the message and add all
sorts of interesting data to it: The date and time when the event
happened, the file, the line number, the debug level of the logger and
others.
There's currently two layouts defined in "Log::Log4perl":
"Log::Log4perl::Layout::SimpleLayout" and
"Log::Log4perl::Layout::PatternLayout":
"Log::Log4perl::SimpleLayout"
formats a message in a simple way and just prepends it by the debug
level and a hyphen: ""$level - $message", for example "FATAL - Can't
open password file".
"Log::Log4perl::Layout::PatternLayout"
on the other hand is very powerful and allows for a very flexible
format in "printf"-style. The format string can contain a number of
placeholders which will be replaced by the logging engine when it's
time to log the message:
%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 (if Sys::Hostname is available)
%l Fully qualified name of the calling method followed by the
callers source the file name and line number between
parentheses.
%L Line number within the file where the log statement was issued
%m The message to be logged
%m{chomp} The message to be logged, stripped off a trailing newline
%M Method or function where the logging request was issued
%n Newline (OS-independent)
%p Priority of the logging event (AKA log level)
%P pid of the current process
%r Number of milliseconds elapsed from program start to logging
event
%R Number of milliseconds elapsed from last logging event to
current logging event
%T A stack trace of functions called
%x The topmost NDC (see below)
%X{key} The entry 'key' of the MDC (see below)
%% A literal percent (%) sign
NDC and MDC are explained in "Nested Diagnostic Context (NDC)" and
"Mapped Diagnostic Context (MDC)".
Also, %d can be fine-tuned to display only certain characteristics
of a date, according to the SimpleDateFormat in the Java World
(<https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/
text/SimpleDateFormat.html>)
In this way, %d{HH:mm} displays only hours and minutes of the
current date, while %d{yy, EEEE} displays a two-digit year, followed
by a spelled-out day (like "Wednesday").
Similar options are available for shrinking the displayed category
or limit file/path components, %F{1} only displays the source file
*name* without any path components while %F logs the full path.
%c{2} only logs the last two components of the current category,
"Foo::Bar::Baz" becomes "Bar::Baz" and saves space.
If those placeholders aren't enough, then you can define your own
right in the config file like this:
log4perl.PatternLayout.cspec.U = sub { return "UID $<" }
See Log::Log4perl::Layout::PatternLayout for further details on
customized specifiers.
Please note that the subroutines you're defining in this way are
going to be run in the "main" namespace, so be sure to fully qualify
functions and variables if they're located in different packages.
SECURITY NOTE: this feature means arbitrary perl code can be
embedded in the config file. In the rare case where the people who
have access to your config file are different from the people who
write your code and shouldn't have execute rights, you might want to
call
Log::Log4perl::Config->allow_code(0);
before you call init(). Alternatively you can supply a restricted
set of Perl opcodes that can be embedded in the config file as
described in "Restricting what Opcodes can be in a Perl Hook".
All placeholders are quantifiable, just like in *printf*. Following this
tradition, "%-20c" will reserve 20 chars for the category and
left-justify it.
For more details on logging and how to use the flexible and the simple
format, check out the original "log4j" website under
SimpleLayout
<http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/SimpleLayo
ut.html> and PatternLayout
<http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLay
out.html>
Penalties
Logging comes with a price tag. "Log::Log4perl" has been optimized to
allow for maximum performance, both with logging enabled and disabled.
But you need to be aware that there's a small hit every time your code
encounters a log statement -- no matter if logging is enabled or not.
"Log::Log4perl" has been designed to keep this so low that it will be
unnoticeable to most applications.
Here's a couple of tricks which help "Log::Log4perl" to avoid
unnecessary delays:
You can save serious time if you're logging something like
# Expensive in non-debug mode!
for (@super_long_array) {
$logger->debug("Element: $_");
}
and @super_long_array is fairly big, so looping through it is pretty
expensive. Only you, the programmer, knows that going through that "for"
loop can be skipped entirely if the current logging level for the actual
component is higher than "debug". In this case, use this instead:
# Cheap in non-debug mode!
if($logger->is_debug()) {
for (@super_long_array) {
$logger->debug("Element: $_");
}
}
If you're afraid that generating the parameters to the logging function
is fairly expensive, use closures:
# Passed as subroutine ref
use Data::Dumper;
$logger->debug(sub { Dumper($data) } );
This won't unravel $data via Dumper() unless it's actually needed
because it's logged.
Also, Log::Log4perl lets you specify arguments to logger functions in
*message output filter syntax*:
$logger->debug("Structure: ",
{ filter => \&Dumper,
value => $someref });
In this way, shortly before Log::Log4perl sending the message out to any
appenders, it will be searching all arguments for hash references and
treat them in a special way:
It will invoke the function given as a reference with the "filter" key
("Data::Dumper::Dumper()") and pass it the value that came with the key
named "value" as an argument. The anonymous hash in the call above will
be replaced by the return value of the filter function.
Categories
Categories are also called "Loggers" in Log4perl, both refer to the same
thing and these terms are used interchangeably. "Log::Log4perl" uses
*categories* to determine if a log statement in a component should be
executed or suppressed at the current logging level. Most of the time,
these categories are just the classes the log statements are located in:
package Candy::Twix;
sub new {
my $logger = Log::Log4perl->get_logger("Candy::Twix");
$logger->debug("Creating a new Twix bar");
bless {}, shift;
}
# ...
package Candy::Snickers;
sub new {
my $logger = Log::Log4perl->get_logger("Candy.Snickers");
$logger->debug("Creating a new Snickers bar");
bless {}, shift;
}
# ...
package main;
Log::Log4perl->init("mylogdefs.conf");
# => "LOG> Creating a new Snickers bar"
my $first = Candy::Snickers->new();
# => "LOG> Creating a new Twix bar"
my $second = Candy::Twix->new();
Note that you can separate your category hierarchy levels using either
dots like in Java (.) or double-colons (::) like in Perl. Both notations
are equivalent and are handled the same way internally.
However, categories are just there to make use of inheritance: if you
invoke a logger in a sub-category, it will bubble up the hierarchy and
call the appropriate appenders. Internally, categories are not related
to the class hierarchy of the program at all -- they're purely virtual.
You can use arbitrary categories -- for example in the following
program, which isn't oo-style, but procedural:
sub print_portfolio {
my $log = Log::Log4perl->get_logger("user.portfolio");
$log->debug("Quotes requested: @_");
for(@_) {
print "$_: ", get_quote($_), "\n";
}
}
sub get_quote {
my $log = Log::Log4perl->get_logger("internet.quotesystem");
$log->debug("Fetching quote: $_[0]");
return yahoo_quote($_[0]);
}
The logger in first function, "print_portfolio", is assigned the
(virtual) "user.portfolio" category. Depending on the "Log4perl"
configuration, this will either call a "user.portfolio" appender, a
"user" appender, or an appender assigned to root -- without
"user.portfolio" having any relevance to the class system used in the
program. The logger in the second function adheres to the
"internet.quotesystem" category -- again, maybe because it's bundled
with other Internet functions, but not because there would be a class of
this name somewhere.
However, be careful, don't go overboard: if you're developing a system
in object-oriented style, using the class hierarchy is usually your best
choice. Think about the people taking over your code one day: The class
hierarchy is probably what they know right up front, so it's easy for
them to tune the logging to their needs.
Turn off a component
"Log4perl" doesn't only allow you to selectively switch *on* a category
of log messages, you can also use the mechanism to selectively *disable*
logging in certain components whereas logging is kept turned on in
higher-level categories. This mechanism comes in handy if you find that
while bumping up the logging level of a high-level (i. e. close to root)
category, that one component logs more than it should,
Here's how it works:
############################################################
# Turn off logging in a lower-level category while keeping
# it active in higher-level categories.
############################################################
log4perl.rootLogger=DEBUG, LOGFILE
log4perl.logger.deep.down.the.hierarchy = ERROR, LOGFILE
# ... Define appenders ...
This way, log messages issued from within "Deep::Down::The::Hierarchy"
and below will be logged only if they're "ERROR" or worse, while in all
other system components even "DEBUG" messages will be logged.
Return Values
All logging methods return values indicating if their message actually
reached one or more appenders. If the message has been suppressed
because of level constraints, "undef" is returned.
For example,
my $ret = $logger->info("Message");
will return "undef" if the system debug level for the current category
is not "INFO" or more permissive. If Log::Log4perl forwarded the message
to one or more appenders, the number of appenders is returned.
If appenders decide to veto on the message with an appender threshold,
the log method's return value will have them excluded. This means that
if you've got one appender holding an appender threshold and you're
logging a message which passes the system's log level hurdle but not the
appender threshold, 0 will be returned by the log function.
The bottom line is: Logging functions will return a *true* value if the
message made it through to one or more appenders and a *false* value if
it didn't. This allows for constructs like
$logger->fatal("@_") or print STDERR "@_\n";
which will ensure that the fatal message isn't lost if the current level
is lower than FATAL or printed twice if the level is acceptable but an
appender already points to STDERR.
Pitfalls with Categories
Be careful with just blindly reusing the system's packages as
categories. If you do, you'll get into trouble with inherited methods.
Imagine the following class setup:
use Log::Log4perl;
###########################################
package Bar;
###########################################
sub new {
my($class) = @_;
my $logger = Log::Log4perl::get_logger(__PACKAGE__);
$logger->debug("Creating instance");
bless {}, $class;
}
###########################################
package Bar::Twix;
###########################################
our @ISA = qw(Bar);
###########################################
package main;
###########################################
Log::Log4perl->init(\ qq{
log4perl.category.Bar.Twix = DEBUG, Screen
log4perl.appender.Screen = Log::Log4perl::Appender::Screen
log4perl.appender.Screen.layout = SimpleLayout
});
my $bar = Bar::Twix->new();
"Bar::Twix" just inherits everything from "Bar", including the
constructor "new()". Contrary to what you might be thinking at first,
this won't log anything. Reason for this is the "get_logger()" call in
package "Bar", which will always get a logger of the "Bar" category,
even if we call "new()" via the "Bar::Twix" package, which will make
perl go up the inheritance tree to actually execute "Bar::new()". Since
we've only defined logging behaviour for "Bar::Twix" in the
configuration file, nothing will happen.
This can be fixed by changing the "get_logger()" method in "Bar::new()"
to obtain a logger of the category matching the *actual* class of the
object, like in
# ... in Bar::new() ...
my $logger = Log::Log4perl::get_logger( $class );
In a method other than the constructor, the class name of the actual
object can be obtained by calling "ref()" on the object reference, so
package BaseClass;
use Log::Log4perl qw( get_logger );
sub new {
bless {}, shift;
}
sub method {
my( $self ) = @_;
get_logger( ref $self )->debug( "message" );
}
package SubClass;
our @ISA = qw(BaseClass);
is the recommended pattern to make sure that
my $sub = SubClass->new();
$sub->meth();
starts logging if the "SubClass" category (and not the "BaseClass"
category has logging enabled at the DEBUG level.
Initialize once and only once
It's important to realize that Log::Log4perl gets initialized once and
only once, typically at the start of a program or system. Calling
"init()" more than once will cause it to clobber the existing
configuration and *replace* it by the new one.
If you're in a traditional CGI environment, where every request is
handled by a new process, calling "init()" every time is fine. In
persistent environments like "mod_perl", however, Log::Log4perl should
be initialized either at system startup time (Apache offers startup
handlers for that) or via
# Init or skip if already done
Log::Log4perl->init_once($conf_file);
"init_once()" is identical to "init()", just with the exception that it
will leave a potentially existing configuration alone and will only call
"init()" if Log::Log4perl hasn't been initialized yet.
If you're just curious if Log::Log4perl has been initialized yet, the
check
if(Log::Log4perl->initialized()) {
# Yes, Log::Log4perl has already been initialized
} else {
# No, not initialized yet ...
}
can be used.
If you're afraid that the components of your system are stepping on each
other's toes or if you are thinking that different components should
initialize Log::Log4perl separately, try to consolidate your system to
use a centralized Log4perl configuration file and use Log4perl's
*categories* to separate your components.
Custom Filters
Log4perl allows the use of customized filters in its appenders to
control the output of messages. These filters might grep for certain
text chunks in a message, verify that its priority matches or exceeds a
certain level or that this is the 10th time the same message has been
submitted -- and come to a log/no log decision based upon these
circumstantial facts.
Check out Log::Log4perl::Filter for detailed instructions on how to use
them.
Performance
The performance of Log::Log4perl calls obviously depends on a lot of
things. But to give you a general idea, here's some rough numbers:
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.
Numbers depend on the complexity of the Log::Log4perl configuration. For
a more detailed benchmark test, check the "docs/benchmark.results.txt"
document in the Log::Log4perl distribution.
Cool Tricks
Here's a collection of useful tricks for the advanced "Log::Log4perl"
user. For more, check the FAQ, either in the distribution
(Log::Log4perl::FAQ) or on <http://log4perl.sourceforge.net>.
Shortcuts
When getting an instance of a logger, instead of saying
use Log::Log4perl;
my $logger = Log::Log4perl->get_logger();
it's often more convenient to import the "get_logger" method from
"Log::Log4perl" into the current namespace:
use Log::Log4perl qw(get_logger);
my $logger = get_logger();
Please note this difference: To obtain the root logger, please use
"get_logger("")", call it without parameters ("get_logger()"), you'll
get the logger of a category named after the current package.
"get_logger()" is equivalent to "get_logger(__PACKAGE__)".
Alternative initialization
Instead of having "init()" read in a configuration file by specifying a
file name or passing it a reference to an open filehandle
("Log::Log4perl->init( \*FILE )"), you can also pass in a reference to a
string, containing the content of the file:
Log::Log4perl->init( \$config_text );
Also, if you've got the "name=value" pairs of the configuration in a
hash, you can just as well initialize "Log::Log4perl" with a reference
to it:
my %key_value_pairs = (
"log4perl.rootLogger" => "ERROR, LOGFILE",
"log4perl.appender.LOGFILE" => "Log::Log4perl::Appender::File",
...
);
Log::Log4perl->init( \%key_value_pairs );
Or also you can use a URL, see below:
Using LWP to parse URLs