Tutorial: Fehler im syslog suchen / das syslog zähmen

  • Hallo,


    im syslog finden sich viele wichtige Hinweise für die Problemsuche, zum Beispiel, wenn der VDR Boot-Schwierigkeiten hat. Jeder, der sich daran gewöhnt, sich im syslog-Dschungel zu orientieren, ist klar im Vorteil.


    Das Grundproblem mit dem syslog-Lesen ist zunächst die schiere Unmenge an Informationen. Das nächste Problem ist, dass ältere syslog-Einträge zwar auch noch für einige Tage archiviert vorliegen, aber nicht direkt in /var/log/syslog, sondern in den übrigen syslogs, die unter /var/log/ liegen (Beispiel: /var/log/syslog.1, /var/log/syslog.2.gz, etc.).


    Meist geht es erstmal darum, über die Suche nach einem bestimmten Schlüsselwort im syslog sich an die richtige Zeile (und Uhrzeit) heranzupirschen, oft genutzte Suchwörter sind beispielsweise "segfault", "error" oder "failed". Um solche aufwändigen "greppereien" zu vereinfachen, habe ich für mich - und natütrlich andere - ein Shellskript namens vdrhealth.sh geschrieben, welches hier helfen soll.


    vdrhealth durchsucht alle Dateien namens syslog* in /var/log. Damit ist es hilfreich, wenn man sich einen Überblick über die Zuverlässigkeit des VDRs über einen bestimmten Zeitraum machen will. - Ist Problem X nur einmal während der letzten 25 Boots aufgetreten oder vielleicht sogar viel häufiger?


    Ich möchte die Nutzungsweise des Scripts anhand des Beispiels: "Findet der VDR beim Boot immer alle meine DVB-Devices?" erläutern.


    Beispiel: Findet der VDR beim Boot immer alle meine DVB-Devices?


    in yaVDR 0.2 haben wir versucht, den Bootvorgang zu beschleunigen, so dass das VDR-Backend im Vergleich zu anderen Distributionen sehr schnell gestartet wird. Bei einigen Usern wird der VDR zu einem Zeitpunkt gestartet, wo die DVB-Devices vom Kernel noch gar nicht oder noch nicht vollständig registriert worden sind. Würde er einige Sekunden später starten, wären sie registriert und die Welt wäre in Ordnung. (Insbesondere USB-Geräte brauchen oft ein wenig länger als PCI-Karten.)


    Weil es in yaVDR 0.2 keinen Abwarte-Mechanismus gibt, der kontrolliert, ob alle erwarteten Geräte da sind (yaVDR 0.3 ist das "dvbmon", in zukünftigen Releases wird sich das ganze aber wieder radikal ändern), kann es also passieren, dass von drei vorhandenen DVB-Geräten nur zwei, nur eins oder gar keins erkannt wird beim Booten, obwohl man sich sicher ist, dass für alle drei Geräte Treiber und Firmware vorhanden / korrekt installiert sind. (Diese Sicherheit gewinnt man, wenn man bei laufendem PC das VDR-Backend beendet und neu startet, zum Beispiel über's Web-Frontend. Wenn nach dem Restart des VDR-Backends alle DVB-Geräte korrekt erkannt werden, sieht es nach einem Timing-Problem beim Booten aus.)


    Syslog lesen macht schlau


    Im syslog kann man genau sehen, wieviele DVB-Geräte das VDR-Backend beim Starten entdeckt hat, wenn man dort nach der richtigen Zeile sucht. Die sieht bei mir zum Beispiel so aus:

    Code
    1. Aug 20 02:38:47 yavdr02 vdr: [805] found 2 DVB devices


    Und so filtert man genau diese Zeilen aus dem ganzen Wust im syslog heraus:

    Code
    1. grep "found .* DVB device" /var/log/syslog

    Dieser Befehl sollte einem die Einträge mit dieser Zeile auflisten, evtl gibt es noch einen schöneren Regex als diesen.


    Weil es ein Timing-Problem ist, kann es auch sein, dass es nur manchmal auftritt, manchmal aber auch nicht. Von zehn Bootvorgängen sind vielleicht 6 erfolgreich und bei 4 Boots tritt so ein Problem auf.


    Um für einen zuverlässigen Boot den Startvorgang von VDR dann künstlich hinauszuzögern, ist es erstmal interessant, in Erfahrung bringen, wie lange die eigenen DVB-Devices im Normalfall brauchen, um beim Booten initialisiert zu werden und was die Maximalwerte aus der Praxis sind.


    Shellscript VDRHealth


    Um sowas leichter zu analysieren, habe ich das Shellscript vdrhealth.sh gebastelt, welches das syslog (auch die älteren syslog-Archivdateien) durchsucht und nur die hierfür interessanten Zeilen rauswirft. Das Script (welches übrigens mein erstes Shellscript ist, also nicht meckern), wirft auch noch je nach Konfiguration mehr oder weniger zusätzliche Zeilen aus. So wird einem gezeigt, wann der Rechner ungefähr gestartet worden ist und wann er einen Shutdown gemacht hat, wann der Kernel die DVB-Geräte initialisiert hat und andere wichtige Kleinigkeiten.


    Das Script ist noch in Entwicklung, kann sich also noch ändern. Die jewels neueste Version gibt es hier:
    https://svn.origo.ethz.ch/yavdr/trunk/misc/vdrhealth.sh


    So kann man es installieren und nutzen:

    Code
    1. wget https://svn.origo.ethz.ch/yavdr/trunk/misc/vdrhealth.sh
    2. chmod +x vdrhealth.sh
    3. ./vdrhealth.sh

    Das Script erstellt im Verzeichnis, in dem es aufgerufen wird einen Report, in dem so eine Art Best-Of-Syslog drin ist. Man sieht darin ungefähr, was der VDR-Rechner die letzte Woche über so gemacht hat.


    Beispielzeilen aus VDRHealth:


    Diese Zeile deutet darauf hin, dass der Rechner gerade gestartet worden ist:

    Code
    1. Aug 16 19:44:47 yavdr02 kernel: imklog 4.2.0, log source = /proc/kmsg started.


    Diese Zeile deutet darauf hin, dass der Rechner gerade einen Shutdown macht:

    Code
    1. Aug 17 00:22:43 yavdr02 kernel: Kernel logging (proc) stopped.


    Das war's schon?
    Sicherlich sind viele Fragen unbeantwortet geblieben, aber das kann ja im Dialog geklärt werden. Es ist noch kaum was geschrieben worden darüber, wie man die Verbosity des Scripts modifieziert.


    Über Fehler automatisch informiert werden


    Neben diesem Script verwende ich noch log2mail, um per E-Mail über Fehlermeldungen im syslog informiert zu werden. log2maíl zu konfigurieren, ist aber relativ dösig und bei Gelegenheit möchte ich dafür mal LogSurfer/LogSurfer+ oder swatch ausprobieren.


    Gruß
    hepi

  • Hallo,


    nachdem der obige Beitrag vom August 2010 in den Untiefen des Portals abgetaucht war, haben meine Teamkollegen mich ermutigt, ihn etwas umzuschreiben und anzupinnen. Gesagt, getan, nun nur noch ein kleines Posting untendran (dieses), damit der Thread auch ein wenig Aufmerksamkeit findet... :unsch


    Gruß
    hepi

  • Wenn es wiederkehrende Fehler gibt und man vielleicht wissen will ob/wie oft die auftreten, dann ist das ganz sicher nicht dumm. Klar, unsereins überfliegt das syslog und checkt anhanddessen nach Gefühl ein paar Sachen ab. Aber ohne Erfahrung ? Oder meinst du wenn man nach Fehlern sucht sollte man das Log nicht anschauen sondern es einfach so wissen (zB per Handauflegen)


    Sorry aber manche Kommentare ärgern mich


    :umleitung

  • Zitat

    Original von hepi
    Hallo,


    nachdem der obige Beitrag vom August 2010 in den Untiefen des Portals abgetaucht war, haben meine Teamkollegen mich ermutigt, ihn etwas umzuschreiben und anzupinnen. Gesagt, getan, nun nur noch ein kleines Posting untendran (dieses), damit der Thread auch ein wenig Aufmerksamkeit findet... :unsch


    Gruß
    hepi


    Warum soll das dumm sein?
    Meinst du dein Weg ist der einzig richtige zum Ziel.

    VDR:
    Hardware: Thermaltake DH102, Zotac ION ITX-F-E, 2Gig Ram, TechnoTrend
    dual DVB-S2 6400, TechnoTrend Connect CT-3650,


    Software: EasyVDR 1.0

  • Hallo,
    hilfreich wenn man einen Fehler, zum Beispiel per Fernbedienung, auslösen kann ist auch:

    Code
    1. sudo tail -f /var/log/syslog


    Strg+c beendet das wieder.


    Gruß Ulf


    About schönere Regex:

    Code
    1. sudo dmesg| grep ERROR


    Was übrigen wie immer unter Linux andere Dinge findet als:
    sudo dmesg| grep error

  • Genau. Wobei der Parameter -i dann bei grep -i error sowohl Zeilen mit "error" als auch "ERROR" findet.


    Und dieser Befehl zeigt einem live auftrende Zeilen mit "error" oder "ERROR" an:


    Code
    1. tail -f /var/log/syslog | grep -i error


    So kann man parallel zum Live-Betrieb sehen, ob ein bestimmter Fehler auftritt. Zum Beispiel bei unzuverlässiger Empfangsqualität oder USB-Problemen oder Ähnlichem.


    Man muss aber schon vorher wissen, welchen error man sucht.


    Gruß
    hepi

  • Zitat

    Original von hepi
    Und dieser Befehl zeigt einem live auftrende Zeilen mit "error" oder "ERROR" an:

    Code
    1. tail -f /var/log/syslog | grep -i error


    Einspruch , Euer Ehren,
    genau das ist "überfiltert" wie e9hack oben schon anmerkte ;-)


    ein fortgesetztes tail (weil-f ) noch einem grep vorzulegen macht wirklich wenig Sinn,
    beim dem tail will ich ja gerade sehen was aktuell im syslog landet und nicht immer steht error an den Meldungen die zur Lösung führen.


    Gruß Ulf

  • Du hast Recht, für das Beispiel "error" ist es nicht das Gelbe vom Ei, aber es gibt Fälle, wo ich genau diesen Befehl brauche und keinen anderen:

    Code
    1. tail -f /var/log/syslog | grep -i "iso frame descriptor has an error"

    Mich interessiert im Zusammenhang mit der Fehlersuche im Thread Darstellungsproblem bei 2 TT-3600 USB nur diese eine Fehlermeldung "iso frame descriptor has an error". Ich weiß schon vorher genau, welche Fehlermeldung es ist, aber ich will wissen, ob, wann und wie oft sie auftritt. Und ich will das Live-TV-Bild und gleichzeitig das Live-Syslog im Auge behalten, um zu sehen, ob synchron mit dem Fehler Artefakte im Bild kommen.


    Es ist aber wirklich eher ein Spezialfall.


    Viele Grüße
    hepi