Logging und Tracing mit Kontextinformationen

Fehlermeldungen in Logs sind der Startpunkt einer Spurensuche: Meist steht in der Meldung selbst nur eine ID des Datensatzes, der den Fehler auslöste. Logging-Frameworks können bereits beim Entgegennehmen der Anfrage Kontextinformationen setzen, die zusätzlich zum Log-Eintrag protokolliert werden. Wer noch mehr Funktionalität benötigt, findet mit Zipkin eine Lösung, um Tracing-Informationen und Aufrufpfade anwendungsübergreifend zu annotieren, zu protokollieren und auszuwerten.

Dieser Vortrag gibt einen Einstieg in die Fähigkeiten von Log4j und zeigt die darüber hinausgehenden Möglichkeiten von Zipkin.

Transcript

1. .consulting .solutions .partnership Logs mit Kontext – Log4j, Zipkin, Spring Sleuth Alexander Schwartz, Principal IT Consultant JUG Saabrücken – 25. Januar 2017
2. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 2 Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
3. Mein Sponsor und Arbeitgeber – msg systems ag © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 3 1980 gegründet mehr als 6.000 Kollegen 812 Millionen € Umsatz 2016 25 Länder mit 18 Standorten in Deutschland präsent
4. Wer ich bin – Principal IT Consultant im Geschäftsbereich Travel & Logistics © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 4 >15 Jahre Java 7 Jahre PL/SQL 7 Jahre Absatzfinanzierung 3,5 Jahre Direktbank 1 Frau 2 Kinder 570 gefundene Geocaches @ahus1de
5. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 5 Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
6. Für die Fehlersuche Ein Fehler ist aufgetreten © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 6 Das geht nicht! Was steht denn in den Logs?
7. Für die Fehlersuche Willkommen in der Logging-Hölle! © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 7 Log: Code: for (Invoice i : invoiceRespository.findAll()) { i.calculateTotal(); } 07:26:00.595 d.a.t.d.Invoice ERROR - can't load item ID 4711
8. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth 8 © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
9. Kontextinformationen bei log4j Steckbrief log4j © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 9 Features: API für Logging, Implementierung für verschiedene Formate asynchrones Logging, Re-Konfiguration zur Laufzeit, Filter-Support Verfügbarkeit und Lizenz: • Apache Projekt unter Apache License 2.0 Historie: • 1.2 verfügbar seit Mai 2002 (seit 2015 end of life) • 2.0 verfügbar seit Juli 2014 • 2.10 verfügbar seit November 2017
10. Kontextinformationen bei log4j Logging mit Kontextinformationen – log4j 1.x und slf4j © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 10 for (Invoice i : respository.findAll()) { MDC.put(INVOICE_ID, Long.toString(i.getId())); try { i.calculateTotal(); } finally { MDC.remove(INVOICE_ID); } }
11. Kontextinformationen bei log4j Logging mit Kontextinformationen – log4j 2.x © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 11 for (Invoice i : respository.findAll()) try (final CloseableThreadContext.Instance c = CloseableThreadContext.put( INVOICE_ID, String.valueOf(i.getId()))) { i.calculateTotal(); } }
12. Kontextinformationen bei log4j Pattern in der Log-Ausgaben anpassen © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 12 Konfiguration: Logausgabe: <PatternLayout pattern="%d{HH:mm:ss.SSS} %X %-5level ..."/> 08:39:42.969 {invoiceId=1} ... - can't load item ID 4711
13. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth 13 © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
14. Kontext für Webanwendungen Filter für mehr Kontextinformationen im Log © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 14 @Provider public class RequestFilter implements ContainerRequestFilter { @Override public void filter(ContainerRequestContext containerRequestContext) { MDC.put("http.url", containerRequestContext.getUriInfo().getRequestUri().toString()); MDC.put("http.method", containerRequestContext.getMethod()); Principal principal = containerRequestContext.getSecurityContext().getUserPrincipal(); if(principal != null) { MDC.put("user", principal.getName()); } else { MDC.put("user", "anonymous"); } } }
15. Kontext für Webanwendungen Filter für mehr Kontextinformationen im Log © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 15 @Provider public class ResponseFilter implements ContainerResponseFilter { @Override public void filter(ContainerRequestContext containerRequestContext, ContainerResponseContext containerResponseContext) { MDC.remove("http.url"); MDC.remove("http.method"); MDC.remove("user"); } }
16. Kontext für Webanwendungen Logausgabe für Webanwendungen © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 16 08:52:54.276 {http.method=GET, http.url=http://localhost:8080/api/startBillingRun, invoiceId=1, user=Theo Tester} ERROR d.a.t.d.Invoice - can't load item ID 4711 Zusätzlich möglich: • Client-IP-Adresse • Teil der Session-ID • Browser-Kennung (User Agent)
17. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth 17 © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
18. Tracing über Schnittstellengrenzen Nachverfolgung über Systemgrenzen © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 18 Ein Aufruf des Nutzers schreibt auf drei verschiedenen Servern Logeinträge
19. Tracing über Schnittstellengrenzen Konzept Dapper in der Umsetzung von Zipkin © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 19 Trace-ID und zusätzlich eine Span-ID mitgeben Trace-ID vergeben
20. Tracing über Schnittstellengrenzen Wie es funktioniert © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 20 Zusätzliche HTTP Header: GET /api/callback HTTP/1.1 Host: localhost:8080 ... X-B3-SpanId: 34e628fc44c0cff1 X-B3-TraceId: a72f03509a36daae ... 09:20:05.840 { X-B3-SpanId=34e628fc44c0cff1, X-B3-TraceId=a72f03509a36daae, ..., invoiceId=1} ERROR d.a.t.d.Invoice - can't load item ID 4711 Zusätzliche Informationen im Log:
21. Tracing über Schnittstellengrenzen Was dafür benötigt wird © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 21 Zum Selberbauen: Servlet-Filter zum Auslesen der Informationen bei eingehenden Requests Wrapper für Aufrufe zu Umsystemen, damit Kontextinformationen gesetzt werden Für Spring-Boot: Zusätzliche Depedency Spring Sleuth [slyth] (spring-cloud-starter-sleuth) Bausteine für andere Projekte: Zipkin Teilprojekt „brave“ für server- und clientseitige Unterstützung
22. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth 22 © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
23. Werkzeuge für Entwicklung und Produktion Was ist eigentlich dieses Zipkin? © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 23 Aufgabe: • Distributed Tracing • Sammeln von Kontext- und Timing-Informationen • Zentrale Sammlung der Informationen für Fehler-, Timing- und Abhängigkeitsanalyse (in Produktion wird meist nur ein kleiner Prozentsatz aller Requests protokolliert) Konzepte: • Re-Implementierung der Konzepte von Google Dapper, welches ein internes Closed-Source Werkzeug bei Google ist • Zuerst umgesetzt als Teil von Finagle bei Twitter, später Open Source
24. Werkzeuge für Entwicklung und Produktion Zipkin Server empfängt Informationen und bietet eine Web-Oberfläche © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 24 Zu jeder Trace-/Span-ID: • Start-/Endzeit Client • Start-/Endzeit Server • Tags und Logs
25. Werkzeuge für Entwicklung und Produktion Web-Oberfläche Zipkin © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 25
26. Werkzeuge für Entwicklung und Produktion Anreichern mit zusätzlichen Informationen © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 26 @Component public class BillingResource { @Autowired private Tracer tracer; public String startBillingRun() { /* ... */ Span span = tracer.getCurrentSpan(); span.logEvent("log a line"); tracer.addTag("tag", "value"); /* ... */ } }
27. Werkzeuge für Entwicklung und Produktion Zipkin Browser-Plugin für Chrome © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 27 Vorgabe der Trace-ID in HTTP Headern Direkte Anzeige des Traces in einem neuen Tab
28. Werkzeuge für Entwicklung und Produktion Zipkin Browser-Plugin für Chrome © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 28
29. Werkzeuge für Entwicklung und Produktion Bonus: Per-Request-Debugging-Logging © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 29 • Zipkin und Sleuth geben den Header X-B3-Flags weiter, der zusätzliche Informationen enthalten kann • Zipkin-Chrome-Plugin gibt den Wert „1“ weiter (debug=true) • Ein Servlet-Filter kann den Wert entgegennehmen und in den MDC schreiben (zum Beispiel X-B3-Flags-debug mit dem Wert true) • Die folgende log4j2-Konfiguration aktiviert das TRACE-Level für alle Requests, die „true“ in diesem MDC-Schlüssel hinterlegt haben <DynamicThresholdFilter key="X-B3-Flags-debug" onMatch="ACCEPT" defaultThreshold="warn" onMismatch="NEUTRAL"> <KeyValuePair key="true" value="trace"/> </DynamicThresholdFilter>
30. Logs mit Kontext – Log4j, Zipkin, Spring Sleuth 30 © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz Für die Fehlersuche 1 Kontextinformationen bei Log4j 2 Kontext für Webanwendungen 3 Tracing über Schnittstellengrenzen hinaus 4 Werkzeuge für Entwicklung und Produktion 5 Recap – Was bietet mir welches Werkzeug? 6
31. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 31 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) @ahus1de
32. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 32 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) Filter für Web-Aufrufe Kontextinformationen zum Nutzer und der aufgerufenen URL @ahus1de
33. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 33 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) Filter für Web-Aufrufe Kontextinformationen zum Nutzer und der aufgerufenen URL Trace-Header á la Dapper mit Zipkin/Brave/Sleuth Korrelation von Logs über Trace-ID und Span-ID in Entwicklung und Produktion @ahus1de
34. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 34 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) Filter für Web-Aufrufe Kontextinformationen zum Nutzer und der aufgerufenen URL Trace-Header á la Dapper mit Zipkin/Brave/Sleuth Korrelation von Logs über Trace-ID und Span-ID in Entwicklung und Produktion Zipkin-Server Durchsuchbare Trace-Information inklusive Timing in Entwicklung und Produktion @ahus1de
35. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 35 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) Filter für Web-Aufrufe Kontextinformationen zum Nutzer und der aufgerufenen URL Trace-Header á la Dapper mit Zipkin/Brave/Sleuth Korrelation von Logs über Trace-ID und Span-ID in Entwicklung und Produktion Zipkin-Server Durchsuchbare Trace-Information inklusive Timing in Entwicklung und Produktion Zipkin Browser Plugin Vorgabe von Trace-IDs, direkte Suche in Entwicklung und Produktion, Erzwingen von Traces (falls in Produktion standardmäßig deaktiviert oder eingeschränkt) @ahus1de
36. Recap Was bietet mir welches Werkzeug © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 36 Einsatz von… bietet… Thread Context / Diagnostic Context Kontextinformationen in aufgerufenen Funktionen (insbesondere bei Iterationen und Master/Detail Strukturen) Filter für Web-Aufrufe Kontextinformationen zum Nutzer und der aufgerufenen URL Trace-Header á la Dapper mit Zipkin/Brave/Sleuth Korrelation von Logs über Trace-ID und Span-ID in Entwicklung und Produktion Zipkin-Server Durchsuchbare Trace-Information inklusive Timing in Entwicklung und Produktion Zipkin Browser Plugin Vorgabe von Trace-IDs, direkte Suche in Entwicklung und Produktion, Erzwingen von Traces (falls in Produktion standardmäßig deaktiviert oder eingeschränkt) @ahus1de
37. Links © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 37 Log4j 2 – insbesondere NDC/MDC https://logging.apache.org/log4j/2.x/manual/thread- context.html Zipkin, Brave https://github.com/openzipkin/zipkin https://github.com/openzipkin/brave Spring Sleuth https://github.com/spring-cloud/spring-cloud-sleuth @ahus1de Dapper http://research.google.com/pubs/pub36356.html Beispielprojekt https://github.com/ahus1/logging-and-tracing Artikel auf Heise Developer „Logging und Tracing mit Kontextinformation für Java- Entwickler“ https://www.heise.de/-3686586
38. .consulting .solutions .partnership Alexander Schwartz Principal IT Consultant +49 171 5625767 alexander.schwartz@msg-systems.com @ahus1de msg systems ag (Headquarters) Robert-Buerkle-Str. 1, 85737 Ismaning Germany www.msg.group