About Javascript Logging

In komplexen Projekten kommt üblicher Weise der Zeitpunkt, an dem es unverzichtbar wird für die Qualitätssicherung weitere Maßnahmen zu ergreifen. In einer losen Serie möchte ich auf einige dieser Aspekte eingehen:

  • Logging
  • Crash Reporting
  • Support und Feedback

In diesem Artikel beleuchte ich das Logging.

Ebenen / Level

Die einfachste Form eines Log Eintrages ist eine Nachricht. Doch schnell wird klar, dass das alleine nicht mehr reichen wird und etwas mehr Kontext erforderlich ist. Üblicherweise kommt dann schnell der Zeitstempel und der Level hinzu. Das kann dann z.B. so implementiert werden:

log.error()
log.warn()
log.info()
log.debug()

In Umgebungen wie dem Browser kann leicht danach gefiltert werden, aber in einem Logfile sieht das vielleicht schon anders aus. Aus diesem Grunde greife ich gerne auf einen Trick zurück, den ich bei der Arbeit an einem großen Projekt von meinen Kollegen gelernt habe, nämlich diese Ebenen besonders zu kennzeichnen:

E|***
W|**
I|*
D|

Ok, das sieht nett und übersichtlich aus, aber was ist daran besser?

Die Möglichkeit zu filtern ist es, denn ein Filtern nach |* wird alle Nachrichten inklusive und oberhalb von I|* anzeigen, also auch Warnungen und Fehler. |** und |*** filtern entsprechend auf höheren Ebenen. Das funktioniert auf macOS z.B. sehr gut in Xcode oder der Console App.

Zeit

Üblicherweise beginnt ein Log-Eintrag mit einem Zeitstempel. Das ist sinnvoll für ein Programm das in voller Produktivität beim Kunden oder auf dem Server läuft. Während der Entwicklung ist diese Information aber eher überflüssig und verkürzt auch den sichtbaren Bereich der Nachricht. Wenn überhaupt die Zeit interessiert, dann doch eher wie viel Zeit vergangen ist, bis dieses oder jenes geschieht. Daher kann es Sinn machen die Zeit seit dem Start des Programmes anzugeben:

I|*       0ms App launch
D|      123ms Open file abc.xyz
E|***   412ms Could not open file abc.xyz because: Does not exist

Farben und Symbole

Ein anderer Aspekt der Hilfreich ist bei der schnellen Wahrnehmung von Informationen, ist die Farbe des Eintrages. Der Browser erledigt das schon für uns, indem er die Fehler in rot darstellt. Aber in manchen Umgebungen, wie z.B. Xcode, ist die Verwendung von Farben nicht möglich oder nur umständlich zu erreichen, als Alternativer können dort Emojis dienen:

🔷 I|*       0ms App launch
◽️ D|      123ms Open file abc.xyz
❌ E|***   412ms Could not open file abc.xyz because: Does not exist

Das Rot sticht sofort ins Auge und die Fehlermeldung ist so schnell lokalisiert.

Ursprungsort der Nachricht

Ok, wir haben gesehen, es gab einen Fehler, aber wo ist dieser aufgetreten? Der tollste Log-Eintrag nützt leider nichts, wenn wir die Ursache nicht lokalisieren können. Daher kann z.B. der Dateiname und die Zeilennummer mit ausgegeben werden. Viele IDEs erlauben es durch eine bestimmte Formatierung direkt zu einem Ort zu springen. In Xcode z.B. durch CMD + SHIFT + O und dann Angabe der Datei und der Zeilennummer durch Doppelpunkt getrennt. Im Log könnte das dann so aussehen:

🔷 I|*       0ms <main.c:33> App launch
◽️ D|      123ms <AppDelegate.m:54> Open file abc.xyz
❌ E|***   412ms <AppDelegate.m:62> Could not open file abc.xyz because: Does not exist

Aber! Das sind keine Informationen, die in einer produktiven Umgebung verwendet werden sollten.

Nebenläufigkeit

Und noch ein Merkmal ist wichtig in modernen Programmen, nämlich ob die Meldung aus einem asynchronen Code Block stammt oder dem Haupt-Thread. Auch hier kann eine Visualisierung mit Emojis hilfreich sein, wie hier durch eine Rakete:

◽️ 🔷 I|*       0ms <main.c:33> App launch
🚀 ❌ E|***   412ms <MyCache.m:12> Expected files were missing

Abschluss

Auch so ein alltägliches Thema wie das Logging kann also noch Raum für Optimierungen bieten und somit an manchen Stellen Zeit sparen, weil relevante Informationen schnell erfasst werden können und auch dir Ort des Problems einfacher zu lokalisieren ist.