Mit Log::Log4perl lassen sich in Programme Log-Anweisungen einbauen, die bei der normalen Programmausführung schlafen. Besteht Bedarf, steuert eine externe Konfigurationsdatei das Erwachen der Schläfer. Sie zeigen an, was das Programm so treibt, ohne dass man dessen Code ändern muss.

Log::Log4perl ist ein Perl-Port des aus der Java-Welt stammenden Log4j-Systems, das auf drei Säulen steht: Logger lösen Log-Nachrichten aus, Prioritäten bestimmen, ob sie durchkommen und Appender leiten sie dann an konfigurierte Ausgabemedien weiter.

Die Prioritäten steuern, ob ein Logger die ihm übergebenen Nachrichten tatsächlich rausschreibt oder unterdrückt. Log::Log4perl bietet fünf Prioritäten: »DEBUG«, »INFO«, »WARN«, »ERROR« und »FATAL«. Wenn die Zentrale sagt, dass sie nur Nachrichten der Priorität »ERROR« und höher sehen will, sorgt Log::Log4perl dafür, dass mit »DEBUG«, »INFO« oder »WARN« geloggte Nachrichten gar nicht erst auftauchen. Sie stehen zwar im Code, werden aber zur Laufzeit unterdrückt.

Zum Logger gehören Kategorien, die typischerweise nach der Klasse benannt sind, in der sie ihre Dienste anbieten. Die Klasse »Riegel::Twix« wird also meist eine Instanz des Loggers der Kategorie »Riegel.Twix« nutzen. Der Knüller: Alle Logger eines Systems (die wahrscheinlich in Dutzenden verschiedener Klassen liegen und demnach Dutzenden von verschiedenen Kategorien angehören) lassen sich von einer zentralen Stelle ansprechen und fernsteuern.

Treten Probleme in »Riegel::Twix« auf, muss nicht das ganze System in den Debug-Modus, es reicht bereits aus, ein detailliertes Logging in der Kategorie »Riegel« anzuwerfen. Entsprechend springen die Logger der Kategorien »Riegel« und »Riegel.Twix« an. Dazu muss man nicht etwa den Code ändern, es genügt völlig, eine zentrale Konfigurationsdatei anzupassen.

Loggen für Faule

Das Tutorial auf [2] zeigt die Anwendung von Log::Log4perl im Detail. Heute ist “Loggen für Faule” dran – alle Vorzüge von Log4perl ohne viel Aufwand. Listing 1 (»Building.pm«) zeigt als Beispiel eine typische Perl-Anwendung: zwei Klassen, die die Temperatur eines Atomkraftwerks regeln und in einer Wohnung den Fernseher an- und ausschalten. Die Methoden sind gespickt mit Logging-Anweisungen: »DEBUG()«, »INFO()«, »ERROR()« sind alles Funktionen aus Log::Log4perl\’s »:easy«-Fundus, die alle zunächst inaktiv sind.

Die Basisklasse »Building« definiert den Konstruktor »new()«, den die abgeleiteten Klassen einfach erben. Die Klasse »Building::NuclearPowerPlant« abstrahiert ein Atomkraftwerk mit den Methoden »temperature()« zum Setzen und Abfragen der Reaktortemperatur und »is_ok()« für die Prüfung, ob noch alles im grünen Bereich läuft.

Die Klasse »Building::Residential« ahmt dagegen ein Privathaus nach und ist von der Basisklasse »Building« abgeleitet. Die Methode »tv(“on”|”off”)« schaltet den Fernseher im Wohnzimmer auf Befehl an und aus.

