Per-Request Log-Level mit Spring Boot

Die Nutzung von Log-Ausgaben für den Einblick in die internen Abläufe von Web-Servern gehört seit vielen Jahren zum normalen Handwerkszeug. Alle im Java-Umfeld verbreiteten Logging-Bibliotheken (das ungeliebte Java Logging API, das altgediente Log4J, der Quasi-Nachfolger Logback oder der Logging-Wrapper SLF4J) bieten Log-Levels an (z.B. TRACE, DEBUG, INFO, WARN und ERROR), um die Log-Ausgaben zu filtern. Während der Entwicklung ist es unproblematisch, wenn viele Logger auf der Stufe DEBUG stehen, da alle Log-Ausgaben von eigenen Requests erzeugt werden. Was macht man aber in der produktiven Umgebung?

Hier hat man die Wahl:

1. man stellt den Großteil der Logger auf z.B. WARN - in diesem Fall ist der Inhalt des Log-Files übersichtlich, es benötigt vergleichsweise wenig Platz und der Server wird durch die Log-Ausgaben minimal ausgebremst; allerdings findet man im Log-File sehr wenig Informationen, wenn man Probleme analysieren möchte, die z.B. bei einem Kunden auftreten.
2. man stellt viele Logger auf z.B. DEBUG - in diesem Fall werden die Inhalte der Log-Files sehr schnell unübersichtlich, sie benötigen viel Platz auf dem (teuren) Storage und der Server kann signifikant bei der Bearbeitung der Requests ausgebremst werden.

Bisher habe ich immer die erste Variante genutzt und die Log-Levels der einzelnen Logger dynamisch zur Laufzeit konfigurierbar gemacht. Spring Boot bietet dieses Feature z.B. von Haus aus mittels Spring Boot Actuator. So kann man z.B. von einem Spring Boot Admin-Frontend aus die Logger manuell auf DEBUG umstellen, dann die zu analysierenden Requests auslösen und anschließend die Logger auf den urspünglichen Log-Level zurückstellen. Im Log-File findet man dann die detaillierten Log-Ausgaben, um das Problem zu analysieren. Die “normalen” Anwender sind währenddessen “leider” weiterhin aktiv und verursachen ebenfalls sehr viele, detallierte Log-Ausgaben, so dass man die eigenen relevanten Ausgaben finden und isolieren muss und während der eigenen Tests wird der Server eventuell wieder durch die Log-Ausgaben ausgebremst.

Per-Request Log-Level

Es gibt eine elegante Lösung, die alle Vorteile in sich vereint und alle Nachteile vermeidet. Wenn man es schafft, dass nur für bestimmte Requests der Log-Level aller Logger auf DEBUG steht, für alle anderen Requests aber weiterhin z.B. WARN genutzt wird, dann erziehlt man folgende Effekte:

• Die Log-Files können sehr detaillierte Log-Ausgaben enthalten, um die Fehlersuche zu unterstützen
• Die Inhalte der Log-Files bleiben trotzdem übersichtlich und können so schnell zur Fehlersuche beitragen
• Die Log-Files werden durch die Fehleranalyse nur unwesentlich größer
• Der Web-Server wird während der Fehlersuche nicht durch die Log-Ausgaben ausgebremst

Als ich von dieser Lösungsidee gehört habe, habe ich sofort versucht, sie zu implementieren und dann in eine bestehende Spring-Boot-Anwendung zu integrieren. Im Folgenden beschreibe ich meine Implementierung der Idee.

Beschreibung der Lösung

Die Requests, die einen detaillierteren Log-Level nutzen sollen, müssen besonders markiert werden. Ein einfacher und leicht nutzbarer Weg sind HTTP-Custom-Header. Ich habe dazu zwei Header definiert. Über den ersten Header kann man den Log-Level angeben, den man während des zugehörigen Requests nutzen möchte. Dieser Header hat den Default-Namen X-PER-REQUEST-LOG-LEVEL. Mit dem zweiten Header kann man optional noch den (Basis-)Namen des Loggers angeben. Dieser Header hat den Default-Namen X-PER-REQUEST-LOGGER-NAME. Falls man diesen zweiten Header nutzt, werden nur die Logger, deren Name mit dem angegebenen Namen beginnt, auf den angegebenen Log-Level gesetzt; andersfalls werden
alle Logger auf den angegebenen Log-Level gesetzt. Wenn man möchte, kann man die Namen der Header z.B. in einer application.properties-Datei umdefinieren ohne den Code zu ändern:

logging.per-request.log-level.custom-header   = X-PER-REQUEST-LOG-LEVEL
logging.per-request.logger-name.custom-header = X-PER-REQUEST-LOGGER-NAME

Bei jedem Request wird durch einen Request-Interceptor geprüft, ob diese Header angegeben wurden und ggf. die Werte der Header in den MDC (mapped diagnostic context) geschrieben. Am Ende jedes Requests werden die Werte immer aus dem MDC entfernt, so dass nachfolgende Requests nicht beeinflusst werden.

