Small Gem: Use MDC to add a prefix to every log statement

This one was a lifesaver. I was working on code that processes messages, and needed to add the message id to every log statement. While this sounds straightforward, in reality it wasn't. Here's a very simplified version of the code that illustrates the problem:

function processMessage(Message message) {
  log.info("Processing new message")  // log statement #1
  if (message.action == "NEW") {
    addNewWidget()
  } else if (message.action == "UPDATE") {
    updateWidget(message.widgetId)
  }
}

function addNewWidget() {
   log.info("Creating new widget") // log statement #2
   database.createNew(new WidgetEntity())
   sendNotification("New widget created")
}

function updateWidget(int widgetId) {
  log.info("Updating widget $widgetId") // log statement #3
  Widget widget = database.findByWidgetId(widgetId)
  widget.setLastModifiedDate(now)
  widget.save()
  sendNotification("Widget updated")
}

function sendNotification(String message) {
  log.info("Sending notification") // log statement #4
  // code to send notification
}

It's easy to prefix the first log statement with the message id:

log.info("[$message.messageId]: Processing new message")

But for the other log statements, the message id is not available. The only solution seemed to be to pass around the message id. This involved changing every method signature to include the message id:

function addNewWidget(String messageId) {
  // ...
}
function updateWidget(int widgetId, String messageId) {
  // ...
}
function sendNotification(String message, String messageId) {
  // ...
}

Ugh! This is a painful solution, especially in a system with many classes and methods.

But what could I do instead? Getting the message id into the logs was imperative - without it, we couldn't trace the path of the messages or troubleshoot problems.

And that's when I discovered Logback's Mapped Diagnostic Context or MDC. And adding the message id to the logs suddenly became a piece of cake:

function processMessage(Message message) {
  MDC.put("messageId", message.messageId)
  log.info("Processing new message") 
  if (message.action == NEW) {
    addNewWidget()
  } else if (message.action == UPDATE) {
    updateWidget(message.widgetId)
  }
  MDC.clear()
}

I added only two statements to the code - one MDC.put to include the message id, and one MDC.clear to remove it when done.

After that, I added the %X modifier to my logback layout and voilà - every log message included the message id!