NETWAYS Blog

Der erste Schritt bei Fehlern ist meist der Versuch, anhand von Logmeldungen nachzuvollziehen, was die Anwendung zuletzt gemacht hat, bevor das Problem aufgetreten ist. Hier zeigt sich dann schnell, wie gut die Anwendung darauf vorbereitet ist, dem Benutzer bei der Fehlersuche zu helfen. Dazu einige Beispiel:

[2014-05-28 09:47:04 +0200] <Q #0x7f5a08c68780 W #0x7f5a08c688c0> critical/remote: Cannot connect to host 'voip.beutner.name' on port '5665'

Auf den ersten Blick sieht es so aus, als würde die Verbindung nicht aufgebaut werden können. Aber es fehlen einige wichtige Informationen, um die Logmeldung in den Kontext einordnen zu können:

• Wer hat aus welchem Grund versucht die Verbindung aufzubauen bzw. was für eine Art Verbindung ist es? (Datenbank? Cluster? Was ganz anderes?)
• Warum ist der Verbindungsaufbau gescheitert („Connection refused“ in diesem Fall, wenn man mit strace nachschaut, warum der connect()-Aufruf fehlschlägt)?
• Welche Auswirkungen hat dies (in diesem Fall wird der Verbindungsaufbau periodisch erneut versucht, wodurch sich auch die Frage stellt, ob der Fehler wirklich „critical“ ist)?

Die andere Seite des Spektrums bietet eine wahre Informationsüberflutung und ist mindestens genauso schlecht:

Caught unhandled exception.
Current time: 2014-05-28 09:46:51 +0200
***
* Application version: v2.0.0-beta1-8-g641ff1f
* Installation root: /home/gbeutner/i2
* Sysconf directory: /home/gbeutner/i2/etc
* Local state directory: /home/gbeutner/i2/var
* Package data directory: /home/gbeutner/i2/share/icinga2
* State path: /home/gbeutner/i2/var/lib/icinga2/icinga2.state
* PID path: /home/gbeutner/i2/var/run/icinga2/icinga2.pid
* Application type: icinga/IcingaApplication
***
/home/gbeutner/icinga2/lib/base/application.cpp(671): Throw in function void icinga::Application::UpdatePidFile(const icinga::String &, pid_t)
Dynamic exception type: boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<std::runtime_error> >
std::exception::what: Could not open PID file '/home/gbeutner/i2/var/run/icinga2/icinga2.pid'
[icinga::StackTrace*] =
(0) libbase.so: void boost::throw_exception<boost::exception_detail::error_info_injector<std::runtime_error> >(boost::exception_detail::error_info_injector<std::runtime_error> const&) (+0xb3) [0x7fec91f6b323] (throw_exception.hpp:61)
(1) libbase.so: void boost::exception_detail::throw_exception_<std::runtime_error>(std::runtime_error const&, char const*, char const*, int) (+0x66) [0x7fec91f64c96] (exception.hpp:276)
(2) libbase.so: icinga::Application::UpdatePidFile(icinga::String const&, int) (+0xe7) [0x7fec91f5de87] (application.cpp:671)
(3) libbase.so: icinga::Application::Run() (+0xd9) [0x7fec91f627f9] (basic_string.h:287)
(4) icinga2: Main() (+0x740c) [0x4250cc] (??:0)
(5) icinga2: main (+0x25) [0x4252a5] (??:0)
(6) libc.so.6: __libc_start_main (+0xfd) [0x7fec9023dead] (libc-start.c:276)
(7) ./sbin/icinga2() [0x41dbf9]
[icinga::ContextTrace*] =
***
* This would indicate a runtime problem or configuration error. If you believe this is a bug in Icinga 2
* please submit a bug report at  and include this stack trace as well as any other
* information that might be useful in order to reproduce this problem.
***
Aborted

In dieser Fehlermeldung sind soviele Informationen versteckt, dass es für den Benutzer schon teilweise schwierig wird, überhaupt die eigentliche Fehlermeldung („Could not open PID file ‚/home/gbeutner/i2/var/run/icinga2/icinga2.pid'“) zu finden. Und trotzdem fehlt hier eigentlich eine ganz entscheidende Information: Warum ist das Öffnen der Datei denn eigentlich gescheitert?
Für mich als Entwickler sind solche Fehlermeldungen natürlich sehr praktisch: Ich weiss genau – abgesehen vom fehlenden Fehlercode, in welcher Zeile und zu welchem Zeitpunkt der Fehler aufgetreten ist; die Fehlermeldung beinhaltet die Pfade zu wichtigen Dateien. Diese Details helfen mir, das Problem zu reproduzieren bzw. evtl sogar direkt anhand des Stacktraces zu finden.
Die beiden Beispiele verdeutlichen einige Eigenschaften, die Fehlermeldungen haben sollen, um den Benutzer bei der Fehlersuche zu helfen:

• Sie sollten kurz und einfach zu verstehen sein (keine Stacktraces, Klassennamen, o.ä.)
• Sie sollten alle wichtigen Informationen enthalten (Dateinamen, Fehlercode)
• Sie sollten den Benutzer in Richtung der Problemlösung leiten (z.B. bei EPERM -> Hinweis auf Datei-Berechtigungen)
• Zusätzlich sollten die für Entwickler wichtigen Informationen aber trotzdem bereitgehalten werden; vielleicht als Referenz auf eine separate Log-Datei, die dann auch gerne seitenlange Stacktraces enthalten kann

Dass bei den Logmeldungen von Icinga 2 dieses Ideal noch nicht erreicht ist, haben wir im Bugtracker zusammengefasst und arbeiten fleissig daran, dies noch zu verbessern. Wer beim Testen noch auf etwas unhandliche Fehlermeldungen stößt, sollte dazu Issues erstellen, damit wir diese für die Beta 2 noch anpassen können.