How to attach UUID to your logs using SLF4J MDC

Most real-world distributed systems or even simple web applications need to handle multiple clients simultaneously. In such systems, auditing and issue troubleshooting & debugging becomes very important aspect.

That’s where uniquely attaching a GUID for a given request becomes very important. It also helps in troubleshooting production issues. Ex. When a user logged in, you can generate a unique interaction id(global unique identifier) and add it to each log line. Later, upon searching his guid, you can retrieve all logs from your logging system for specific session and specific request.

In Java, we have SLF4J library which provides abstractions over multiple logging frameworks. It also provides supports for attaching attributes to the given request using MDC (Mapped Diagnostic Contexts). Without MDC, we would have needed to pass guid across your code layers i.e. controllers -> services-> repository etc. to log it for each line. MDC makes it very simple where you can set the attribute once and it will be logged for every line.

On high level flow is:

  • Define layout schema for your logs adding attributes which you want to add for each and every log line.
  • Add those attributes dynamically as per your business logic.

Below is sample log file output. From below file, we can not determine what was sequence of event’s when a user logged in.

application.log
2016-06-26 14:28:24.264 INFO c.f.i.w.c.f.LoggingFilter-86 User xyz logged in
2016-06-26 14:28:24.265 INFO c.f.i.w.c.f.LoggingFilter-86 User xyz logged in
2016-06-26 14:28:24.265 INFO c.f.i.w.c.f.LoggingFilter-86 request completed successfully
2016-06-26 14:28:24.266 INFO c.f.i.w.c.f.LoggingFilter-86 serving userprofile data
2016-06-26 14:28:24.266 INFO c.f.i.w.c.f.LoggingFilter-86 request completed successfully
2016-06-26 14:28:24.266 INFO c.f.i.w.c.f.LoggingFilter-86 serving userprofile data

Let’s improve above example by adding following attributes for each line. This will help us to trace the exact sequence of event’s for given apirequestId

  1. ApirequestId
  2. RemoteIpAddress
  3. HostName
  4. ThreadId

Let’s implement this using logback - which is java logging library. Notice that we have added %X{apiRequestId} %X{remoteIpAddress} %X{hostName} %X{threadId} in logging pattern where these attributes will be set by us at runtime for each client who logs in to the system.

logback.groovy
appender("FILE", FileAppender) {
  file = "application.log"
  append = true
  encoder(PatternLayoutEncoder) {
  	// Below is log pattern where we have added apirequestId, remoteIpAddress,
  	// hostName and threadId to be logged for each log line
    pattern = "%d{'yyyy-MM-dd HH:mm:ss.SSS'} %-5p 	%X{apiRequestId}|%X{remoteIpAddress}|%X{hostName}|%X{threadId}|%c{1}-%L %m%n"
  }
}

For brevity, I have not included all the code. As per your business logic, you can set these attributes something like this.

Please make sure to clear the MDC before initializing to avoid other requests using same thread in future to not use stale attributes.

LoggingFilter.java
MDC.clear(); // Clear the attributes before we start attaching the attributes for the new request
MDC.put(AppConstants.API_REQUEST_ID, generateGUID());
String remoteIp = httpRequest.getHeader("X-Forwarded-For") == null ? 
					httpRequest.getRemoteAddr(): 
					httpRequest.getHeader("X-Forwarded-For");
MDC.put(AppConstants.REMOTE_IP_ADDRESS, remoteIp);
MDC.put(AppConstants.HOST_NAME, httpRequest.getServerName());
MDC.put(AppConstants.THREAD_ID, Thread.currentThread().getName());

Once done, your log file format will look like below

application.log
2016-06-26 14:28:24.264 INFO 1459202415032|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 User xyz logged in
2016-06-26 14:28:24.265 INFO 1459202415033|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 User xyz logged in
2016-06-26 14:28:24.265 INFO  1459202415032|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 request completed successfully
2016-06-26 14:28:24.266 INFO  1459202415032|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 serving userprofile data
2016-06-26 14:28:24.266 INFO  1459202415033|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 request completed successfully
2016-06-26 14:28:24.266 INFO  1459202415033|172.10.11.20|example.com|http-nio-8080-exec-3|
c.f.i.w.c.f.LoggingFilter-86 serving userprofile data

Hence, You should be able to search using requestId ex. 1459202415032 to get complete event log trace. Tools like Splunk, logstash makes it much easier to ingest and search the logs by these unique requestId or interaction Id.

References


# Reference
1 http://www.slf4j.org/extensions.html
2 http://logback.qos.ch/manual/mdc.html
3 http://blog.trifork.com/2013/06/06/adding-user-info-to-log-entries-in-a-multi-user-app-using-mapped-diagnostic-context/

Version History


Date Description
2016-06-26    Initial Version