Go on a Bughunt in production, but without a map!
Dirk Kröhan, Javaland Vortrag 2023
Die Folgen von Fehlverhalten einer Software reichen von schlichter Unannehmlichkeit bis hin zu einem Totalausfall. Daher sollte bereits während der Entwicklungsphase ausgiebig getestet werden. Allerdings kann es trotz ausführlicher manueller und automatisierter Tests nie eine Korrektheitsgarantie geben. Schlussendlich kann ein Fehlverhalten der Software im Produktivbetrieb nicht ausgeschlossen werden und wird früher oder später passieren. Um das Fehlverhalten nachträglich korrigieren zu können, muss die Fehlerursache nachvollziehbar sein. Das setzt insbesondere die Nachvollziehbarkeit des Zustands vorraus, indem sich das System zum Zeitpunkt des Fehlverhaltens befindet. Um den Zustand eines Systems nachvollziehen zu können, wird in der Regel Logging verwendet. Beim Logging werden Zustandsnachrichten (bzw. Log-Nachrichten) vom System generiert und abgespeichert. Um die für ein Fehlverhalten relevanten Log-Nachrichten schnell identifizieren zu können, ist es wichtig, die insgesamt generierten Log-Nachrichten auf das nötige Minimum zu reduzieren. Das “nötige Minimum” unterscheidet sich jedoch abhängig von dem zu analysierenden Fehlverhalten. Die gängige Lösung ist das Kategorisieren der Log-Nachrichten nach “Log-Level”. Übliche Kategorisierungen sind “ERROR” (Unerwarteter, fehlerhafter und nicht handhabbarer Systemzustand), “WARN” (Fehlerhafter, aber handhabbarer Systemzustand), “INFO” (Erwarteter, für Nachvollziehbarkeit relevanter Systemzustand), “DEBUG” (Erwarteter, für erhöhte Nachvollziehbarkeit relevanter Systemzustand). Im Produktivbetrieb kann dann konfiguriert werden, welchem Log-Level eine Nachricht entsprechen muss, um ausgegeben zu werden. Dieser Ansatz verhindert bei entsprechender Konfiguration das übermäßige Generieren von Log-Nachrichten, hat aber den Nachteil, dass eine feingranulare Änderung des Log-Levels während der Fehleranalyse nicht möglich ist. Wird das Log-Level im gesamten oder einem Teil des Systems während der Fehleranalyse angepasst, werden für alle Systemaktivitäten Zustandsnachrichten entsprechend dem angepassten Log-Level generiert, unabhängig davon, ob sie für die Fehleranalyse relevant sind, oder nicht. Das wiederum kann zu einer Überflutung an Log-Nachrichten führen, was die Fehleranalyse wiederum erschwert. Stattdessen wäre es notwendig, das Log-Level nur für die für die Fehleranalyse relevanten Systemaktivitäten konfigurieren zu können.
Technische Umsetzung
Anstatt das Log-Level auf Systemebene zu konfigurieren, wird es auf Request-Ebene konfiguriert. Das heißt, für einen eingehenden Request entscheided das System, auf welchem Log-Level es für den Request relevante Log-Nachrichten ausgeben soll. Ein einfacher Weg zur Umsetzung ist das Setzen eines HTTP-Headers. Als Beispiel nennen wir unseren HTTP-Header ‘enable-debug-logging’ und setzen den Header auf true, falls Debug-Logging für den Request aktiviert werden soll. Hat der Header den Wert false oder ist nicht gesetzt, wird das Log-Level nicht verändert. Im Backend verwenden wir Spring. Zur Auswertung des HTTP-Headers brauchen wir einen Request-Filter. Außerdem brauchen wir eine RequestScoped-Bean, in der wir ein Flag entsprechend dem ausgelesenen HTTP-Header setzen.
@Component
class LoggingFilter implements javax.servlet.Filter {
@Inject
private RequestLoggingState loggingState;
@Override
public void doFilter(ServletRequest servletRequest,
ServletResponse servletResponse, FilterChain filterChain) throws IOException,
ServletException {
if(servletRequest instanceof HttpServletRequest httpServletRequest) {String headerValue =
httpServletRequest.getHeader("enable-debug-logging");
if(Boolean.TRUE.toString().equals(headerValue)) {
loggingState.setDebugLoggingEnabled(true);
}
}
}
}
@Component
@Scope(value = WebApplicationContext.SCOPE_REQUEST,
proxyMode = ScopedProxyMode.TARGET_CLASS)
class RequestLoggingState {
private boolean debugLoggingEnabled = false;
public boolean isDebugLoggingEnabled() {
return debugLoggingEnabled;
}
public void setDebugLoggingEnabled(boolean debugLoggingEnabled) {
this.debugLoggingEnabled =
debugLoggingEnabled;
}
}
Für das Logging verwenden wir Logback. Logback erlaubt das Implementieren von Filtern, mit denen Log-Nachrichten dynamisch verworfen werden können. In Logback hat man die Wahl zwischen einem klassischen Filter und einem TurboFilter. TurboFilter haben einen geringeren Overhead und sind daher bevorzugt zu verwenden.
class DebugLoggingLogbackFilter implements TurboFilter {
@Inject
private RequestLoggingState requestLoggingState;
@Override
public FilterReply decide(Marker marker, Logger logger,
Level level, String s, Object[] objects, Throwable throwable) {
if(requestLoggingState.isDebugLoggingEnabled()
&& logger.getLevel().isGreaterOrEqual(Level.DEBUG)
&& level.isGreaterOrEqual(Level.DEBUG)) {
return FilterReply.ACCEPT;
}
return FilterReply.NEUTRAL;
}
}
Zum Prüfen, ob eine Nachricht geloggt werden soll gehören drei Bedingungen. Die erste Bedingung prüft, ob der HTTP-Header zum aktivieren des Debug-Loggings überhaupt gesetzt wurde. Die zweite Bedingung prüft, ob das aktuell konfigurierte Log-Level es überhaupt nötig macht, dass das DEBUG-Log-Level explizit aktiviert werden muss (falls ohnehin schon TRACE konfiguriert ist, sollte unser Filter nicht den Nebeneffekt haben, dass nur noch DEBUG geloggt wird). In der dritten und letzten Bedingung prüfen wir, ob das Log-Level der aktuellen Log-Nachricht DEBUG ist. Sind alle drei Bedingungen erfüllt, wird die Nachricht geloggt. Ansonsten lassen wir die Entscheidung offen, indem wir FilterReply.NEUTRAL zurück geben. In diesem Fall wird die Nachricht dann anhand des aktuell konfigurierten Log-Levels geloggt. Ist alles korrekt implementiert, wird nun für alle HTTP-Requests mit dem Header ‘enable-debuglogging: true’ das Debug-Logging aktiviert und die Fehleranalyse beim nächsten Bug in Production hoffentlich einfacher…
