Blog

Blog

Neues aus unserem Blog

Mit 66 Zeichen, da fängt das Logging an

Jochen Just Freitag, 11. Juli 2014 @ 19:40 geschrieben von Jochen Just

In der täglichen Arbeit ist es für viele Entwickler völlig normal, einen Tomcat über Eclipse Web Tools zu starten. Genauso üblich ist es, dass die installierten Anwendungen ein Logging-Framework (log4j, SLF4J, etc.) verwenden. Kommt nun bei mehr als einer Anwendung oder in einer der verwendeten Bibliotheken die Java Logging API (java.util.logging - JUL) zum Einsatz, gilt es eine Stolperfalle zu beachten.

Ausgangslage

In meinem Fall hatte ich mehrere Web-Anwendungen installiert. Als Logging-Framework kam Logback über SLF4J zum Einsatz. Einige der verwendeten Bibliotheken nutzten Apache Commons Logging oder log4j. Diese leitete ich über die bekannten Wege in SLF4J um. Beim Beheben eines Anwendungsfehlers fiel mir auf, dass ein Stacktrace auf System.err geloggt wurde und nicht, wie eigentlich konfiguriert, auf System.out. Der Grund hierfür war die Tatsache, dass eine 3rd-Party-Library JUL verwendet. JUL in SLF4J umzuleiten ist zwar etwas komplizierter als die oberen beiden Frameworks, aber auch schnell erledigt. Alles kein Problem.

Das dachte ich zumindest. Nach erfolgter Umleitung kam der Stacktrace zwar nicht mehr auf System.err, dafür war er aber anderweitig nirgends zu sehen. Nach einiger Zeit des Suchens fand ich die Ausgabe des Stacktraces dann doch noch - unerfreulicherweise in der Log-Datei einer der anderen installierten Anwendungen.

Analyse und Lösung des Problems

Nach erstem Kopfkratzen fiel mir auf, dass die Anwendung, bei welcher der Stacktrace schließlich landete, ebenfalls eine Bibliothek nutzte, die auch JUL verwendete. Daher war auch dort die Umleitung in SLF4J aktiv. Nur was hat das mit der anderen Anwendung zu tun?

Ein Blick in die Dokumentation von Tomcat zum Thema JUL bestätigt: Es sollte pro Webanwendung eine "JUL-Instanz" zur Verfügung stehen. Diverse Debugging-Sessions später war klar, dass in meinem Fall eben nur eine "JUL-Instanz" für den ganzen Container vorhanden war. Wie konnte das sein? Nach einigem Überlegen kam ich letztlich auf die Lösung:

Laut Dokumentation ersetzt Tomcat den Standard-LogManager des JDKs durch eine eigene Implementierung. Eben diese Implementierung sorgt dafür, dass es pro Webanwendung eine "JUL-Instanz" gibt. Dies wird in den Startskripten einer Standard-Tomcat-Installation gemacht. Aber ich benutzte ja keine Standard-Installation, sondern die Eclipse-Integration. Diese greift zwar zu großen Teilen auf eine Standard-Tomcat-Installation zurück, aber nutzt nicht deren Startskripte.

Um das Problem zu beseitigen, musste ich in der Eclipse-Run-Configuration, die den Tomcat startet, folgenden Eintrag den VM arguments hinzufügen:

-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager

Schon kam der Stacktrace an dem Ort heraus, den ich (per Logback) konfiguriert hatte. Mit etwas Glück (oder Pech) wäre ich auf den Fehler gar nicht gestoßen, wenn die Anwendung, deren Stacktrace ich umleiten wollte, nach der anderen installiert worden wäre. Die letzte Anwendung, die JUL auf SLF4J umleitet, "gewinnt" in diesem Fall.

Fazit

Obwohl man eine IDE schon viele Jahre benutzt, kann man immer noch Neues lernen. Ein einfaches VM argument kann große Auswirkungen haben.

Das Ärgerliche ist, sobald man sich die Lösung selbst langwierig erarbeitet hat, fallen einem natürlich auch die Stellen auf, an denen auf diesen Umstand hingewiesen wird:

Bleibt eigentlich nur noch die Frage offen, was das Team von Eclipse Web Tools daran hindert, dies direkt beim Anlegen der Run-Configuration zu tun.


zur Übersicht

Willkommen auf dem avono Blog

Hier auf dem avono Blog finden Sie in regelmäßigen Abständen sowohl technische Neuigkeiten aus unserer Partnerproduktwelt als auch nützliche Entwicklertipps.
Und jetzt kommt der obligatorische Disclaimer: Die Ausführungen der Blogeinträge spiegeln nicht die Meinung der avono AG sondern nur die Sicht der einzelnen Autoren wider.

Weitere Blogeinträge