01 #!/usr/bin/perl
02 ###########################################
03 # Mike Schilli, 2002 (m@perlmeister.com)
04 ###########################################
05 use warnings;
06 use strict;
07 
08 ###########################################
09 package Building;
10 ###########################################
11 use Log::Log4perl qw(:easy);
12 sub new {
13     my($class) = @_;
14     DEBUG("Create new $class");
15     bless {}, $class;
16 }
17 
18 ###########################################
19 package Building::NuclearPowerPlant;
20 ###########################################
21 use Log::Log4perl qw(:easy);
22 our @ISA = qw(Building);
23 
24 ###########################################
25 sub temperature {
26     my($self, $temp) = @_;
27 
28     if(defined $temp) {
29         DEBUG("Set temperature to $temp");
30         $self->{temp} = $temp;
31         $self->is_ok();
32     }
33 
34     return $self->{temp};
35 }
36 
37 ###########################################
38 sub is_ok {
39     my($self) = @_;
40     if(defined $self->{temp} and
41        $self->{temp} > 100) {
42         ERROR("I'm exploding!");
43         return 0;
44     }
45     INFO("OK");
46     return 1;
47 }
48 
49 ###########################################
50 package Building::Residential;
51 ###########################################
52 use Log::Log4perl qw(:easy);
53 our @ISA = qw(Building);
54 
55 ###########################################
56 sub tv {
57     my($self, $action) = @_;
58 
59     if(defined $action) {
60         DEBUG("Set tv to $action");
61         $self->{tv} = $action;
62     }
63 
64     INFO("TV is $self->{tv}");
65     return $self->{tv};
66 }
67 
68 1;

Aufpasser hinter den Kulissen

Alle drei Klassen ziehen dabei jeweils (!) »Log::Log4perl qw(:easy)« herein, um hinter den Kulissen Default-Logger zu erzeugen, die einfach auf die Kategorie des jeweiligen Klassennamens hören. Die auf gleiche Weise exportierten Funktionen »DEBUG()«, »INFO()«, »ERROR()« und weitere gelangen ebenfalls über das »:easy«-Tag in den Namensraum der jeweiligen Klasse.

Listing 2 (»building.pl«) zeigt ein Skript, das die Klassen verwendet. Auf der Kommandozeile nimmt es optional ein Argument entgegen, das die Log4perl-Konfigurationsdatei bestimmt. Im Format von Java-Properties-Dateien lässt sich Log4perl so bequem von außen fernsteuern. Findet »building.pl« allerdings keine Angabe, wird Log4perl nicht initialisiert, was im »:easy«-Modus seit Version 0.25 einfach alle Log-Anweisungen schlafen legt.

Von der Kommandozeile ohne Argument aufgerufen, erledigt »building.pl« zwar bereitwillig seine Aufgaben, zeigt allerdings nichts an:

$ building.pl
$

Wer trotzdem wissen will, was so im Einzelnen abgeht, der sollte sich eine Log4perl-Konfigurationsdatei nach »info .conf« anlegen. »info.conf« bestimmt, dass die Logger in der Kategorie »Building« und in allen ihren Unterklassen (also in diesem Beispiel die in »Building«, »Building::Residential« und »Building::NuclearPowerPlant« verwendeten Logger) zu schreiben beginnen, und zwar nur Nachrichten mit mindestens der Priorität »INFO«.

Der Appender »Screen« ist vom Typ »Log::Dispatch::Screen« und leitet einfach alle durchgelassenen Nachrichten nach »STDERR« weiter. Das Pattern-Layout legt mit

%d [%c]: %m%n

fest, dass jeder Nachricht (»%m«) zuerst das aktuelle Datum (»%d«) und die Logger-Kategorie (»%c«) vorangeht, während stets ein Zeilenumbruch (»%n«) nachfolgt.

Es folgt die Ausgabe des Programms »building.pl« (nach »STDERR«), nachdem es mit dem Parameter »info.conf« aufgerufen wurde:

2002/10/05 21:36:50  [Building.Residential]: TV is on
2002/10/05 21:36:50  [Building.NuclearPowerPlant]: I'm exploding!

Die »DEBUG«-Nachrichten werden, wie man sieht, unterdrückt. Hieße Zeile 1 in »info.conf« hingegen

1 log4perl.category.Building=DEBUG, Screen

kämen auch sie durch, wie die Ausgabe in Listing 4 zeigt.

01 #!/usr/bin/perl
02 ###########################################
03 # Mike Schilli, 2002 (m@perlmeister.com)
04 ###########################################
05 use warnings;
06 use strict;
07 
08 use Building;
09 use Log::Log4perl qw(:easy);
10 
11 if($ARGV[0]) {
12     Log::Log4perl->init($ARGV[0]);
13 }
14 
15 my $plant = Building::NuclearPowerPlant->new();
16 my $home  = Building::Residential->new();
17 
18    # Switch TV on
19 $home->tv("on");
20    # Overheat nuklear power plant
21 $plant->temperature(200);

