Logging, Fehler-Analyse

[Heri Bender, módosítva 9 év-val korábban]

Hallo
Bin z.Z. noch in der Kennenlern-/Ausprobier-Phase (Version 6.2).
Immer wieder geht etwas nicht so, wie ich mir das vorstelle. Zur Analyse eines Fehlers steht mir aber nur die (oft wenig hilfreiche) Online-Fehlermeldung zur Verfügung ("Your request failed to complete" oder ähnlich).
catalina.log und das von mir eingerichtete log4j-Logfile berichten meist nix über den grad aufgetretenen Fehler.
Log4j und Liferay ist mir ein Rätsel. Die üblichen Mechanismen im Zusammenhang mit Log4j funktionieren nicht (auto-konfiguration aus einer log4j.xml Datei im Classpath, Kommandozeilenoption -Dlog4j.debug=true hat keinen Effekt, etc.) Habe in andern Beiträgen gelernt, dass eine eigene portal-log4j-ext.xml Datei in einem META-INF\ Verzeichnis gemacht werden muss. Hab ich gemacht, und zwar in tomcat/lib/WEB-INF. Die Log-Levels habe ich mal sehr grosszügig auf Debug gestellt, und dann nur die gröbsten Viel-Logger auf Level INFO gestellt (siehe Beilage)
Das Log-File wird tatsächlich in root/logs angelegt. Aber die darin enthaltenen Informationen sind sehr spärlich. Eigentlich nur solches Zeugs, das mich (im Moment) nicht interessiert (Rendering, etc.).
Wenn im Frontend eine Fehlermeldung kommt, dann muss doch irgendwo eine Exception passiert sein. Aber kein einziger Eintrag auf WARN oder ERROR level zu finden. Da müsste doch viel mehr sein.
Selber bin ich Java-Entwickler und eigentlicher Log4j-Spezialist, aber ich verstehe nicht wirklich, wie Liferay dieses Tool einsetzt.
Z.B.:
- Was soll der Java-Util command-line param im startup-Script? Ich hab ja log4j
- Das gleiche mit den ewigen Wiederholungen in jedem Portlet von logging.properties, welche alle auf eine Konsole loggen (die ja in einem Server gar nicht vorhanden ist).
- Hab gesehen, dass in der Server-Administration die Log-Levels eingestellt werden können. Aber ich will doch nicht im Ernst alle 333 aufgeführten Klassen einzeln auf Debug stellen. Dafür ist doch die hierarchische Organisation der package Struktur vorgesehen. Und mir kann niemand angeben, dass Liferay nur aus 333 Klassen besteht. Ich bin es gewohnt, log4j per Config-File zu tunen. Aber wie?

Kann mir da mal jemand auf die Sprünge helfen? Was habe ich falsch verstanden?

PS: In den Wiki's und den diversen Guides (User, Admin, Developer) ist fast nix über das Logging zu finden, und das, was zu finden ist, ist teilweise nur halb wahr, zumindest ziemlich unbrauchbar.

[Olaf Kock, módosítva 9 év-val korábban]

Heri Bender:

PS: In den Wiki's und den diversen Guides (User, Admin, Developer) ist fast nix über das Logging zu finden, und das, was zu finden ist, ist teilweise nur halb wahr, zumindest ziemlich unbrauchbar.

Ich kann zwar mit dieser Antwort keine vollständige Dokumentation ersetzen, allerdings vielleicht einige der o.a. Annahmen ins rechte Licht rücken.

Liferay wird üblicherweise - wie gewohnt - mit log4j Konfigurationsdateien konfiguriert. Die Konfiguration via Web-UI ist transient, beim nächsten Neustart wird sie wieder durch die dateibasierte Grundkonfiguration ersetzt. Der nette Nebeneffekt davon ist, dass "zeitweise" hochgesetzte Loglevel nicht dauerhaft die Logfiles vollschreiben. Daher sollte die tatsächliche Konfiguration nicht über dieses UI erfolgen und es ist nicht auf besonders effektive Arbeit (Hierarchien etc.) ausgelegt. Das könnte man sicher mal ändern, durch die Grundannahme der temporären Anpassung ist das jedoch üblicherweise kein besonderer Schmerz (korrigiere mich jemand, wenn das doch der Fall ist).

