Logs finden und verstehen - Webserver Error Log

vanilla_thunder · October 4, 2020, 1:02am

Wenn man ein Problem mit dem Shop meldet, wird man fast immer nach den Logs gefragt.
Hier erzähle ich euch, wo man diese Logs findet und wie man sie versteht.

Webserver Error Log

(nicht zu verwechseln mit dem Access Log)
Der Webserver selbst ist dafür zuständig, diesen Log zu befüllen. Neben echten Fehlermeldungen über gescheiterte Funktionsaufrufe oder “Rechtschreibfehler” im Code, schreibt der Webserver auch alles rein, was bei der Ausführung von PHP Scripts negativ auffällt: veralteter Code, unbekannte Variablen, fehlende Berechtigungen im Dateisystem, etc.

Wo dieser Log entsteht, hängt von der Konfiguration des Webservers und somit von eurem Hoster ab:
einige Hoster haben einen gesonderten Menüpunkt “Logs” oder “Protokolle” irgendwo in der Hosting-Verwaltungsoverfläche, andere Hoster überlassen es dem Kunden, den Log zu aktivieren.

In den Systeminformationen im Admin könnt ihr sehen, ob und wie dieser Log konfiguriert ist:

Von Bedeutung sind für uns diese Konfigurationsparameter:

log_errors - aktiviert/deaktiviert das Protokollieren in den Fehler-Log.
error_log - der Pfad der Log-Datei.
“no value” bedeutet, dass der Pfad zu der Datei nicht vorgegeben ist, somit wird auch kein Log geführt, egal ob log_errors an oder aus ist.
error_reporting regelt, was in den Log geschrieben werden und was nicht.
Dieser Parameter wird vom OXID selbst vorgegeben und wir brauchen ihn nicht weiter zu beachten.

Wer dennoch mehr erfahren möchte, kann das hier aufklappen.

Es gibt mehrere Typen von Meldungen, stark zusammengefasst gibt es:

Strict - Hinweise zur Verbesserung der Code-Kompatibilität.
Deprecated - Info über Funktionen, die in den nächsten PHP Versionen nicht mehr existieren. Im Moment funktioniert aber alles einwandfrei.
Notice - Hinweise auf kleine Problemchen im Code, meistes durch unsauberen oder veralteten Code bedingt. Kommt bei OXID ziemlich oft vor. Vergleichbar damit, wenn man auf der Straße ins Rutschen kommt, aber nicht hinfällt.
Warning - Hinweise auf Probleme im Code, die aber nicht zum kompletten Stillstand geführt haben. Man ist zwar hingefallen, konnte danach aber aufstehen und mit angeschlagenem Selbstwertgefühl weiter gehen.
Error - Probleme im Code, die zum kompletten Stillstand geführt haben. Klappe zu, Affe tot.

Wirklich wichtig sind für uns Errors und Warnings, da sie auf Beeinträchtigungen der Shopfunktionen hinweisen. Notices sollte man eigentlich im Auge behalten, aber OXID besteht zur Hälfte aus unsauberem veralteten Code, weswegen der Log zu 90% aus Notices bestehen würde.
Deswegen wird error_reporting im Code von OXID auf den Wert “E_ALL & ~E_DEPRECATED & ~E_NOTICE” bzw. 24567 festgelegt.
https://github.com/OXID-eSales/oxideshop_ce/blob/v6.5.6/source/bootstrap.php#L8

Die Aufschlüselung der einzelnen Typen von Meldungen und deren Kombination für diesen Konfigurationsparameter kann mit diesem Tool berechnet werden: PHP Error Reporting Level/Bitmask Calculator

Error Log aktivieren und konfigurieren

Mit dem nachfolgenden Code sollte der Webserver seine Meldungen in die Datei source/log/error.log im Shop schreiben.

Code für die .htaccess Datei:

php_flag log_errors On
php_value error_log /absolute/path/to/shop/source/log/error.log

(für der error_log Pfad könnt ihr config.inc.php öffnen und den Wert von sShopDir + “/log/error.log” nehmen)

Code für die index.php Datei:

ini_set('log_errors ',1);
ini_set('error_log',dirname(__FILE__).'/log/error.log');

Fehlermeldungen lesen

