Logging und Tracing mit Kontextinformationen

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.

5f528a3f6814d28b583f31842e3e8d9e?s=128

Alexander Schwartz

January 25, 2018
Tweet

Transcript

  1. 1.

    .consulting .solutions .partnership Logs mit Kontext – Log4j, Zipkin, Spring

    Sleuth Alexander Schwartz, Principal IT Consultant JUG Saabrücken – 25. Januar 2017
  2. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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. 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