thomas_strecker
I'm new here

Aussagekräftige Logs?!

Jump to solution

Hallo,

Ich habe folgende Fehlermeldungen im Deployment/der Generierung:

ERROR 

[–] 12.08.2011 12:28:57 ERROR 12.08.2011 12:28:57.671 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

ERROR 

[–] 12.08.2011 12:28:57 ERROR 12.08.2011 12:28:57.218 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

ERROR 

[–] 12.08.2011 12:27:58 ERROR 12.08.2011 12:27:58.955 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction):  at 0, 0: Method Invocation urlCreator.getUrl at line 78

ERROR 

[–] 12.08.2011 12:26:36 ERROR 12.08.2011 12:26:36.984 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

ERROR 

[–] 12.08.2011 12:26:36 ERROR 12.08.2011 12:26:36.532 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

ERROR 

[–] 12.08.2011 12:26:16 ERROR 12.08.2011 12:26:16.754 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

ERROR 

[–] 12.08.2011 12:26:16 ERROR 12.08.2011 12:26:16.754 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

Kann mir irgend jemand sagen, was ich aus diesen Fehlermeldungen erkennen soll? Ich habe mal die umgebenden Logs für 2 Meldungen rausgesucht:

ERROR 

[–] 12.08.2011 12:28:57 ERROR 12.08.2011 12:28:57.671 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.638 {seID=321515} (de.espirit.firstspirit.store.access.sitestore.PageRefImpl): generating page reference 'industrialautomation_2' (id=820800, html, EN)

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.638 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): creating output stream for '/en/hannovermesse/ueber_die_messe/programm/_1_column_4/leitmessen/industrialautomation/industrialautomation_2.xhtml'

und

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.449 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): creating output stream for '/en/hannovermesse/ueber_die_messe/programm/_1_column_4/leitmessen/industrialautomation/automationproductnewsletter.xhtml'

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.221 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): copy file content industrialautomation_akquibroschuere2012 (id=843071), lang = EN, to media/en/01informationenfraussteller/broschueren_3/Industrial-Automation_Informationsbroschuere-fuer-Aussteller_information-brochure-for-exhibitors2012.pdf

ERROR 

[–] 12.08.2011 12:28:57 ERROR 12.08.2011 12:28:57.218 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): java.lang.NullPointerException

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.198 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): copy picture HM_11_IA_BI_Process_Automation_HM10_H09_4066701 (id=367034), lang = EN, res = picture_accordion_100, to media/04bilder/aufloesungsunabhaengig_1/2011_5/HM_11_IA_BI_Process_Automation_picture_accordion_100.jpg

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.190 {seID=321515} (de.espirit.firstspirit.generate.SiteProduction): copy picture HM_11_BI_kleine_Buehne_Industrial_Automation (id=426257), lang = EN, res = ORIGINAL, to media/en/04bilder/stage/Industrial-Automation.png

INFO  

[–] 12.08.2011 12:28:57 INFO  12.08.2011 12:28:57.176 {seID=321515} (de.espirit.firstspirit.store.access.sitestore.PageRefImpl): generating page reference 'industrialautomation_1' (id=391554, html, EN)

0 Kudos
1 Solution

Accepted Solutions

Hallo Herr Strecker,

Wenn Sie schreiben, man benötigt die "drüberliegenden INFO Meldungen", meinen Sie tatsächlich im Log vorher stehende Meldungen oder zeitlich vorausgehende Meldungen? Im Log, wie ich es im Monitoring Bereich sehe, stehen nämlich die ältesten Seiten ganz unten.

Sorry, ich lesen die Logfiles immer als Textdateien (direkt das fs-server.log aus dem Dateisystem), und da sind die Fehlermeldungen dann genau anders herum sortiert als im Server-Monitoring.

Ich meinte die zeitlich vorrausgehenden Meldungen.

Die Fehler traten bei uns "spontan" auf, d.h. beim letzten Deployment funktionierte alles, jetzt gibt es Probleme. In diesem Fall handelt es sich sogar um ein produktives System. Wenn wir jetzt für alle Seiten, die das entsprechende Template verwenden, den Debug-Modus einschalten, wird das Deployment sicherlich viel länger dauern, oder?

