Loggen für Faule (Linux-Magazin, Januar 2003)

Mit Log::Log4perl lassen sich Log-Anweisungen in Programme einbauen und schlafen legen. Meldet eine externe Konfigurationsdatei Bedarf an, erwachen die Schläfer und zeigen an, was das Programm so treibt, ohne dass man deswegen den 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 Lognachrichten aus, Prioritäten bestimmen, ob sie durchkommen und Appender leiten sie dann an konfigurierte Ausgabemedien weiter.

Prioritäten steuern, ob ein Logger die ihm übergebenen Nachrichten tatsächlich rausschreibt oder unterdrückt. Log::Log4perl bietet 5 Prioritäten: DEBUG, INFO, WARN, ERROR und FATAL. Sagt die Zentrale: ``Ich will nur Nachrichten der Priorität ERROR und höher sehen'', 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.

Logger gehören Kategorien an, die typischerweise nach der Klasse benannt sind, in der sie ihre Dienste anbieten. Die Klasse Riegel::Twix wird typischerweise eine Instanz des Loggers der Kategorie Riegel.Twix nutzen.

Der Knüller: Alle Logger eines Systems (die wahrscheinlich in dutzenden von verschiedenen 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 geschaltet werden -- es reicht, 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 -- typischerweise reicht es, eine zentrale Konfigurationsdatei anzupassen.

Das Tutorial auf [2] zeigt die Anwendung von Log::Log4perl im Detail. Heute wollen wir einmal ``Loggen für Faule'' durchnehmen -- alle Vorzüge von Log4perl ohne viel Aufwand.

Listing Building.pm zeigt 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 :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() zur Prüfung, ob noch alles im grünen Bereich läuft.

Die Klasse Building::Residential ahmt ein Privathaus nach und ist von der Basisklasse Building abgeleitet. Die Methode tv("on"|"off") schaltet den Fernseher im Wohnzimmer an und aus.

Alle drei Klassen ziehen 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 ebenfalls so exportierten Funktionen DEBUG(), INFO(), ERROR() etc. gelangen ebenfalls über das :easy-Tag in den Namensraum der jeweiligen Klasse.

Listing 1: Building.pm

    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;

Listing 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 Log::Log4perl nicht initialisiert, was im :easy-Modus seit Log::Log4perl 0.25 einfach alle Log-Anweisungen schlafen legt.

Listing 2: building.pl

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

Von der Kommandozeile ohne Argument aufgerufen, erledigt building.pl zwar seine Aufgaben, zeigt aber nichts an:

    $ building.pl
    $

Interessiert hingegen, was so im Einzelnen abgeht, empfiehlt es sich, eine Log4perl-Konfigurationsdatei nach info.conf anzulegen.

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

info.conf bestimmt, dass die Logger in der Kategorie Building und in allen ihrer Unterklassen (also im 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 PatternLayout 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. Hier ist 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. Hiesse Zeile 1 in info.conf hingegen

    1 log4perl.category.Building = DEBUG, Screen

kämen auch sie durch:

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

Geschwätz reduzieren

Wem diese Ausgabe zu geschwätzig ist und lieber nur Nachrichten aus dem Atomkraftwerk empfangen möchte, fährt besser mit einer Konfigurationsdatei wie in Listing nukeonly.conf gezeigt:

    building.pl nukeonly.conf

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

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

Listing 3: nukeonly.conf

    1 log4perl.category.Building.NuclearPowerPlant = DEBUG, Screen
    2 log4perl.appender.Screen          = Log::Dispatch::Screen
    3 log4perl.appender.Screen.stderr   = 0
    4 log4perl.appender.Screen.layout  = PatternLayout
    5 log4perl.appender.Screen.layout.ConversionPattern = %d> %m%n

Hier zeigt sich auch die Beschränkung des :easy-Ansatzes, der einfach annimmt, dass die Kategorie des gerade verwendeten Loggers gleichzusetzen wäre mit dem aktuellen Package -- was sich allerdings anhand der ererbten new-Methode in den Building::*-Subklassen als falsch herausstellt: Statt eines Building-Loggers sollte der Konstruktor einen Logger der Kategorie der gerade konstruierten Subklasse verwenden, was folgender Konstruktor richtig tut:

    sub new {
        my($class) = @_;
        my $logger = get_logger($class);
        $logger->debug("Create new $class");
        bless {}, $class;
    }

Dann stimmt auch die Ausgabe im vererbten Konstruktor:

    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!

Ausgabe in andere Kanäle

Immer nur auf STDERR auszugeben, mag vielleicht für Kommandozeilenskripts noch angehen. Im Hintergrund laufende Dämonen sollten allerdings in eine Logdatei schreiben, in eine Datenbank loggen oder Emails aussenden. Dies alles und mehr unterstützt Log::Log4perl -- natürlich nur mit Konfigurationsparametern, der Code der Applikation bleibt weiterhin unangetastet.

Listing 4: err2file.conf

    1 log4perl.category = ERROR, File
    2 log4perl.appender.File          = Log::Dispatch::File
    3 log4perl.appender.File.filename = test.log
    4 log4perl.appender.File.layout   = PatternLayout
    5 log4perl.appender.File.layout.ConversionPattern = %d %F %L %p> %m%n

Nehmen wir an, die Applikation soll ab sofort ihre ERROR-Nachrichten aller Kategorien in eine Logdatei test.log senden. Listing err2file.conf zeigt die entsprechende Konfiguration. Einfach

    building.pl err2file.conf

aufrufen und 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 einfach die Root-Kategorie, die Mutter aller anderen Kategorien, von denen dann alle 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 wir brauchen die DEBUG-Meldungen daraus auf STDERR, ohne die Ausgabe der ERROR-Meldungen nach test.log zu unterbrechen, erweitern wir die Konfigurationsdatei einfach um vier Zeilen, wie in Listing err2file2.conf gezeigt.

Listing 5: err2file2.conf

    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 
    06 log4perl.category = ERROR, File
    07 log4perl.appender.File          = Log::Dispatch::File
    08 log4perl.appender.File.filename = test.log
    09 log4perl.appender.File.layout   = PatternLayout
    10 log4perl.appender.File.layout.ConversionPattern = %d %F %L %p> %m%n
    11 log4perl.appender.File.Threshold = ERROR

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 weiterhin die oben gezeigte Ausgabe nach test.log. Die letzte Zeile in err2file2.conf ist wichtig, denn Log::Log4perl unterstützt, wie in der Dokumentation auf [3] unter ``Beginner's Pitfalls'' illustriert, Appendervererbung: Beschließt ein Logger in Building.Residential einmal, seinen Appender feuern zu lassen, blubbert die Nachricht die Appenderhierarchie hoch und wird bedingungslos von allen angeschlossenen Appendern übernommen -- im vorliegenden Fall landeten die DEBUG-Nachrichten aus Building::Residential allesamt im Root-Logger. Um dies zu verhindern setzt die letzte Zeile in err2file2.conf den Appender-Threshold des Logdatei-Appenders auf ERROR, damit die DEBUG-Nachrichten in letzter Sekunde geblockt werden.

You've got Mail!

Wichtige Ereignisse sollte man nicht in einer Logdatei verstauben lassen, sondern schnell an Interessierte weiterleiten. Explodiert das Atomkraftwerk, soll die Applikation sofort eine Email mit einer Warnung schicken. Auch dies geht natürlich, ohne in den Applikationscode einzugreifen, Listing mailerrors.conf zeigt die Konfigurationsdatei. Der Aufruf

    building.pl mailerrors.conf

schickt die in Abbildung 1 gezeigte Email and den entsetzten Adressaten.

Listing 6: mailerrors.conf

    1 log4perl.category.Building.NuclearPowerPlant = ERROR, Mailer
    2 log4perl.appender.Mailer          = Log::Dispatch::Email::MailSend
    3 log4perl.appender.Mailer.to      = l4ptest@perlmeister.com
    4 log4perl.appender.Mailer.subject = Problem im Atomkraftwerk!
    5 log4perl.appender.Mailer.layout  = PatternLayout
    6 log4perl.appender.Mailer.layout.ConversionPattern = %d %F %L> %m%n

Abbildung 1: You've got mail!

Ich hoffe, diese kurze Wirbelwindtour durch Log::Log4perl hat euren Appetit angeregt, dieses neue Modul in euren Applikationen zu verwenden. Es gäbe noch viel zu erzählen -- wie man Datenbanken anspricht, wie man eigene Appender schreibt, und auch noch das ein oder andere Rezept für Log::Log4perl. Das Tutorial auf [2], die Manualseiten auf [3] und die log4j-Dokumentation auf [4] sollten euren größten Hunger stillen. Für mehr gibt's die Mailingliste auf [3], auf der sich euer Perl-Onkel gerne eurer Anfragen annimmt. Man sieht sich!

Infos

[1]
Listings zu diesem Artikel: ftp://www.linux-magazin.de/pub/listings/magazin/2003/01/Perl

[2]
Michael Schilli, ``Retire your debugger, log smartly with Log::Log4perl!'', http://www.perl.com/pub/a/2002/09/11/log4perl.html

[3]
Das Projekt log4perl auf SourceForge: http://log4perl.sourceforge.net

[4]
Das Projekt log4j auf der Apache-Jakarta-Seite: http://jakarta.apache.org/log4j

Michael Schilli

arbeitet als Software-Engineer bei Yahoo! in Sunnyvale, Kalifornien. Er hat "Goto Perl 5" (deutsch) und "Perl Power" (englisch) für Addison-Wesley geschrieben und ist unter mschilli@perlmeister.com zu erreichen. Seine Homepage: http://perlmeister.com.