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

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

View Slide

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

View Slide

Sponsor and Employer – msg systems ag
Founded 1980
More than 7.000 Employees
891 Million € Turnover 2017
25 Countries
18 offices
in Germany

View Slide

About me – Principal IT Consultant @ msg Travel & Logistics
15 year Java
7 years PL/SQL
7 years
consumer finance
3,5 years online banking
1 wife
2 kids
600+
Geocaches
@ahus1de

View Slide

1
2
3
4
5
6

View Slide

An error occurred
That doesn’t work! What’s in the logs?

View Slide

Welcome to Logging Hell!
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
© msg | April 2018 | Logging and Tracing for your Microservices | Alexander Schwartz
1
2
3
4
5
6

View Slide

Brief history of Log4j
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

View Slide

Logging with context information – log4j 1.x and slf4j
for (Invoice i : respository.findAll()) {
MDC.put(INVOICE_ID, Long.toString(i.getId()));
try {
i.calculateTotal();
} finally {
MDC.remove(INVOICE_ID);
}
}

View Slide

Logging with context information – log4j 2.x
for (Invoice i : respository.findAll())
try (final CloseableThreadContext.Instance c
= CloseableThreadContext.put(
INVOICE_ID, String.valueOf(i.getId()))) {
i.calculateTotal();
}
}

View Slide

Adding context information to the log
Configuration:
Log output:

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

View Slide

13
1
2
3
4
5
6

View Slide

Filters for more context information in the log
@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

Filters for more context information in the log
@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

Log output for Web Applications
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)

View Slide

17
1
2
3
4
5
6

View Slide

One user requests writes log
entries on three different servers

View Slide

Concept Dapper and its application in Zipkin
pass trace-ID and
additionally a span-ID
assign Trace-ID

View Slide

How it works
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:

View Slide

What you need
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

View Slide

22
1
2
3
4
5
6

View Slide

What is Zipkin?
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

View Slide

Zipkin Server receives information and provides a Web UI
For each trace-/span-ID:
• start-/end time client
• start-/end time server
• tags and logs

View Slide

Web UI Zipkin

View Slide

Adding more information
@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

Zipkin Browser-Plugin for Chrome
Add trace-ID
to HTTP Headers
at client
Direct link to traces view
in a new tab

View Slide

Zipkin Browser-Plugin for Chrome

View Slide

Bonus: Per-Request-Debugging-Logging
• 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
defaultThreshold="warn" onMismatch="NEUTRAL">

View Slide

30
1
2
3
4
5
6

View Slide

Recap
What to use and where to start
Use … to get …
Thread Context / Diagnostic Context Context information in all dependent calls (useful for iterations in
master/detail structures)
@ahus1de

View Slide

Recap
Use … to get …
Filter for Web requests Context information about the user and the called URL
@ahus1de

View Slide

Recap
Use … to get …
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

View Slide

Recap
Use … to get …
Zipkin/Brave/Sleuth
Zipkin-Server Searchable traces including timing and dependencies for
development and production
@ahus1de

View Slide

Recap
Use … to get …
Zipkin/Brave/Sleuth
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

View Slide

Links
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

View Slide

.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

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

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

Alexander Schwartz

More Decks by Alexander Schwartz

Other Decks in Programming

Featured

Transcript