Ich verstehe den Absatz über eine benötigte META-INF/portal-log4j-ext.xml, die allerdings in tomcat/lib/WEB-INF abgelegt wird: Ich hätte erwartet, dass diese Datei im Classpath liegen muss. Tomcat erwartet in einem lib directory aber üblicherweise jar files, keine einzelnen Dateien. Daher würde ich durchaus erwarten, dass die dort abgelegte portal-log4j-ext.xml wirkungslos bleibt.

Was die Relevanz der Fehlermeldungen in Front- wie Backend angeht, bitte ich - gerade im Fall von üblichen Operationen, die mit einer nicht ausreichenden Fehlermeldung quittiert werden - um den Eintrag eines Tickets. Das gilt übrigens unabhängig vom tatsächlichen Logging: Normale Benutzeroperationen sollen auch ohne Einbindung eines Systemadministrators (vulgo: Logfile) vernünftige Fehlermeldungen bringen.

[Heri Bender, módosítva 9 év-val korábban]

Danke für die Informationen. Dass die Änderungen per GUI nicht persistiert werden, habe ich z.B. noch nicht mitbekommen

Classpath: log4j würde normalerweise eine im Classpath liegende Datei log4j.xml automatisch finden und für seine Konfiguration verwenden. In Liferay funktioniert dies nicht (hab ich ausprobiert, z.B. mit -Dlog4j.debug=true auf der Kommandozeile). Codestudium hat mir gezeigt, dass LR eine portal-log4j-ext.xml Datei im Folder <classpath>/META-INF sucht. Und da tomcat/lib im classpath liegt, schien es mir naheliegend, dort meine Konfiguration global unterzubringen.

Wenn ich einen System-Start im Debugger durchsteppe, dann sehe ich, dass zunächst das Java-Logging initialisiert wird. Die initialisierten Logger- etc. Klassen werden komplett durch ein LR-eigenes Log-Adapter-Framework gekapselt (mit ähnlichem Interface wie commons-logging). Im weiteren Verlauf wird auch, aufgrund eines Flags in portal.properties, log4j geladen. Es scheint, dass dann die gesamten gekapselten Log-Instanzen durch Log4j-Implementationen ausgewechselt werden. Erst ab diesem Zeitpunkt erscheinen Log-Einträge in meinem konfigurierten DailyRollingFileAppender. Aber, wie in der Antwort unten schon gesagt, vermute ich, dass hier nur ein kleiner Teil der von LR erfolgten Log-Statements Eingang finden. Ich möchte aber eigentlich alle relevanten Logeinträge in einem File finden, angefangen vom Systemstart.

Ticket-Erstellung: Eine Ticket macht m.E. keinen Sinn, wenn nicht minimale Hintergrundinformationen mitgeliefert werden können. Ein Ticket à la "Beim Speichern meines Blog-Beitrags kam die Fehler-Meldung: 'Vorgang konnte nicht erfolgreich abgeschlossen werden'. Was mache ich falsch?" ohne weitere Begleitumstände ist wohl völlig sinnlos, da kein Mensch darauf eine Antwort haben kann. Meiner Erfahrung nach ist aber gerade ein gutes Logging die wichtigste Grundlage, Fehlverhalten zu verfolgen und die Gründe dafür zu erkennen.

[Heri Bender, módosítva 9 év-val korábban]

Niemand da im deutschsprachigen Raum, der sich mit log4j in Liferay auskennt? Oder anders gefragt: Mit welchen Mitteln spürt ihr Systemfehler auf?

Nun, ich habe dieselben Fragen im englischen Benutzer-Forum nochmals gestellt: Question in english message board

[André Bunse, módosítva 9 év-val korábban]

Hallo Heri,

also in meinem letzten Projekt habe ich einige Versuche unternommen, um das Logging innerhalb von Liferay zu vereinheitlichen.