01 log4perl.category.Building = INFO, Screen
02 log4perl.appender.Screen   = Log::Dispatch::Screen
03 log4perl.appender.Screen.layout  = PatternLayout
04 log4perl.appender.Screen.layout.ConversionPattern =  %d [%c]: %m%n

01 2002/10/06 15:11:13 [Building]: Create new Building::NuclearPowerPlant
02 2002/10/06 15:11:13 [Building]: Create new Building::Residential
03 2002/10/06 15:11:13 [Building.Residential]:  Set tv to on
04 2002/10/06 15:11:13 [Building.Residential]: TV is on
05 2002/10/06 15:11:13 [Building.NuclearPowerPlant]:  Set temperature to 200
06 2002/10/06 15:11:13 [Building.NuclearPowerPlant]:  I'm exploding!

Geschwätz reduzieren

Wer dies zu geschwätzig findet und lieber nur Nachrichten aus dem Atomkraftwerk empfangen möchte, fährt besser mit einer Konfigurationsdatei wie in Listing 5. Der Aufruf:

building.pl nukeonly.conf

zeigt Meldungen aller Prioritäten, beschränkt die Ausgabe aber auf die Kategorie »Building.NuclearPowerPlant«:

2002/10/05 21:36:51> Set temperature to 200
2002/10/05 21:36:51> I'm exploding!

Hier wird die Beschränkung des »:easy«-Ansatzes deutlich, der einfach davon ausgeht, dass die Kategorie des gerade verwendeten Loggers immer gleichzusetzen wäre mit dem aktuellen Package – was sich jedoch anhand der ererbten »new«-Methode in den »Building::*«-Subklassen als falsch herausstellt.

Statt eines »Building«-Loggers sollte der Konstruktor einen Logger der gerade konstruierten Subklassen-Kategorie verwenden, etwa wie dieser Konstruktor:<c>@15 Li:sub new {

my($class) = @_;

my $logger = get_logger($class);

$logger->debug(“Create new $class”);

bless {}, $class;

}

Damit stimmt dann auch die Ausgabe des vererbten Konstruktors:

2002/10/06 15:14:14> Create new Building::NuclearPowerPlant
2002/10/06 15:14:14> Set temperature to 200
2002/10/06 15:14:14> I'm exploding!

Immer nur auf »STDERR« ausgeben mag vielleicht für Kommandozeilenskripte noch angehen. Im Hintergrund laufende Daemons sollten allerdings in eine Logdatei schreiben, in eine Datenbank loggen oder E-Mails aussenden. Das alles und mehr unterstützt Log4perl – natürlich nur mit Konfigurationsparametern, der Code der Applikation bleibt weiterhin unangetastet.

01 log4perl.category.Building.NuclearPowerPlant = DEBUG, Screen
02 log4perl.appender.Screen     = Log::Dispatch::Screen
03 log4perl.appender.Screen.stderr   = 0
04 log4perl.appender.Screen.layout  = PatternLayout
05 log4perl.appender.Screen.layout.ConversionPattern = %d> %m%n

Ausgaben in andere Kanäle

Angenommen die Applikation soll ab sofort ihre Error-Nachrichten aller Kategorien in eine Logdatei »test.log« senden. Listing 6 zeigt die entsprechende Konfiguration. Einfach

building.pl err2file.conf

aufrufen, schon findet sich folgende Nachricht in »test.log« ein:

2002/10/08 22:29:30 Building.pm   42 ERROR> I'm exploding!

»err2file.conf« definiert mit

log4perl.category = ERROR, File

in der ersten Zeile der Datei einfach die Root-Kategorie, also die Mutter aller Kategorien, von der die anderen automatisch erben.

Das Layout-Pattern »%d %F %L %p> %m%n« schreibt nach dem Datum den Dateinamen des Perl-Moduls (»%F«), die Zeilennummer des Logging-Aufrufs (»%L«) und die Priorität (»%p«) des Vorfalls. Spielt nun »Building::Residential« verrückt und die »DEBUG«-Meldungen daraus sollen auf »STDERR« erscheinen, ohne die Ausgabe der Error-Meldungen nach »test.log« zu unterbrechen, erhält die Konfigurationsdatei einfach vier zusätzliche Zeilen, wie das Listing 7 zeigt. Der Aufruf