Die Inhalte des MDC sollen nun bei jeder Log-Ausgabe geprüft werden, um ggf. das Log-Verhalten zu ändern. Spring-Boot nutzt ohne weiteres zutun immer automatisch Logback als Implementierung des Logging-Systems. Logback bietet praktischerweise ein Konzept namens TurboFilters, welches genau zu den Anforderungen passt. Also nutze ich eine eigene Implementierung eines solchen TurboFilters, um mit einem sehr geringen Overhead bei jeder Log-Ausgabe eine solche Prüfung durchzuführen.

Implementierung

Der Request-Interceptor ist eine einfache Implementierung eines org.springframework.web.servlet.HandlerInterceptor:

LoggingInterceptor.java:

 1/**
 2 * Enables per-request log-level. This allows users to add custom request headers in order to set the log-level
 3 * of all or specified loggers to the desired level for only the current request. All other logging activities
 4 * (outside of the current request) will not be affected.
 5 */
 6@Component
 7public class LoggingInterceptor extends HandlerInterceptorAdapter {
 8
 9  public static final String PER_REQUEST_LOG_LEVEL_MDC_KEY   = "de.os.mobileidp.logging.LoggingInterceptor.per-request-log-level";
10  public static final String PER_REQUEST_LOGGER_NAME_MDC_KEY = "de.os.mobileidp.logging.LoggingInterceptor.per-request-logger-name";
11
12  private final       String logLevelCustomHeader;
13  private final       String loggerNameCustomHeader;
14
15  /**
16   * Creates new logging interceptor.
17   * @param logLevelCustomHeader   request header name to use for setting the desired log-level. The name of this header
18   *                               can be configured by the property <code>logging.per-request.log-level.custom-header</code>.
19   *                               This defaults to <code>'X-PER-REQUEST-LOG-LEVEL'</code>.
20   * @param loggerNameCustomHeader request header name to use for setting the desired log-level for some logger-name
21   *                               only. The name of this header can be configured by the property
22   *                               <code>logging.per-request.logger-name.custom-header</code>. This defaults to
23   *                               <code>'X-PER-REQUEST-LOGGER-NAME'</code>.
24   */
25  public LoggingInterceptor (
26          @Value ("${logging.per-request.log-level.custom-header:X-PER-REQUEST-LOG-LEVEL}")     final String logLevelCustomHeader,
27          @Value ("${logging.per-request.logger-name.custom-header:X-PER-REQUEST-LOGGER-NAME}") final String loggerNameCustomHeader) {
28    this.logLevelCustomHeader   = logLevelCustomHeader;
29    this.loggerNameCustomHeader = loggerNameCustomHeader;
30  }
31
32  /**
33   * This is called before calling the controller that handles the request. The logging interceptor enables a
34   * per-request log-level if some request header is present by adding the desired log level to the MDC.
35   * @param request  current HTTP request
36   * @param response current HTTP response
37   * @param handler  chosen handler to execute, for type and/or instance evaluation
38   * @return always {@code true}.
39   */
40  @Override
41  public boolean preHandle (final HttpServletRequest request, final HttpServletResponse response,
42                            final Object handler) {
43    final String perRequestLogLevel = request.getHeader (logLevelCustomHeader);
44    if (perRequestLogLevel != null) {
45      MDC.put (PER_REQUEST_LOG_LEVEL_MDC_KEY, perRequestLogLevel);
46    }
47    final String perRequestLoggerName = request.getHeader (loggerNameCustomHeader);
48    if (perRequestLoggerName != null) {
49      MDC.put (PER_REQUEST_LOGGER_NAME_MDC_KEY, perRequestLoggerName);
50    }
51    return true;
52  }
53
54  /**
55   * Callback after completion of request processing, that is, after rendering the view.
56   * This will remove any information about some per-request log-level from the MDC.
57   * @param request  current HTTP request
58   * @param response current HTTP response
59   * @param handler  handler that started asynchronous execution, for type and/or instance examination
60   * @param ex       exception thrown on handler execution, if any
61   */
62  @Override
63  public void afterCompletion (final HttpServletRequest request, final HttpServletResponse response,
64                               final Object handler, final Exception ex) {
65    MDC.remove (PER_REQUEST_LOG_LEVEL_MDC_KEY);
66    MDC.remove (PER_REQUEST_LOGGER_NAME_MDC_KEY);
67  }
68}