Die "spontan" auftretenden Fehler resultieren aber wahrscheinlich aus Änderungen im projekt (zum Beispiel wurde ein Medium neu verlinkt, welches nie freigegeben wurde und auf dieses wird nun versucht per Skript zuzugreifen, ohne das geprüft wird, ob das Medium wirklich existiert.

Die Dauer des Deployments wird sich verlängern, aber diese Verlängerung sollte marginal sein.

Die Größe der Logfiles wird allerdings deutlich anschwellen.

Warum schaltet man die - gerade bei Fehlern eklatant wichtigen - Kontext-Informationen ab? Aus meiner Erfahrung weiß ich, dass man mit den richtigen Informationen (hier wären es: Seite/Inhalt bzw. ID, Kanal, Sprache, Section/Template, Stacktrace) viel schneller ans Ziel kommt als wenn man erst eine globale Einstellung anpassen muss, das ganze Projekt erneut generieren muss, dann den Fehler suchen, und am Ende der Behebung die Einstellung wieder rückgängig machen muss. Ich sage ja nicht, dass die Informationen immer geloggt werden müssen, aber im Fehlerfall (der ja hoffentlich nicht oft auftritt) ist die Information kritisch.

Eigentlich sollten diese Fehler während der Entwicklungsphase des Projektes durch entsprechende QS identifiziert und ausgeschlossen werden. Während dieser Phase macht es dann Sinn, den debugMode zu aktivieren.

Aufgrund der Angaben, auf welcher Seite der Fehler geflogen ist, die auch im normalen log zu finden sind, kann man die Generierung/Vorschau im debugMode auf einzelne Seiten beschränken. Eine Generierung des kompletten Projektes ist nur notwendig, wenn die Fehler auf sehr vielen Seiten auftreten.

P.S: Das Umstellen des global.debugMode hat von 7 Fehlern/0 Warnungen zu 7 Fehlern/4460 Warnungen geführt...

Diese zusätzlichen WARN Meldungen sind höchstwahrscheinlich Meldungen, die besagen, dass ein NULL Wert nicht abgefangen wird. Im Templatequelltext werden die meisten dieser Fehler ohne den debugMode nicht ausgegeben, da deren Ausgabe nur für die Entwicklungsphase eines Projektes von Bedeutung sein sollte.

Viele Grüsse aus Dortmund,

  Holger Höbbel

View solution in original post

0 Kudos
3 Replies
hoebbel
Crownpeak employee

Hallo Herr Strecker,

um die Größe und Lesbarkeit der Logfiles nicht übermäßig zu ändern wird der Stacktrace von Exceptions im Generierungslog nur ausgegeben, wenn der debugMode aktiviert wird:

$CMS_SET(#global.debugMode,true)$

Um die Seitenreferenz zu identifizieren, auf der es zu einem Fehler kam, benötigt man die drüberliegenden INFO Meldungen mit

generating page reference '<UID>' (id=<ID>, <CHANNEL>, <LANGUAGE>

und/oder

creating output stream for '<URL>'

Um herauszufinden, welche Stelle {wahrscheinlich ein Skript} nicht nicht abgefangenen Fehlermeldungen erzeugt, müssen Sie vor dem Auftreten des Fehlers (also entweder möglichst weit oben im Seitentemplate oder im Quelltext der globalen Einstellungsseite) den debugMode aktivieren. In der folgenden Generierung bekommen Sie dann noch zusätzlich den Stacktrace der entsprechenden Exceptions ausgegeben, was eine Fehleridentifikation erleichtern wird.

Viele Grüsse aus Dortmund,

  Holger Höbbel

Hallo Herr Höbbel,

danke für diese Informationen. Ich versuche gerade Ihre Vorschläge umzusetzen, habe aber einige Fragen dazu:

  1. Wenn Sie schreiben, man benötigt die "drüberliegenden INFO Meldungen", meinen Sie tatsächlich im Log vorher stehende Meldungen oder zeitlich vorausgehende Meldungen? Im Log, wie ich es im Monitoring Bereich sehe, stehen nämlich die ältesten Seiten ganz unten.
  2. Die Fehler traten bei uns "spontan" auf, d.h. beim letzten Deployment funktionierte alles, jetzt gibt es Probleme. In diesem Fall handelt es sich sogar um ein produktives System. Wenn wir jetzt für alle Seiten, die das entsprechende Template verwenden, den Debug-Modus einschalten, wird das Deployment sicherlich viel länger dauern, oder?
  3. Warum schaltet man die - gerade bei Fehlern eklatant wichtigen - Kontext-Informationen ab? Aus meiner Erfahrung weiß ich, dass man mit den richtigen Informationen (hier wären es: Seite/Inhalt bzw. ID, Kanal, Sprache, Section/Template, Stacktrace) viel schneller ans Ziel kommt als wenn man erst eine globale Einstellung anpassen muss, das ganze Projekt erneut generieren muss, dann den Fehler suchen, und am Ende der Behebung die Einstellung wieder rückgängig machen muss. Ich sage ja nicht, dass die Informationen immer geloggt werden müssen, aber im Fehlerfall (der ja hoffentlich nicht oft auftritt) ist die Information kritisch.

Mit freundlichen Grüßen

    Thomas Strecker

P.S: Das Umstellen des global.debugMode hat von 7 Fehlern/0 Warnungen zu 7 Fehlern/4460 Warnungen geführt...

0 Kudos

Hallo Herr Strecker,

Wenn Sie schreiben, man benötigt die "drüberliegenden INFO Meldungen", meinen Sie tatsächlich im Log vorher stehende Meldungen oder zeitlich vorausgehende Meldungen? Im Log, wie ich es im Monitoring Bereich sehe, stehen nämlich die ältesten Seiten ganz unten.

Sorry, ich lesen die Logfiles immer als Textdateien (direkt das fs-server.log aus dem Dateisystem), und da sind die Fehlermeldungen dann genau anders herum sortiert als im Server-Monitoring.

Ich meinte die zeitlich vorrausgehenden Meldungen.

Die Fehler traten bei uns "spontan" auf, d.h. beim letzten Deployment funktionierte alles, jetzt gibt es Probleme. In diesem Fall handelt es sich sogar um ein produktives System. Wenn wir jetzt für alle Seiten, die das entsprechende Template verwenden, den Debug-Modus einschalten, wird das Deployment sicherlich viel länger dauern, oder?

Die "spontan" auftretenden Fehler resultieren aber wahrscheinlich aus Änderungen im projekt (zum Beispiel wurde ein Medium neu verlinkt, welches nie freigegeben wurde und auf dieses wird nun versucht per Skript zuzugreifen, ohne das geprüft wird, ob das Medium wirklich existiert.

Die Dauer des Deployments wird sich verlängern, aber diese Verlängerung sollte marginal sein.

Die Größe der Logfiles wird allerdings deutlich anschwellen.

Warum schaltet man die - gerade bei Fehlern eklatant wichtigen - Kontext-Informationen ab? Aus meiner Erfahrung weiß ich, dass man mit den richtigen Informationen (hier wären es: Seite/Inhalt bzw. ID, Kanal, Sprache, Section/Template, Stacktrace) viel schneller ans Ziel kommt als wenn man erst eine globale Einstellung anpassen muss, das ganze Projekt erneut generieren muss, dann den Fehler suchen, und am Ende der Behebung die Einstellung wieder rückgängig machen muss. Ich sage ja nicht, dass die Informationen immer geloggt werden müssen, aber im Fehlerfall (der ja hoffentlich nicht oft auftritt) ist die Information kritisch.

Eigentlich sollten diese Fehler während der Entwicklungsphase des Projektes durch entsprechende QS identifiziert und ausgeschlossen werden. Während dieser Phase macht es dann Sinn, den debugMode zu aktivieren.

Aufgrund der Angaben, auf welcher Seite der Fehler geflogen ist, die auch im normalen log zu finden sind, kann man die Generierung/Vorschau im debugMode auf einzelne Seiten beschränken. Eine Generierung des kompletten Projektes ist nur notwendig, wenn die Fehler auf sehr vielen Seiten auftreten.

P.S: Das Umstellen des global.debugMode hat von 7 Fehlern/0 Warnungen zu 7 Fehlern/4460 Warnungen geführt...

Diese zusätzlichen WARN Meldungen sind höchstwahrscheinlich Meldungen, die besagen, dass ein NULL Wert nicht abgefangen wird. Im Templatequelltext werden die meisten dieser Fehler ohne den debugMode nicht ausgegeben, da deren Ausgabe nur für die Entwicklungsphase eines Projektes von Bedeutung sein sollte.

Viele Grüsse aus Dortmund,

  Holger Höbbel

0 Kudos