Wandlungsfähig

Rubys leistungsfähigste Logging-Bibliothek log4r

Markus Jais

Effektives Logging ist Bestandteil jeder nicht trivialen Geschäftsanwendung. Aussagekräftige Einträge in Logdateien oder ähnlichem sind meist unverzichtbar bei der Fehlersuche und Überwachung von kritischen Anwendungen. Rubys log4r-Bibliothek bietet eine Vielzahl von Möglichkeiten, mit denen man das Logging an die jeweiligen Bedürfnisse anpassen kann.

Wenn Sie ein kleines, kurzes Programm in der Kommandozeile starten, welches nur eine einzige einfache Sache erledigt (z.B. eine Datei kopieren) dann sehen Sie in der Shell sofort, ob das geklappt hat oder nicht. Ist z.B. die Datei, welche Sie kopieren wollen, nicht vorhanden, wird Ihnen das in der Regel angezeigt. Aber stellen Sie sich vor, dass Sie täglich um Mitternacht ein Ruby-Skript starten, welches aus einer Datenbank HTML-Seiten für eine Statistik über die tagsüber verkauften Produkte generiert und diese dann per FTP auf einen Rechner kopiert, auf welchen Ihre Marketing-Kollegen Zugriff haben. Nun sind Sie um Mitternacht wohl nur selten noch im Büro (zumindest hoffe ich das für Sie) und werden daher das Programm z.B. per cron starten. Eines Tages ruft Sie der Chef aus der Marketing-Abteilung an und beschwert sich, dass die Statistiken fehlen und das auch noch genau an dem Tag, an welchem er einen Bericht für den Vorstand fertig stellen soll. In solch einem Fall ist es äußerst nützlich, wenn Sie schnell in der Lage sind, den Fehler zu finden.

Da Sie ein sorgfältiger Programmierer sind, haben Sie über das ganze Skript verteilt Logging-Ausgaben eingebaut. So wird z.B. vor dem Kopieren der Datei via FTP eine Log-Ausgabe in eine Datei geschrieben und bei erfolgreichem Kopieren noch einmal. Außerdem protokollieren Sie sämtliche Fehler mit. So sehen Sie z.B. gleich, dass Sie nichts auf den FTP-Server kopieren konnten, weil Ihr Passwort plötzlich nicht mehr stimmt. Ein kurzer Anruf beim Windows-Administrator klärt die Sache auf. Er hatte das Passwort geändert, aber vergessen, Sie davon zu unterrichten. So lässt sich das Problem ganz leicht beheben. Hätten Sie keinerlei Logging-Ausgaben zur Hand gehabt, wäre die Fehlersuche wesentlich aufwändiger gewesen. Ich hoffe, Sie sehen, dass Logging für nahezu alle Programme, welche Sie entwickeln, ein essenzieller Bestandteil ist.

Logging mit log4r

In Rubys Standardbibliothek befindet sich eine einfache Logging-Bibliothek namens logger. Diese reicht für einfache Anwendungen aus. Hier wollen wir uns aber log4r zuwenden, welches wesentlich mächtiger und flexibler ist. Falls Sie RubyGems verwenden, ist die Installation von log4r ein Kinderspiel. Tippen Sie einfach folgenden Befehl in der Kommandozeile:

psenv::pushli(); eval($_oclass[„“]); psenv::popli(); ?>

gem install log4r

Falls Ihnen die erforderlichen Rechte fehlen, müssen Sie diesen Befehl ggf. als root oder mit sudo ausführen. Falls Sie RubyGems nicht verwenden, können Sie sich log4r auf dessen Homepage herunterladen. In Listing 1 sehen Sie ein erstes einfaches Beispiel.

Listing 1
------------------------------------------------------------
#!/usr/local/bin/ruby 


require 'rubygems'
require 'log4r'

include Log4r

log = Logger.new('my_log')
log.outputters = FileOutputter.new('f1', :filename => "./my_log.log")

log.debug("just a debug message")
log.info("important information")
log.warn("you better be prepared")
log.error("now you are in trouble")
log.fatal("this is the end...")

Wenn Sie RubyGems nicht verwenden, löschen Sie folgende Zeile: require ‘rubygems‘

Wenn Sie bereits log4j für Java benutzt haben, wird Ihnen an diesem Beispiel einiges bekannt vorkommen. Aber auch ohne Vorkenntnisse ist es nicht schwer zu verstehen. Als Erstes erzeugen wir ein Logger-Objekt. Das Argument für new ist der Name des Loggers. Dieser ist z.B. nützlich, wenn Sie eine Hierarchie von Loggern aufbauen wollen. Die „Kinder“ eines Loggers erben dann dessen Fähigkeiten.

