Logging nach Bedarf mit Log::Log4perl

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!