Der Turbo-Filter ist ebenfalls recht einfach: Falls der Filter noch nicht gestartet wurde oder falls der MDC keinen Wert für den PER_REQUEST_LOG_LEVEL_MDC_KEY enthält, gibt er einfach FilterReply.NEUTRAL zurück und überlässt die Entscheidung, ob die Log-Meldung ausgegeben werden soll oder nicht, einfach dem “normalen” Logging-Verhalten. Falls allerdings ein Per-Request-Log-Level angegeben wurde und der Name des Loggers mit dem Wert für den PER_REQUEST_LOGGER_NAME_MDC_KEY beginnt (falls vorhanden), so gibt er FilterReply.ACCEPT zurück und damit wird die Log-Meldung unabhängig von anderen Logging-Einstellungen ausgegeben.

LoggingTurboFilter.java:

 1/**
 2 * This logback turbo filter implements the logic, that takes some values from the MDC, that where previously
 3 * stored by the {@link LoggingInterceptor} and then decides whether to allow logging or to let others decide
 4 * whether to enable some logger or not.
 5 */
 6@Component
 7public class LoggingTurboFilter extends TurboFilter {
 8  @Override
 9  public FilterReply decide (final Marker marker, final Logger logger, final Level level, final String format,
10                             final Object[] params, final Throwable t) {
11    if (!isStarted ()) {
12      return FilterReply.NEUTRAL;
13    }
14    final String mdcLevelName = MDC.get (LoggingInterceptor.PER_REQUEST_LOG_LEVEL_MDC_KEY);
15    if (mdcLevelName != null) {
16      final Level mdcLevel = Level.valueOf (mdcLevelName);
17      if (level.isGreaterOrEqual (mdcLevel)) {
18        final String mdcLoggerName = MDC.get (LoggingInterceptor.PER_REQUEST_LOGGER_NAME_MDC_KEY);
19        if (mdcLoggerName == null || logger.getName ().startsWith (mdcLoggerName)) {
20          return FilterReply.ACCEPT;
21        }
22      }
23    }
24    return FilterReply.NEUTRAL;
25  }
26}

Was jetzt noch fehlt, ist ein wenig Code, der den LoggingInterceptor in der Spring InterceptorRegistry anmeldet und den LoggingTurboFilter zur Logback-TurboFilterList hinzufügt:

LoggingConfiguration.java:

 1/**
 2 * Configures per-request log-level feature by programmatically adding logging turbo filter to logback configuration
 3 * and adding logging interceptor to interceptor registry.
 4 */
 5@Component
 6public class LoggingConfiguration extends WebMvcConfigurerAdapter implements ApplicationRunner {
 7
 8  private final LoggingTurboFilter loggingTurboFilter;
 9  private final LoggingInterceptor loggingInterceptor;
10
11  public LoggingConfiguration (final LoggingTurboFilter loggingTurboFilter,
12                               final LoggingInterceptor loggingInterceptor) {
13    this.loggingTurboFilter = loggingTurboFilter;
14    this.loggingInterceptor = loggingInterceptor;
15  }
16
17  @Override
18  public void addInterceptors (final InterceptorRegistry registry) {
19    registry.addInterceptor (loggingInterceptor);
20  }
21
22  @Override
23  public void run (final ApplicationArguments args) {
24    getLoggerContext ().getTurboFilterList ().add (loggingTurboFilter);
25    loggingTurboFilter.start ();
26  }
27
28  private LoggerContext getLoggerContext () {
29    final ILoggerFactory factory = StaticLoggerBinder.getSingleton ().getLoggerFactory ();
30    Assert.isInstanceOf (LoggerContext.class, factory, "LoggerFactory is not a Logback LoggerContext");
31    return (LoggerContext) factory;
32  }
33}

Mit diesen drei Klassen ist die Implementierung vollständig. Natürlich habe ich noch eine Reihe von Unit-Tests geschrieben, um die Korrektheit zu prüfen aber ich wollte den Artikel nicht unnötig in die Länge ziehen.

Verwendung

Es gibt für jeden Browser ein Plugin, um zu jedem Request, der bestimmten Filter-Kriterien entspricht, eigene Header hinzuzufügen. Z.B. gibt es für den Chrome die Erweiterung Requestly:

Mit dem IntelliJ IDEA Request-Client ist es noch einfacher (aber eben nur für einen einzelnen Request):

1GET http://localhost:9000/
2X-PER-REQUEST-LOG-LEVEL:   debug
3X-PER-REQUEST-LOGGER-NAME: de.company.projectx

Zusammenfassung

Die Idee des Log-Levels Per-Request ist relativ einfach in Spring Boot umsetzbar und bietet eine Reihe von Vorteilen ohne echte Nachteile mitzubringen.

Es gäbe noch einige Verbesserungsmöglichkeiten:

• Unterstützung weiterer Logging-Bibliotheken (z.B. Log4J)
• Evtl. Schutz der Funktionalität durch zusätzliche Authentifikation o.ä.
• Implementierung erweitern, so dass man lediglich in gradle oder maven eine Dependency hinzufügen muss und das Feature dann mittels einer Application-Annotation (z.B. @EnablePerRequestLogLevel) aktiviert.