Nachdem wir den Logger erzeugt haben, legen wir noch fest, wohin die Lognachrichten geschrieben werden sollen. Dazu stellt log4r eine Reihe von so genannten Outputtern zur Verfügung. Neben dem hier verwendeten Fileoutputter gibt es u.a. die Möglichkeit, Lognachrichten per E-Mail zu verschicken oder an den syslog-Daemon zu senden. Außerdem gibt es Outputter, welche täglich neue Logfiles anlegen oder die Logausgabe an ein beliebiges IO-Objekt senden (z.B. an ein Socket). Eine vollständige Übersicht finden Sie in der log4r-Dokumentation. Der hier verwendete Fileoutputter bekommt als erstes Argument einen Namen, welcher intern zur Verwaltung aller Outputter verwendet wird und anschließend einen Hash mit verschiedenen Optionen. Uns reicht hier der Parameter :filename. Anschließend loggen wir fünf verschiedene Nachrichten mit je einem unterschiedlichen Loglevel. log4r bietet fünf vordefinierte Loglevel. DEBUG, INFO, WARN, ERROR und FATAL. Sie können den Loglevel auch so setzen, dass z.B. nur alle Log-Nachrichten mit WARN oder schlimmer geloggt werden. DEBUG wird zum Beispiel oft nur während der Entwicklung benutzt, aber im Produktivbetrieb dann abgeschaltet.

Wenn Ihnen die vordefinierten Loglevels nicht zusagen, können Sie auch ganz einfach eigene definieren. Ein Beispiel dazu sehen Sie in Listing 2.

Listing 2
-----------------------------------------------------------------
#!/usr/local/bin/ruby 


require 'rubygems'
require 'log4r'
require 'log4r/configurator'

include Log4r

Configurator.custom_levels(:NORMAL, :BAD, :VERY_BAD)

log2 = Logger.new("my_log2")
pf = PatternFormatter.new(:pattern => "%l %d %m")
fo = FileOutputter.new('f2', :filename => "./my_log2.log", :formatter => pf)

log2.outputters = fo
log2.level = BAD
log2.normal("this is not logged")
log2.very_bad("this is logged")

Hier definieren wird die Loglevel NORMAL, BAD und VERY_BAD. Nachdem wir unseren Logger erzeugt haben, setzen wir den Loglevel auf BAD, sodass die nachfolgende Lognachricht für den Level NORMAL nicht in der Logdatei erscheint, aber die Nachricht für VERY_BAD schon. Sie sehen auch, dass Ruby die Methodenaufrufe für die neu definierten Loglevel automatisch zur Verfügung stellt. Das wird durch die dynamischen Fähigkeiten von Ruby ermöglicht. In Sprachen wie Java oder C++ wäre so etwas nicht so einfach oder gar nicht möglich. Außerdem sehen Sie hier auch noch die Verwendung eines sog. Formatters. Formatter dienen dazu, die Lognachrichten besser zu formatieren. Sie können so die Logdateien lesbarer gestalten oder auch für die maschinelle Auswertung optimieren. Der hier benutzte Patternformatter verwendet einen Formatstring ähnlich dem von Rubys print-Methode (oder wie man ihn auch von Cs printf-Funktion her kennt). Die hier verwendeten Formatangaben %l, %d und %m bedeuten nacheinander: Loglevel, aktuelle Zeit und die eigentliche Lognachricht (genauer gesagt, das was zurückgegeben wird, wenn to_s für die Lognachricht aufgerufen wird). Es gibt noch weitere Formatangaben, welche Sie in der log4r-Dokumentation finden. Eine sehr interessante Formatangabe ist %t, welche den Namen und die Zeilennummer der Quelldatei in der Lognachricht ausgibt. Leider verursacht %t zumindest auf meinen Linux-Rechner mit Ruby 1.8.4 und log4r 1.0.5 einen Fehler. Aber vielleicht ist das bereits gefixt, wenn Sie diesen Artikel lesen.

Konfigurationsdateien

Wie Sie in den bisherigen Beispielen sehen konnten, lässt sich log4r direkt im Ruby-Quellcode konfigurieren. Das ist nicht immer praktikabel. Daher erlaubt log4r die Konfiguration mittels XML und YAML. Ich werde Ihnen hier die XML-Variante vorstellen. Im Listing 3 sehen Sie eine einfache log4r-Konfigurationsdatei.

Listing 3
--------------------------------------------------------------
NORMAL, BAD, VERY_BAD#{logpath}/my_log.logBADfalse%d %l: %m%Y-%m-%d %H:%M:%SSTDOUTFILE

Auch wenn man kein großer XML-Fan ist, ist dieses Beispiel hier nicht weiter schwer zu verstehen. Im Tag <pre_config> werden globale Einstellungen gemacht, wie z.B. die eigenen Loglevels NORMAL, BAD und VERY_BAD. Außerdem sagen wir log4r, dass falls es keine spezielleren Angaben gibt, immer alle Nachrichten mit dem Level NORMAL oder schlimmer (also in diesem Beispiel alles) geloggt werden soll.