Der Format der Einträge im Log hängt von der Konfiguration des Servers ab und früher enthielt jeder Eintrag ebenfalls die IP-Adresse des Verursachers, aber prinzipiell sehen die Einträge etwa so aus:

[Datum + Uhrzeit] Typ der Meldung: Fehlermeldung + wo die Fehlermeldung aufgetreten ist.

Dabei entspricht jede Zeile in der Log-Datei einem Eintrag.
Je nachdem, wie und wo der Fehler passiert ist, kann die Fehlermeldung mal mehr mal weniger Infos enthalten. Z.B. die Fehlermeldungen von Smarty enthalten einige zusätzliche Infos.

Wenn ihr nach den Logs gefragt werden, versucht die zeitlich relevanten Logs zu finden und diese zu posten. Und bitte kontrolliert die veröffentlichten Logs auf persönliche Daten, wie E-Mail Adressen, IP-Adressen oder Passwörter. Wir schauen zwar auch immer drauf, aber Vorsicht ist immer besser als Nachsicht.

Es gibt ein Modul, mit dem man die Fehler-Logs bequem im Admin Interface des Shops auswerten kann:
– Link und Info werden in Kürze ergänzt –

Fehlerursachen beheben

Falls ihr selbst auf die Jagd gehen wollt, gibts noch ein Paar wichtige Hinweise.
Es gibt zwei Arten von Fehlern:

Fehler, die man selbst verursacht hat, z.B. durch eine Modul-Installation oder durch Änderung eines Tempaltes. Das besten an diesen Fehlern ist, dass man weiß, was dazu geführt hat und wie man sie reproduziert.
Fehler, die bei anderen auftauchen, z.B. wenn der Kunde im Shop surft und irgendwohin klickt oder irgendwelche unvorhergesehenen Daten eingibt (Sonderzeichen in Firmennamen, Apostrophe, Hausnummern mit Buchstaben, etc), oder Fehler die durch ein Script/Cronjob ausgelöst werden.

Der Kontext eines Fehlers ist oft sehr hilfreich für seine Lösung. Bei einigen Fehlermeldungen erschließt sich der Kontext von selbst, z.B. bei Fehlern in den Templates ist es klar: der Shop hat versucht ein Template zu rendern, konnte es wegen einem Fehler im Code aber nicht tun.
Ich hatte aber auch schon einen Log gesehen, der über mehrere Monate täglich mehrmals den selben Fehler enthielt: eine bestimmte Funktion, die vor kurzem entfernt wurde, konnte nicht gefunden werden. Quasi, als würde es irgendwo noch den Aufruf dieser Funktion geben, obwohl das Modul entfernt wurde. Es hatte sich dann herausgestellt, dass der Fehler von einer Preissuchmaschine verursacht wurde, die täglich mehrmals den Shop scannen wollte und deren Betreiber eine URL mit diesem Funktionsaufruf hinterlegt hatte.

Ein weiterer wichtiger Punkt ist, dass Fehler bzw. ihre Ursachen nicht immer genau an der Stelle und in der Datei sind, wo die Fehlermeldung aufgetreten ist.
Stellt es euch so vor: ihr gießt euch ein Glas Milch ein und nehmt einen Schluck. Und da wird euch schlagartig klar, dass die Milch abgelaufen ist. Das ist die Fehlermeldung. Die Milch ist aber nicht erst im Glas schlecht geworden, sondern irgendwann vorher und es ist lediglich erst jetzt klar geworden, dass da was nicht stimmt.
(Die erste Regel der Arbeit im IT-Bereich ist: traue niemals dem Inhalt einer Milchpackung)

Es gibt natürlich viele mögliche Ursachen:

der Milchproduzent (also die Kuh) hat schlechte Qualität geliefert
der Milchbauer hatte ein Problem bei der Verarbeitung
der Lieferant hatte Probleme
der Händler hat die Milch unsachgemäß gelagert
der Kühlschrank im Büro ist kaputt
jemand hat die Milch übers Wochenende auf dem Tisch stehen lassen
rein logisch muss ich auch in Betracht ziehen, dass die Milch tatsächlich erst im Glas schlecht geworden sein könnte, weil ich nicht nachweisen kann, ob sie vorher OK oder nicht OK war.