./building.pl err2file2.conf

schreibt

2002/10/05 21:36:38[Building.Residential]: Set tv to on
2002/10/05 21:36:38[Building.Residential]: TV is on

nach »STDERR« und zudem die oben gezeigte Ausgabe nach »test.log«.

Die letzte Zeile in Listing 7 ist wichtig, denn Log4perl unterstützt, wie in der Dokumentation auf [3] unter »Beginner\’s Pitfalls« illustriert, Appender-Vererbung: Beschließt ein Logger in »Building.Residential« einmal, seinen Appender feuern zu lassen, steigt die Nachricht die Appenderhierarchie hoch und wird bedingungslos von allen angeschlossenen Appendern übernommen. Im vorliegenden Fall landen deshalb alle »DEBUG«-Nachrichten aus »Building::Residential« im Root-Logger.

Um genau dies zu verhindern, setzt die letzte Zeile in »err2file2.conf« den Appender-Threshold des Logdatei-Appenders auf »ERROR«, was dazu führt, dass die »DEBUG«-Nachrichten in letzter Sekunde geblockt werden.

01 log4perl.category = ERROR, File
02 log4perl.appender.File          = Log::Dispatch::File
03 log4perl.appender.File.filename = test.log
04 log4perl.appender.File.layout   = PatternLayout
05 log4perl.appender.File.layout.ConversionPattern =  %d %F %L %p> %m%n

01 log4perl.category.Building.Residential = DEBUG, Screen
02 log4perl.appender.Screen   = Log::Dispatch::Screen
03 log4perl.appender.Screen.layout  = PatternLayout
04 log4perl.appender.Screen.layout.ConversionPattern =  %d [%c]: %m%n
05 log4perl.category = ERROR, File
06 log4perl.appender.File          = Log::Dispatch::File
07 log4perl.appender.File.filename = test.log
08 log4perl.appender.File.layout   = PatternLayout
09 log4perl.appender.File.layout.ConversionPattern =  %d %F %L %p> %m%n
10 log4perl.appender.File.Threshold = ERROR

Sie haben Post!

Wichtige Ereignisse sollte man nicht in einer Logdatei verstauben lassen, sondern schnell an alle Interessierten weiterreichen. Explodiert das Atomkraftwerk, soll die Applikation sofort eine E-Mail mit einer Warnung schicken. Auch das geht natürlich, ohne in den Applikationscode einzugreifen. Das Listing 8 (»mailerrors.conf«) zeigt die Konfigurationsdatei. Der Aufruf

building.pl mailerrors.conf

schickt die in Abbildung 1 gezeigte E-Mail an den entsetzten Adressaten.

01 log4perl.category.Building.NuclearPowerPlant =  ERROR, Mailer
02 log4perl.appender.Mailer          = Log::Dispatch::Email::MailSend
03 log4perl.appender.Mailer.to      = l4ptest@perlmeister.com
04 log4perl.appender.Mailer.subject = Problem im Atomkraftwerk!
05 log4perl.appender.Mailer.layout  = PatternLayout
06 log4perl.appender.Mailer.layout.ConversionPattern =          %d %F %L> %m%n

Abbildung 1: Sie haben Post!

Appetit auf mehr?

Ich hoffe, diese kurze Wirbelwindtour durch Log4perl hat Appetit gemacht, dieses neue Modul in vielen Applikationen zu verwenden. Es gäbe darüber noch einiges zu berichten, etwa, wie man Datenbanken anspricht oder eigene Appender schreibt, außerdem noch das eine oder andere Rezept für Log::Log4perl. Das Tutorial auf [2], die Manualseiten auf [3] und die Log4j-Dokumentation auf [4] sollten aber den größten Hunger vorerst stillen. Für mehr gibt es die Mailingliste auf Sourceforge [3], auf der sich der Perl-Onkel aus Amerika gerne um alle Anfragen kümmert. Man sieht sich! (uwo)