MDC

Mapped Diagnostic Context is a mechanism by which we can insert contextual data into the logging system at runtime and use it to provide additional information within the filename of the logfile, or within the log statements themselves.

Use cases for this center around multi-threaded applications where either:

Each thread is responsible for the full lifecyle of a message and we wish to tie all activity relating to that message in a single file with a filename relating to message keys.
Multiple threads are responsible for different aspects of a message’s lifecycle and we wish to feed every log statement associated with a particular message into some sort of log aggregator (like logstash) and then search this activity later using elastic search.

For example, in order to investigate (via log inspection) the processing of the following json message:

{
  messageId:UUID-1242-682830180-2818230-5383389,
  userId:12345,
  processingDate:20151223,
  firstName:"Cyril",
  lastName:"Figgis",
  job:accountant
}

We might wish to generate a single log file whose filename contains the userId, processingDate, and messageId in order to allow us to easily search for via the unix ls command. For example: messageLog-12345-20151223-1242-682830180-2818230-5383389.log

Assuming the message keys are final for the duration of the message processing, then this log file could be found using ls **12345 to find all logs relating to Cyril, or ls *12345*20151223* to find all logs for Cyril which occurred on the 23rd of December.

The problem with this 1 file per message approach is that on certain filesystems, particularly small ones (linode’s disks for example), if you process millions of messages, you end up with millions of log files which are difficult to process, and you might even run out of inodes.

A much more sustainable approach is to have 1 logfile per thread, and instead, stamp the message key information on the log statements within the file, for example:

Thread-01.log

20151223:23:00:00:500 INFO 1242-682830180-2818230-5383389 12345 Processing message
20151223:23:00:03:500 INFO 1242-682830180-2818230-5383389 12345 Calling rest service on http://service:8080/query?x=1
20151223:23:00:07:500 INFO 1242-682830180-2818230-5383389 12345 Transaction complete

The above log file contains 2 different message activities however, our logstash and elastic search layer will allow us to aggregate the data because every line has been stamped with the message key data.

This is how we actually stamp the message key data:

MDC.setContext("descriptor",contextualString);

For example:

public void processMessage(Message m) {
  MDC.setContext("descriptor",m.toString());
  LOGGER.info("Begin message processing")
  //processing logic goes here and any log statements like this next one will be stamped with contextual data:
  LOGGER.info("End message processing")
  MDC.setContext("descriptor", "");
}

Adding this MDC context setup and cleanup at the beginning of every method is tedious, especially if the context can be provided via a m.toString() method. To avoid this we can even create a custom annotation to be processed via AspectJ or similar, where by we annotate the method and if ambiguous the payload whose toString() method should provide the contextual data.

If using toString() is not for you, then maybe

Ensure your data objects provide a getContext() method specifically designed for this purpose.

This allows us to focus on the business logic rather than peppering our code with boilerplate code, such a message would be highly re-usable too.

Here’s a better example:

//example usage
@Loggable
public void processMessage(@Payload Message m) {
  //core business logic here
}

//payload annotation
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.PARAMETER)
public @interface Payload {
}

//loggable annotation
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Loggable {
}

public class LoggableAspect {
	@Around("@annotation(uk.co.solong.loggable.Loggable)")
	public Object around(ProceedingJoinPoint point) throws Throwable {
		Object[] args = point.getArgs();
		for (Object arg : args) {
			//find the arg that is annotated with payload
			MDC.setContext("descriptor", arg.toString());
		}
		LOGGER.info("======Begin message processing======");
		LOGGER.info("======End message processing======");
		MDC.setContext("descriptor", "");
	}
}