Wissen was der User macht. MDC Logging mit Spring-Boot.

Eine Logmeldung ohne User-Informationen ist nichts Wert…

… aber wer will schon bei jeder Zeile den Usernamen übergeben? Was ist schöner? LOG.info("foo {}", username) oder LOG.info("foo")? Und welche Lösung ist konsequenter? Und wie suggestiv sind diese Fragen? ;)

Ich habe die Erfahrung gemacht, dass es in vielen Situationen sinnvoll ist die Log-Meldungen durch Context-Informationen anzureichern, die den aktuellen Prozess besser darstellen. Eine Grundlegende Funktion, die ich in jeder Webapplikation sehe ist ein Filter, der - falls ein User eingeloggt ist - dafür sorgt, dass der Username in jeder Logmeldung auftaucht. Und genau dies werden wir uns jetzt gemeinsam anschauen.

Generelles zum MDC

Der MDC - Mapped Diagnostic Context - ist ein Key-Value-Store, der aktuelle Informationen zur Applikationsausführung in ThreadLocal ablegt. Den MDC trifft man neben Logback auch in Log4j. Log4j 1.x hat darüber hinaus auch noch über einen NDC - Nested Diagnostic Context - verfügt, der einen etwas anderen Ansatz bzgl. der Speicherarchitektur (hier haben wir keine Map, sondern einen Stack in der Hand) - besitzt. Log4j 2 hingegen, implementiert die alt bekannten Funktionen aus Log4j 1 und Logback neu in Form eines Thread Contextes, der entweder als Map oder als Stack zur Verfügung steht.

Im Kern folgen all diese Implementierungen dem gleichen Ziel, nämlich Logmeldungen mit Meta- bzw. Context-Informationen anzureichen. Wem das an Information nicht reicht, sei auf die offizielle - und ausgesprochen gute - Logback Dokumentation verwiesen.

Setup

Ihr werdet sämtliche Informationen, die ihr benötigt um User-Informationen automatisch zu loggen in diesem Artikel finden, falls ihr allerdings lieber ein reines Sourcecode-Example unter den Händen habt, könnt ihr darüber hinaus gerne mein Beispielprojekt von meinem Github Account clonen.

Zunächst einmal haben wir eine Spring-Boot-Applikation mit den folgenden beiden Dependencies in der pom.xml:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-security</artifactId>
</dependency>
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-web</artifactId>
</dependency>

Außerdem haben wir eine Application-Klasse:

@SpringBootApplication
public class MDCLoggingApplication {

	public static void main(String[] args) {
		SpringApplication.run(MDCLoggingApplication.class, args);
	}
}

Und nach dem Start dieser Klasse haben wir zumindest schonmal eine laufende, wenn auch nutzlose, Applikation.

Security-Config

Damit wir einen Usernamen loggen können, brauchen wir zunächst die Möglichkeit uns überhaupt in unserer Anwendung anzumelden. Um das zu bewerkstelligen legen wir uns eine Security-Config an:

@Configuration
@EnableWebSecurity
public class SecurityConfig extends WebSecurityConfigurerAdapter {

  @Override
  protected void configure(HttpSecurity http) throws Exception {
    http.authorizeRequests()
        .antMatchers("/**").authenticated()
        .and().httpBasic();
  }
}

Was hier passiert ist folgendes: Mit dem Ant-Matcher auf /** werden sämtliche HTTP-Ressourcen unserer Applikation geschützt, so dass sie nur für authentifizierte User erreichbar sind. Für die Authentifizierung selbst setzen wir Basic-Auth (httpBasic) ein.

Spring-Boot in Kombination mit Spring-Security macht im übrigen etwas sehr angenehmes: Selbst ohne UserDetailsService wird ein Default-User mit dem Namen user angelegt. Das Passwort für diesen User wird bei jedem Applikationsstart neu generiert und als Logmeldung ausgegeben:

Using default security password: 0cd4138c-248b-4d5d-9a4d-b86f3215a784

Logback-Konfiguration

Leider ist im Default-Logback-Message-Layout von Spring-Boot kein MDC enthalten, so dass wir das vorhandene Pattern anpassen müssen. Für das Überschreiben der Default-Logback-Konfiguration erwartet Spring (in aktueller Version) eine Datei namens logback-spring.xml im Classpath. Diese Datei legen/passen wir an dieser Stelle an. Wichtig ist der letzte Teil des LOG_PATTERN: ... %m | %mdc .... Dabei werden an der Stelle %mdc unsere Context-Informationen ausgegeben.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
  <include resource="org/springframework/boot/logging/logback/defaults.xml" />
  <property name="LOG_PATTERN" value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m | %mdc %n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}" />

  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${LOG_PATTERN}</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

Test Controller

Weiter legen wir einen Controller an, der uns eine Log-Meldung ausgibt, sobald wir ihn aufrufen:

@Controller
public class TestController {
  private static final Logger LOG = LoggerFactory.getLogger(TestController.class);

  @ResponseBody
  @RequestMapping("/")
  public String index() {
    LOG.info("foo called!");
    return "foo";
  }
}

Logging-Filter

Das Herzstück all unserer Bemühungen ist allerdings der Logging-Filter. Dieser ist ein normaler ServletFilter. Innerhalb dieses Filters holen wir uns zunächst das UserDetails-Objekt des gerade angemeldeten Users und stecken daraufhin den dort enthaltenen Username in unseren MDC.

Danach geben wir den Request und die Response weiter an unsere filterChain und entfernen anschließend - nachdem alle Filter und potentielle Servlets mit der Verarbeitung des Requests fertig sind - den Username wieder aus dem MDC.

@Component
public class LoggingFilter implements Filter {
  ...

  @Override
  public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain)
  throws IOException, ServletException {

    Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
    if (authentication != null) {
      UserDetails principal = (UserDetails) authentication.getPrincipal();
      MDC.put("username", principal.getUsername());
    }

    filterChain.doFilter(servletRequest, servletResponse);
    MDC.remove("username");
  }

  ...
}

Fazit

Als Resultat erhalten wir nach erfolgreicher Anmeldung auf http://localhost:8080 die ansehnliche Logmeldung:

de.chclaus.examples.TestController       : foo called! | username=user

Und damit machen wir das Kapitel mit folgendem Fazit zu: Mit wenigen Handgriffen können wir mit dieser Technik für sehr viel mehr Transparenz und Nachvollziehbarkeit in unseren Server-Logs sorgen.