Logging and Tracing with Context Information - Log4j, Zipkin and Spring Sleuth

Analyzing a distributed Microservice environment requires you to correlate logs entries and trace calls between services. Log4j, Zipkin and Spring Sleuth will do that for you!

Error Messages in logs are the starting point of a search for clues. But if you're running in a distributed Microservice environment, correlation of logs entries and tracing between services becomes important.

Logging frameworks can add context information that and log them together with the message. If you need more functionality, Zipkin can help you: It will provide correlation IDs to correlate log entries between systems. You can add this information to your existing logs or forward it to a central Zipkin server. You can augment the traces with tags so you can search them online.

This presentation gives an introduction about the possibilities of Log4j and shows the additional possibilities of Zipkin and Spring Sleuth.

Transcript

1. .consulting .solutions .partnership Logging and Tracing for your Microservices – Log4j, Zipkin and Spring Sleuth Alexander Schwartz, Principal IT Consultant JAX DevOps – 10 April 2018
2. Logging and Tracing for your Microservices © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 2 Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
3. Sponsor and Employer – msg systems ag © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 3 Founded 1980 More than 7.000 Employees 891 Million € Turnover 2017 25 Countries 18 offices in Germany
4. About me – Principal IT Consultant @ msg Travel & Logistics © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 4 15 year Java 7 years PL/SQL 7 years consumer finance 3,5 years online banking 1 wife 2 kids 600+ Geocaches @ahus1de
5. Logging and Tracing for your Microservices © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 5 Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
6. Searching for Errors An error occurred © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 6 That doesn’t work! What’s in the logs?
7. Searching for Errors Welcome to Logging Hell! © msg | April 2018 | Logging and Tracing for your Microservices | 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. Logging and Tracing for your Microservices 8 © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
9. Context Information with Log4j Brief history of Log4j © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 9 Features: API for logging, implementation for different log formats, asynchronous logging, re-configuration at runtime, filters Availability and License: • Apache Projekt with Apache License 2.0 History: • 1.2 since May 2002 (2015 end of life) • 2.0 since July 2014 • 2.11 since March 2018
10. Context Information with Log4j Logging with context information – log4j 1.x and slf4j © msg | April 2018 | Logging and Tracing for your Microservices | 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. Context Information with Log4j Logging with context information – log4j 2.x © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 11 for (Invoice i : respository.findAll()) try (final CloseableThreadContext.Instance c = CloseableThreadContext.put( INVOICE_ID, String.valueOf(i.getId()))) { i.calculateTotal(); } }
12. Context Information with Log4j Adding context information to the log © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 12 Configuration: Log output: <PatternLayout pattern="%d{HH:mm:ss.SSS} %X %-5level ..."/> 08:39:42.969 {invoiceId=1} ... - can't load item ID 4711
13. Logging and Tracing for your Microservices 13 © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
14. Context Information for Web Applications Filters for more context information in the log © msg | April 2018 | Logging and Tracing for your Microservices | 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. Context Information for Web Applications Filters for more context information in the log © msg | April 2018 | Logging and Tracing for your Microservices | 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. Context Information for Web Applications Log output for Web Applications © msg | April 2018 | Logging and Tracing for your Microservices | 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 Further fields that might of of interest: • Client-IP-Address • Part of the Session-ID • Browser name (User Agent)
17. Logging and Tracing for your Microservices 17 © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
18. Tracing across Services and Interfaces Tools for Development and Production © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 18 One user requests writes log entries on three different servers
19. Tracing across Services and Interfaces Concept Dapper and its application in Zipkin © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 19 pass trace-ID and additionally a span-ID assign Trace-ID
20. Tracing across Services and Interfaces How it works © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 20 Additional 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 purchase ID 4711 Additional Informationen in the Log:
21. Tracing across Services and Interfaces What you need © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 21 Do-it-yourself: Servlet-Filter to read information from incoming request Wrapper for calls to remote systems to pass on context information For Spring-Boot: Add Spring Sleuth [slyth] as a dependency Building blocks for other projects: Zipkin‘s “brave” libraries for client- and server-side handling
22. Logging and Tracing for your Microservices 22 © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
23. Tools for Development and Production What is Zipkin? © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 23 Core Functionality: • Distributed Tracing • Collect context and timing information • Central store for collected information to analyze errors, timing issues and dependencies (in production usually only a small percentage of the requests is traced) Concepts: • Re-implementation of the concepts of Google Dapper, that is an internal closed-source tool at Google • First used as part of Finagle at Twitter, now Open Source
24. Tools for Development and Production Zipkin Server receives information and provides a Web UI © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 24 For each trace-/span-ID: • start-/end time client • start-/end time server • tags and logs
25. Tools for Development and Production Web UI Zipkin © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 25
26. Tools for Development and Production Adding more information © msg | April 2018 | Logging and Tracing for your Microservices | 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. Tools for Development and Production Zipkin Browser-Plugin for Chrome © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 27 Add trace-ID to HTTP Headers at client Direct link to traces view in a new tab
28. Tools for Development and Production Zipkin Browser-Plugin for Chrome © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 28
29. Tools for Development and Production Bonus: Per-Request-Debugging-Logging © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 29 • Zipkin and Sleuth pass on the Header X-B3-Flags, that can encode additional information • Zipkin-Chrome-Plugin passes the value “1” (debug=true) • A Servlet-Filter can pick up this value and pass it to the MDC (for example set X-B3-Flags-debug to true) • The following log4j2-Konfiguration activates the trace level for requests that have this HTTP-Header <DynamicThresholdFilter key="X-B3-Flags-debug" onMatch="ACCEPT" defaultThreshold="warn" onMismatch="NEUTRAL"> <KeyValuePair key="true" value="trace"/> </DynamicThresholdFilter>
30. Logging and Tracing for your Microservices 30 © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz Searching for Errors 1 Context Information with Log4j 2 Context Information for Web Applications 3 Tracing across Services and Interfaces 4 Tools for Development and Production 5 Recap – What to use and where to start 6
31. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 31 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) @ahus1de
32. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 32 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) Filter for Web requests Context information about the user and the called URL @ahus1de
33. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 33 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) Filter for Web requests Context information about the user and the called URL Trace-Header á la Dapper with Zipkin/Brave/Sleuth Correlation of logs with trace-ID and span-ID in development and production, including per-request debug logs @ahus1de
34. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 34 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) Filter for Web requests Context information about the user and the called URL Trace-Header á la Dapper with Zipkin/Brave/Sleuth Correlation of logs with trace-ID and span-ID in development and production, including per-request debug logs Zipkin-Server Searchable traces including timing and dependencies for development and production @ahus1de
35. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 35 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) Filter for Web requests Context information about the user and the called URL Trace-Header á la Dapper with Zipkin/Brave/Sleuth Correlation of logs with trace-ID and span-ID in development and production, including per-request debug logs Zipkin-Server Searchable traces including timing and dependencies for development and production Zipkin Browser Plugin Externally provided trace-IDs, direct search in development and production, enforced traces (if disabled by default in production or limited to only a percentage of the requests) @ahus1de
36. Recap What to use and where to start © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 36 Use … to get … Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in master/detail structures) Filter for Web requests Context information about the user and the called URL Trace-Header á la Dapper with Zipkin/Brave/Sleuth Correlation of logs with trace-ID and span-ID in development and production, including per-request debug logs Zipkin-Server Searchable traces including timing and dependencies for development and production Zipkin Browser Plugin Externally provided trace-IDs, direct search in development and production, enforced traces (if disabled by default in production or limited to only a percentage of the requests) @ahus1de
37. Links © msg | April 2018 | Logging and Tracing for your Microservices | 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 Sample Project (plus links to articles) https://github.com/ahus1/logging-and-tracing
38. .consulting .solutions .partnership Alexander Schwartz Principal IT Consultant +49 171 5625767 alexander.schwartz@msg.group @ahus1de msg systems ag (Headquarters) Robert-Buerkle-Str. 1, 85737 Ismaning Germany www.msg.group