Anschließend definieren wir zwei Outputter. Da wir für den StdoutOutputter keine weiteren Angaben machen, übernimmt er die Einstellungen aus <pre_config> und die globalen log4r-Einstellungen, was das Logformat usw. betrifft. Für den zweiten Outputter setzen wir dagegen eine ganze Reihe von Optionen. Zuerst einmal legen wir fest, dass es sich um einen Fileoutputter handelt. Mit <filename> legen wir den Namen der Logdatei fest. Den Wert #{logpath} setzen wir später in unserem Ruby-Programm. Da wir in die Logdatei nur Lognachrichten schreiben wollen, welche mindestens das Loglevel BAD haben, setzen wird dieses mit <level>. <trunc>. Es legt fest, ob die Logdatei bei jedem neuen Start unseres Programms neu geschrieben werden soll oder ob die Lognachrichten an eine bestehende Datei angehängt werden sollen. Mit dem <formatter> geben wir sowohl die Formatierung der eigentlichen Lognachricht an (mit <pattern>) sowie die exakte Formatierung von Datumswerten.

Zum Schluss definieren wir noch zwei Logger für die Ausgabe in die Konsole bzw. in die Logdatei. Diese können wir dann in unserem Ruby-Programm verwenden. Es bietet sich oft an, einen Logger für die Konsole und einen weiteren für eine Logdatei zu definieren. So können Sie beim Starten Ihres Programms evtl. gleich sehen, ob es Probleme gibt, und gleichzeitig haben Sie die Lognachrichten dauerhaft in einer Datei gesichert. Nun müssen wir nur noch unsere Konfigurationsdatei verwenden. Wie das geht, sehen Sie in Listing 4.

Listing 4
------------------------------------------------------------
#!/usr/local/bin/ruby 


require 'rubygems'
require 'log4r'
require 'log4r/configurator'

include Log4r

Configurator['logpath'] = '/var/tmp/ruby_logs'
Configurator.load_xml_file('log4r_conf.xml')


std_log = Logger['stdout']
file_log = Logger['logfile']


std_log.normal("normal message")
std_log.very_bad("very bad message")

file_log.normal("normal message")
file_log.very_bad("very bad message")

Um die XML-Datei zu laden verwenden wir Configurator.load_xml_file. Vorher setzen wir noch den Wert für logpath. Anschließend können wir auf die am Ende der XML-Datei definierten Logger zugreifen und diese auch gleich verwenden. Wenn Sie dieses kleine Programm starten, werden Sie sämtliche Nachrichten in der Konsole sehen, aber nur die VERY_BAD-Nachrichten in der Logdatei.

Wie viel Logging?

Solange Sie Ihre Anwendung testen, ist es meist sinnvoll, so viel wie möglich zu loggen und das Loglevel so einzustellen, dass alles geloggt wird. Im späteren Produktivbetrieb müssen Sie dann selbst entscheiden, ob Sie weiterhin alles loggen wollen oder zum Beispiel nur noch kritische Fehler. Treten Fehler auf, ist man auch im produktiven Einsatz oft froh, wenn man ausführliche Logdateien hat. Eventuell kann zu intensives Logging zu Performance-Einbußen führen. Im Zweifel ist es ratsam, dies ausgiebig zu testen. Auch können bei Anwendungen unter hoher Last bei intensivem Logging die Logdateien schnell sehr groß werden und dadurch eventuell unübersichtlich. Eine allgemein gültige Regel, wann man wie viel loggen soll, gibt es nicht. Sie müssen also von Fall zu Fall entscheiden, was für Ihre Anwendung am besten ist.

Fazit

Wie Sie sehen können, ist die Benutzung von log4r nicht schwierig. Die hier gezeigten einfachen Beispiele sollen Ihnen helfen, einen schnellen Einstieg in log4r zu finden. Auf der Website des Projektes finden Sie weitere Dokumentation. Ein sehr interessantes Kapitel dazu finden Sie auch in dem sehr empfehlenswerten Buch von Maik Schmidt: „Enterprise Integration with Ruby“ (Maik Schmidt: Enterprise Integration with Ruby. Pragmatic Bookshelf, 2006).

Markus Jais ist Softwareentwickler. In seiner Freizeit trifft er sich mit Freunden, geht Wandern, beschäftigt sich mit Ruby, Perl, Python, Java, MySQL und PostgresSQL und lernt Spanisch. Im Internet ist er unter www.mjais.de zu finden.
Geschrieben von
Markus Jais
Kommentare

Schreibe einen Kommentar

Deine E-Mail-Adresse wird nicht veröffentlicht.