.consulting .solutions .partnership Logging and Tracing for your Microservices – Log4j, Zipkin and Spring Sleuth Alexander Schwartz, Principal IT Consultant JAX DevOps – 10 April 2018 

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 

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 

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 

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 

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? 

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 

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 

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 

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

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

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: 08:39:42.969 {invoiceId=1} ... - can't load item ID 4711 

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 

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

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

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) 

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 

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 

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 

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: 

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 

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 

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 

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 

Tools for Development and Production Web UI Zipkin © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 25 

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

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 

Tools for Development and Production Zipkin Browser-Plugin for Chrome © msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz 28 

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 

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 

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 

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 

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 

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 

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 

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 

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 

.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