Ihr müsst zuerst die möglichen Ursachen im Hinblick auf ihre Wahrscheinlichkeit und Aufwand der Prüfung abwägen und zuerst das prüfen, was man am einfachsten prüfen kann:

Man könnte mit sehr wenig Aufwand die Kühlschranktür öffnen und fühlen, ob es drin kalt ist.
Man könnte sich ebenfalls daran erinnern, dass diese Milch vor 3 Tagen noch OK war.
Man könnte beim Einzelhändler anrufen und fragen, ob es Beschwerden übder dieses Produkt gab.

Dann gibt es noch Ursachen, die wir nicht prüfen können. Dazu zählen in diesem Fall alle Prozesse, die vor dem Erwerb der Milchpackung stattfanden. Ein deutlich realitätsnäheres Beipsiel wäre ein Problem mit angebundenen Drittanbietern, wie Payment Gateways, Import/Exporte, Repricing Tools etc. Auch solche Probleme kommen vor, da muss man sich mit den Dienstleistern in Verbindung setzen.

Gehen wir mal ein paar Fehlermeldungen durch, die ich hier im Forum oder in meinem Dev-Shop gefunden habe:

[timestamp] Parse error: syntax error, unexpected ‘:’, expecting ‘;’ or ‘{’ in /vendor/oxid-esales/oxideshop-ce/source/Core/Email.php on line 2307

Dieser Fehler betrifft eine der Core-Klassen von OXID.
Da OXID Code ausgiebig getestet wird, ist ein echter Fehler dort extrem unwahrscheinlich und es kommt auf den Kontext an: der Fehler tritt nur dann auf, wenn der Script per Cronjob ausgeführt wird.
Die Ursache für das Problem ist also nicht der Code (im normalen Shop-Betrieb funktion alles), sondern die Weise, wie der Code ausgeführt wird.
Wir wissen ja, dass es mehrere PHP Versionen gibt und man sie beim Hoster irgendie einstellen kann, aber nur die ITler wissen, dass in der Console und über den Browser ebenfalls unterschiedliche PHP Versionen zur Verfügung stehen.
Für alle anderen Menschen ist dies eine der Sachen, die man auf die harte Weise lernt: ein mal darüber stolpern und danach weiß man Bescheid.(Ach was, wir ITler haben das genau auf die gleiche Weise gelernt, nur viel früher )

[timestamp] PHP Fatal error: Smarty error: [in page/details/inc/deliverytime.tpl line 14]: syntax error: unclosed tag \{if} (opened line 1). (Smarty_Compiler.class.php, line 312) in /srv/oxid/dev/vendor/smarty/smarty/libs/Smarty.class.php on line 1100

Das ist eine sehr einfacher und eindeutiger Smarty-Fehler: In der Datei ‘page/details/inc/deliverytime.tpl’
wurde in der Zeile 1 ein [{if ... }] Tag geöffnet, aber nicht mehr geschloßen.

Die Fehlerbehebung ist genau so einfach: Datei im Editor öffnen und entweder ist da ein [{if ...}] zu viel oder ein [{/if}] zu wenig. Ein typischer Copy-Paste Fehler.

[timestamp] PHP Warning: file_put_contents(/pfad/zum/shop/var/configuration/shops/1.yaml): failed to open stream: Permission denied in /pfad/zum/shop/vendor/oxid-esales/oxideshop-ce/source/Internal/Framework/Storage/YamlFileStorage.php on line 84

Das Problem hier ist ziemlich klar: fehlende Berechtigung. Doch warum fehlen sie?
Der Kontext hilft unheimlich: dieser Fehler kommt dann, wenn ich Moduleinstellungen im Admin speicheren möchte und sie nicht gespeichert werden. Davor hatte ich ein neues Modul über Composer installiert.
Die Ursache muss sein, dass bei der Installation die Schreibrechte im var Ordner geändert werden, also muss man sie nach der Installation wieder manuell anpassen. (Passier bei mir, weil ich Composer mit meinem SSH Benutzer ausführe und der Webserver hinterher die Dateien nicht ändern darf)

[timestamp] PHP Fatal error: Smarty error: [in layout/base.tpl line 107]: syntax error: $smarty.cookie is an unknown reference (Smarty_Compiler.class.php, line 2164) in /pfad/zum/shop/vendor/smarty/smarty/libs/Smarty.class.php on line 1100

Hier ist es wie mit der Milch: die Fehlermeldung ist zwar in Smarty.class.php in der Zeile 1100 aufgekommen, aber passiert ist der Fehler schon vorher und der Smarty Compiler ist so klug, uns diese Info in der Fehlermeldung zu geben: [in layout/base.tpl line 107].
Kontext: Ich hatte dieses Template vorher geändert und eine Zeile mit dem Code [{$smarty.cookie}] eingefügt.
Die Fehlerbehebung ist eindeutig: $smarty.cookie ist dem Shop nicht bekannt, also muss man den neuen Code wieder entfernen und die richtige Variable suchen.
Dieser Fehler kommt vor, wenn man Code aus älteren Beiträgen in eine neuere Shop-Version kopiert.

[timestamp] PHP Fatal error: Smarty error: [in ox:2eb4676806a3d2e87.060765230 line 17]: syntax error: unrecognized tag: $oCont-&gt;oxcontents__oxtitle->value (Smarty_Compiler.class.php, line 441) in /srv/oxid/dev/vendor/smarty/smarty/libs/Smarty.class.php on line 1100

Diese Fehlermeldung ist etwas komplizierter, aber man sieht, dass der Smarty Tag $oCont-&gt;oxcontents__oxtitle->value dieses Problem verursacht.
Offensichtlich wurden -> in dem Tag encoded und nun da steht stattdessen ‘->’ oder ->. Die WYSIWYG Editoren machen sowas gelegentlich.
Aber wo ist dieser fehlerhafte Tag versteckt?
Die Fehlermeldung taucht zwar wieder im Smarty Compiler auf, aber im Compiler gibts keine Smarty Tags, sie sind nur in Templates und in CMS Seiten. Die Info vom Compiler besagt, dass der Fehler “[in ox:2eb4676806a3d2e87.060765230 line 17]” liegt und das ist schon mal keine Template Datei, also müssen wir in CMS Seiten suchen.
Wer mit PhpMyAdmin (oder ähnlichen Tools) und SQL vertraut ist, kann in der Tabelle oxcontents nach einem Teil des problematischen Codes suchen “oxcontents__oxtitle” und die Seiten einzeln prüfen.
Sehr hilfreich ist es, wenn der Fehler auf dedizierten Shop-Seiten von bestimmten CMS Seiten auftritt, z.B. Impressum oder AGB und nicht auf den Seiten, wo CMS Seiten nur als kleine Inhaltsblöcke eingefügt werden. Im letzteren Fall muss man im Code des entsprechenden Templates schauen, welche CMS Seite dort eingebunden werden und diese CMS Seiten einzeln prüfen.
Wenn man die betroffene CMS Seite gefunden hat, muss man die kodierten Zeichen in den Smarty Tags durch die Originale ersetzen: “-&gt;” zu “->” machen und speichern, am besten direkt über PhpMyAdmin, damit der Fehler nicht nochmal vom Editor verursacht wird.
(Übrigens, die Zeichenkette “2eb4676806a3d2e87.06076523” aus “ox:2eb4676806a3d2e87.060765230” ist die oxID der CMS Seite und die letzte “0” ist die Sprach-ID, in dem Fall also die Primärsprache.)

Hätte ich den Fehler nicht selbst produziert, indem ich die Smarty Tags in einer CMS Seite verunstaltet habe, hätte ich bestimmt auch lange danach gesucht. Deswegen ist so wichtig, alle Änderungen in den Templates und CMS Seiten sofort zu testen, so habt ihr immer den Kontext zu möglichen Fehlern.

Am Ende sind die Fehler, die man selbst verursacht, auch am einfachsten zu lösen.
Bei “fremden” Fehlern muss man Antworten auf folgende Fragen finden:

wann hat es das letzte mal funktioniert?
was hat sich seitdem verändert?
wenn das Problem nicht direkt reproduzierbar ist:
welche Gemeinsamkeiten gibt es zwischen den Problemfällen und welche Unterschiede zu den erfolgreichen Tests?

Und scheut euch nicht davor, im Forum nach Hilfe zu fragen!
Danke auch an die Hartnäckigen, die bis hierher gelesen haben!