Upgrade to Pro — share decks privately, control downloads, hide ads and more …

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.

Alexander Schwartz

January 25, 2018
Tweet

More Decks by Alexander Schwartz

Other Decks in Programming

Transcript

  1. .consulting .solutions .partnership
    Logs mit Kontext – Log4j, Zipkin, Spring Sleuth
    Alexander Schwartz, Principal IT Consultant
    JUG Saabrücken – 25. Januar 2017

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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?

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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);
    }
    }

    View Slide

  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();
    }
    }

    View Slide

  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:

    08:39:42.969 {invoiceId=1} ... - can't load item ID 4711

    View Slide

  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

    View Slide

  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");
    }
    }
    }

    View Slide

  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");
    }
    }

    View Slide

  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)

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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:

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  25. Werkzeuge für Entwicklung und Produktion
    Web-Oberfläche Zipkin
    © msg | Januar 2018 | Logs mit Kontext – Log4j, Zipkin, Spring Sleuth | Alexander Schwartz 25

    View Slide

  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");
    /* ... */
    }
    }

    View Slide

  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

    View Slide

  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

    View Slide

  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
    defaultThreshold="warn" onMismatch="NEUTRAL">


    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  38. .consulting .solutions .partnership
    Alexander Schwartz
    Principal IT Consultant
    +49 171 5625767
    [email protected]
    @ahus1de
    msg systems ag (Headquarters)
    Robert-Buerkle-Str. 1, 85737 Ismaning
    Germany
    www.msg.group

    View Slide