“ Happy is he who can trace effects to their causes.”
Virgil
Das Logging von Web-Anwendungen, bzw. allen Server-Anwendungen ist mit seinen eigenen kleinen Tücken versehen. Die üblichen, mehr oder wenig hilfreichen Log Anweisungen, die sich im Source Code tummeln, sorgen für einen stetigen Strom von Log-Ausgaben. Solange sich die Ausgabe auf einen einzelnen Request bezieht, ist häufig noch sehr gut nachvollziehbar, was gerade auf dem Server passiert. Bei sehr vielen Anfragen an den Server leidet aber die Übersicht.
Das folgende Beispiel zeigt die Log-Ausgaben, die ein Request nach einem speziellen Ahnen erzeugt.
2023-01-15 17:27:01 - ancestor tree: 17 2023-01-15 17:27:01 - open tree: 17 /Kayser/ 2023-01-15 17:27:01 - ancestor: Friedrich Magnus /Kayser/ 2023-01-15 17:27:01 - family: 25 2023-01-15 17:27:01 - read person 2023-01-15 17:27:01 - father: Christoph /Kayser/ 2023-01-15 17:27:01 - mother: Sophia Margarethe Elisabeth /Matthiessen/
Bis auf die Log-Ausgabe in Zeile 5 scheinen alle Ausgaben hilfreiche Informationen zu liefern. Aber schon bei zwei zeitgleich verarbeiteten Requests wird die Ausgabe fragwürdig.
2023-01-15 17:27:01 - ancestor tree: 17 2023-01-15 17:27:01 - open tree: 17 /Kayser/ 2023-01-15 17:27:01 - ancestor tree: 17 2023-01-15 17:27:01 - ancestor: Friedrich Magnus /Kayser/ 2023-01-15 17:27:01 - open tree: 17 /Kayser/ 2023-01-15 17:27:01 - family: 25 2023-01-15 17:27:01 - family: 13 2023-01-15 17:27:01 - read person 2023-01-15 17:27:01 - read person 2023-01-15 17:27:01 - ancestor: Anna Margret /Tribben/ 2023-01-15 17:27:01 - father: Christoph /Kayser/ 2023-01-15 17:27:01 - father: Christopher /Trippen/ 2023-01-15 17:27:01 - mother: Sophia Margarethe Elisabeth /Matthiessen/ 2023-01-15 17:27:01 - mother: Hille /Tribbe/
Die Zugehörigkeit der Eltern ist für den Entwickler nur über den Nachnamen nachzuvollziehen. Was wäre aber, wenn sich nun auch noch die Anfrage nach Christoph Kayser in die Ausgabe mischt? Wer zu welcher Familie gehört ist aber schon aus dieser Log-Ausgabe nicht mehr zu rekonstruieren.
Schöne wäre es also eine Ausgabe zu erzeugen, bei der zusammengehörige Log-Zeilen entsprechend markiert sind. Das zugehörige Konzept nennt sich Trace-ID und bedeutet, dass für jeden Request eine eindeutige ID für die Verarbeitung erzeugt wird. Diese ID kann dann in den Log-Ausgaben genutzt werden.
Da es unhandlich ist, solch eine ID durch alle Klassen und Methoden durchzureichen, nutzt dieser einfache Ansatz das Mapped Diagnostic Context Pattern (MDC). Dabei werden in einem Thread-basierten Kontext alle Werte vorgehalten, die zusätzlich beim Logging ausgegeben werden sollen. Aktuelle Log Frameworks (Slf4J, Log4J, etc.) unterstützen dieses Pattern und stellen entsprechende Klassen bereit.
Um eine eigene Trace-ID für jeden Request zu erstellen, reicht der folgende OncePerRequestFilter.
@Configuration
public class TraceIdConfiguration implements WebMvcConfigurer {
@Bean
public Filter loginFilter() {
return new OncePerRequestFilter() {
@Override
protected void doFilterInternal(@NonNull HttpServletRequest request, @NonNull HttpServletResponse response,
@NonNull FilterChain filterChain) throws ServletException, IOException {
MDC.put("trace-id", UUID.randomUUID());
MDC.put("user-id", SecurityContextHolder.getContext().getAuthentication().getName());
filterChain.doFilter(request, response);
MDC.remove("user-id");
MDC.remove("trace-id");
}
};
}
}
Dieser Filter fügt vor der Bearbeitung des Requests, die beiden Attribute trace-id und user-id in den MDC ein. Dafür stellt das Logging Framework die Klasse MDC bereit. Nach der Verarbeitung des Requests werden die beiden Attribute wieder aus dem MDC entfernt. Sie sollen ja nicht versehentlich an anderer Stelle ausgegeben werden, falls der aktuelle Thread wiederverwendet wird.
Nun fehlt noch die Möglichkeit diese beiden Attribute in den Log-Ausgaben anzuzeigen. Dafür kann das Attribute mit der %X Formatanweisung im Logging Pattern angegeben werden.
logging.pattern.file=%d{yyyy-MM-dd HH:mm:ss} %X{trace-id} %X{user-id} %-5level %logger{36} - %msg%
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss} %X{trace-id} %X{user-id} - %msg%n
Die beiden Zeilen in der application.properties ändern die bisherigen Logausgabe.
2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - ancestor tree: 17 2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - open tree: 17 /Kayser/ 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - ancestor tree: 17 2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - ancestor: Friedrich Magnus /Kayser/ 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - open tree: 17 /Kayser/ 2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - family: 25 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - family: 13 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - read person 2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - read person 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - ancestor: Anna Margret /Tribben/ 2023-01-15 17:27:01 0b82b84e-189f-4b52-bbe1-46e9ccc849af kaiser - father: Christoph /Kayser/ 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - father: Christopher /Trippen/ 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - mother: Sophia Margarethe Elisabeth /Matthiessen/ 2023-01-15 17:27:01 562a1fd3-bd38-4f90-b799-e280c0d6652f lechtr - mother: Hille /Tribbe/
Nun ist es für den Entwickler sehr viel einfacher zu verstehen welche Log-Zeilen zu welchem Request führen und in Tools wie Kibana können Logausgaben gezielt gefiltert werden.