Persistent Custom MDC Logging in Apache Camel

Logging is an ubiquitous need in any production quality application, and one common scenario is to log the active (logged in) username, or to log the user and order IDs for customer order event details. This is typically done to create an audit trail so that issues can be more easily traced should something go wrong, but there are any number of reasons why you might decide to create a custom log.

Mapped Diagnostic Contexts (MDCs) in Apache Camel are great for creating custom logging statements, and will easily meet our needs for these use cases.  MDC is offered by both slf4j and log4j, and is also supported by JBoss Logging. (Apache Camel is a part of the Red Hat JBoss Fuse integration platform.)

In addition, you can use something like GELF to automatically index any MDC, thus allowing them to be easily searched using ElasticSearch (logging configuration is not required for this feature), so there are a few reasons why this might be an appealing solution.

This article will demonstrate how to set up MDC to perform custom logging.

Using MDC

MDC primarily stores a key-value map of contextual data (strings mapping to strings), and the context map key can be added to your logging format (logging.properties, or other logging configuration), like in the following example (orderId is the context key):

%d{HH:mm:ss,SSS} %-5p [%c] %X{camel.routeId} | %X{orderId} | (%t) %s%E%n

Adding an MDC in Java is as simple as :

MDC.put("myKey", "myValue");

With JBoss logging MDCs persist until you remove them.  However, due to a bug, this is not the case for Apache Camel on Karaf. Camel itself does provide some persistent MDCs by default, and these can be found here http://camel.apache.org/mdc-logging.html.

Now, what if you want your own custom MDC to persist on Camel/Karaf?  If you have a route that is processing an order, logging the order ID throughout the route flow would be very helpful when troubleshooting issues in production. Unless we can persist the MDC, this isn't going to work.

Making MDC Persistent

Luckily, all you need to do to get your custom MDC values to persist is extend Camel's MDCUnitOfWork.  At a minimum you will want your extension to look something like the example below that shows your custom "orderId" MDC.  You can also extend the clear() method, and others if you desire, but the methods below are the basic ones you'd need to get the job done.

public class CustomUnitOfWork extends MDCUnitOfWork implements UnitOfWork {
  public static final String MDC_ORDERID = "orderId";
  private final String originalOrderId;

  public CustomUnitOfWork(Exchange exchange) {
    super(exchange);
    this.originalOrderId = MDC.get(MDC_ORDERID);
  }

  @Override
    public UnitOfWork newInstance(Exchange exchange) {
    return new CustomUnitOfWork(exchange);
  }

  @Override
    public AsyncCallback beforeProcess(Processor processor, Exchange exchange, AsyncCallback callback) {
    return new MyMDCCallback(callback);
  }

  /**
  * * {@link AsyncCallback} which preserves {@link org.slf4j.MDC} when the
  * asynchronous routing engine is being used. * This also includes the
  * default camel MDCs.
  */
  private static final class MyMDCCallback implements AsyncCallback {
    private final AsyncCallback delegate;
    private final String breadcrumbId;
    private final String exchangeId;
    private final String messageId;
    private final String correlationId;
    private final String routeId;
    private final String camelContextId;
    private final String orderId;

    private MyMDCCallback(AsyncCallback delegate) {
      this.delegate = delegate;
      this.exchangeId = MDC.get(MDC_EXCHANGE_ID);
      this.messageId = MDC.get(MDC_MESSAGE_ID);
      this.breadcrumbId = MDC.get(MDC_BREADCRUMB_ID);
      this.correlationId = MDC.get(MDC_CORRELATION_ID);
      this.camelContextId = MDC.get(MDC_CAMEL_CONTEXT_ID);
      this.routeId = MDC.get(MDC_ROUTE_ID);
      this.orderId = MDC.get(MDC_ORDERID);
    }
  }

  public void done(boolean doneSync) {
    try {
      if (!doneSync) {
        // when done asynchronously then restore information from
        // previous thread
        if (breadcrumbId != null) {
          MDC.put(MDC_BREADCRUMB_ID, breadcrumbId);
        }
        if (orderId != null) {
          MDC.put(MDC_ORDERID, orderId);
        }
        if (exchangeId != null) {
          MDC.put(MDC_EXCHANGE_ID, exchangeId);
        }
        if (messageId != null) {
          MDC.put(MDC_MESSAGE_ID, messageId);
        }
        if (correlationId != null) {
          MDC.put(MDC_CORRELATION_ID, correlationId);
        }
        if (camelContextId != null) {
          MDC.put(MDC_CAMEL_CONTEXT_ID, camelContextId);
        }
      }
      // need to setup the routeId finally
      if (routeId != null) {
        MDC.put(MDC_ROUTE_ID, routeId);
      }
    } finally {
      // muse ensure delegate is invoked
      delegate.done(doneSync);
    }
  }

  @Override
  public String toString() {
    return delegate.toString();
  }
}

Accessing the MDC

Now how do we use this? If you are using Spring, getting your CustomUnitOfWork in use is easy. First implement the UnitOfWorkFactory, like below:

public class CustomUnitOfWorkFactory implements UnitOfWorkFactory {
  @Override
  public UnitOfWork createUnitOfWork(Exchange exchange) {
    return new CustomUnitOfWork(exchange);
  }
}

Then create your Spring bean:

 <bean id="unitOfWorkFactory" class="com.redhat.example.CustomUnitOfWorkFactory"/>

Once this is all in place, you can verify your UnitOfWork is in use for your bundle by checking for a log statement starting with 'Using custom UnitOfWorkFactory:' followed by your class name.

MDCs will persist in logging throughout the Camel route.  Keep in mind there are some exceptions to this. The use of SEDA, or something else that would normally act as a start of a brand new route, will clear the context for that Route.  Your custom MDCs are set up to be treated the same way as the camel.breadcrumbid (a unique id used for tracking messages across transports,) so you can think of it that way.