Ziel war es, wirklich alle Logausgaben an eine Ausgabe umzuleiten und am Ende auch die Möglichkeit zu haben, das ganze Remote
per Socket abzufragen und zu filtern. (z.B. Apache Chainsaw)

In diesem Zusammenhang habe ich mit slf4j und den einzelnen Bridges rumgespielt. (siehe => http://www.slf4j.org/legacy.html)

Ich weiss nur, dass am Ende nicht alles funktioniert hat wie es sollte und es hat auch die Zeit gefehlt weiterzutesten.

Quellen hab ich leider auch keine mehr zur Hand, wo ich noch mal reinschauen könnte. Sorry.

Viel Erfolg, kannst ja mal berichten, wie es ausgegangen ist.

gruß

[Heri Bender, módosítva 9 év-val korábban]

Wo hast Du denn die verschiedenen Logs gefunden, bevor Du vereinheitlicht hast? Wie gesagt finde ich von den meisten Log-Ausgaben keine Spur.

[André Bunse, módosítva 9 év-val korábban]

für Tomcat, definiert in ${TOMCAT_HOME}/conf/logging.properties

Darin habe ich folgende FileHandler definiert:

${TOMCAT_HOME}/logs

root.log
catalina.2014-01-01.log
localhost_access_log.2014-01-01.txt
host-manager.2014-01-01.log
manager.2014-01-01.log
localhost.2014-01-01.log

für Ausgaben auf die Console kann man noch ConsoleHandler definieren.

für Liferay, definiert in ${TOMCAT_HOME}/webapps/ROOT/WEB-INF/classes habe ich

log4j.properties
logging.properties
META-INF/portal-log4j.xml
META-INF/log4j.dtd

und dazu dann noch etliche jars in ${TOMCAT_HOME}/lib/ext

das alles unter einen Hut zu kriegen, habe ich dann halt mit slf4j versucht und
wie gesagt, es ist kein vernünftiges Ergebnis bei rausgekommen aufgrund fehlender Zeit.

Vielleicht helfen dir ein paar Infos, die du oben siehst.

gruß

[André Bunse, módosítva 9 év-val korábban]

Hallo Heri,

ich konfiguriere das Logging mit Hilfe einer log4j.properties Datei in ${TOMCAT}/webapps/ROOT/WEB-INF/classes

Hier mal ein Ausschnitt einer Minimal-Konfiguration:

default.DatePattern='.'yyyy-MM-dd
default.ConversionPattern=%d{HH:mm:ss} %-5p [%-20.20t] %-40.40C (%-5.5L)  %m%n

log4j.rootLogger=INFO, CONSOLE

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.EnhancedPatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=${default.ConversionPattern}

log4j.logger.com.liferay=ERROR
log4j.logger.com.liferay.documentLibrary=WARN
log4j.logger.com.liferay.documentLibrary.util.DLIndexer=INFO
log4j.logger.org.portletbridge=INFO
log4j.logger.org.quartz=ERROR
log4j.logger.org.springframework=ERROR

Wie man sieht, muss man nicht alle Klassen manuell einstellen, sondern kann auf oberster Ebene
Defaults vergeben für Packages und diese dann beliebig verfeinern.

Experimentiert hatte ich auch schon mit weiteren Appendern (z.B. in eine Datei oder in eine Datenbank)
und besonders interessant fand ich die Möglichkeit mit einem SocketHubAppender, der es ermöglicht
Logs per Socket abzufragen, so dass auch ohne Probleme Remote Logs angezeigt werden können.
In diesem Zusammenhang hatte ich mit Apache Chainsaw rumgespielt.

[Heri Bender, módosítva 9 év-val korábban]

Danke für die Tipps. Wie gesagt habe ich keine Probleme, log4j loggers und appenders so zu konfigurieren, wie ich es haben will. Mein Problem ist, dass selbst wenn der level relativ hoch eingestellt ist, kaum Informationen im log zu finden sind über den Verlauf eines einzelnen Requests. Ich vermute, dass meine Log-Konfiguration nur einen kleinen Teil der Sourcen betrifft.