Ratpacked: Using Mapped Diagnostic Context (MDC) Logging

The logging framework SLF4J supports Mapped Diagnostic Context (MDC). With MDC we can use a logging context that can be identified by something unique. This is useful, because then we can distinguish log messages from a big logging stream by something unique. Normally MDC is implemented on a per thread basis, but that is not useful in a Ratpack application. Ratpack provides the MDCInterceptor class to use SLF4J's MDC support in a Ratpack application. We must register an instance of MDCInterceptor with the registry. We can use the static method instance to create a new instance. With the method withInit we can define an action to be executed for the initialisation of the instance. An Execution parameter is used with the action and we can use it to check for objects in the registry.

In the following example we initialise the MDCInterceptor and check if there is a RequestId object in the registry (as described in the Javadoc of MDCInterceptor). If the RequestId object is available we set the MDC logging context variable requestId with the value of the RequestId object. Later in our logging configuration we can use this value so we can distinguish all logging statements belonging to a single request (with the given identifier).

// File: src/ratpack/ratpack.groovy
import com.mrhaki.ratpack.DefaultMessages
import com.mrhaki.ratpack.Messages

import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.slf4j.MDC

import ratpack.exec.Execution
import ratpack.handling.RequestId
import ratpack.logging.MDCInterceptor

import static ratpack.groovy.Groovy.ratpack

// Create logger for logging in this class.
Logger logger = LoggerFactory.getLogger('com.mrhaki.ratpack.RatpackApp')

ratpack {
    bindings {
        // Supporting class.
        bind Messages, DefaultMessages

        // Use instance() method for a new
        // MDCInterceptor object without any 
        // initialisation at creation time.
        //bindInstance MDCInterceptor.instance()

        // Here we use the withInit method
        // to assign a variable requestId on the 
        // logging context.
        bindInstance MDCInterceptor.withInit { Execution e ->
            e.maybeGet(RequestId).ifPresent { RequestId requestId ->
                MDC.put 'requestId', requestId.toString()
            }
        }
    }

    handlers {
        // Assign requestUri variable to MDC logging
        // context with URI for the request.
        all {
            // Assign raw uri to logging diagnostic context.
            MDC.put('requestUri', request.rawUri)
            next()
        }

        // Sample handler using Messages class with
        // SLF4J logging statements.
        get { Messages messages ->
            logger.debug 'General get handler to return message'
            render messages.message
        }
    }
}

Next we can define a logging configuration that uses the variables requestId and requestUri:

// File: src/ratpack/logback.groovy
appender('STDOUT', ConsoleAppender) {
    encoder(PatternLayoutEncoder) {
        // We define a pattern with the MDC logging context
        // variables requestId and requestUri.
        pattern = '%d{HH:mm:ss.SSS} - %-32logger{32} - %-5level - [%X{requestId}] "%X{requestUri}" - %msg%n'
    }
}

appender('ASYNC', reactor.logback.AsyncAppender) {
    appenderRef 'STDOUT'
}

logger 'com.mrhaki.ratpack', DEBUG

root INFO, ['ASYNC']

When we run our Ratpack application we get log messages with the request identifier and the request URI. We can filter and sort the logging messages using these values:

14:24:22.841 - com.mrhaki.ratpack.RatpackApp    - DEBUG - [ec0ddd3a-0a02-0af7-0974-679981106dd6] "/" - General get handler to return message
14:24:22.841 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [ec0ddd3a-0a02-0af7-0974-679981106dd6] "/" - DefaultMessage.getMessage
14:24:22.842 - com.mrhaki.ratpack.RatpackApp    - DEBUG - [7a95921d-a3f2-5075-57be-8dc852977958] "/" - General get handler to return message
14:24:22.842 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [ec0ddd3a-0a02-0af7-0974-679981106dd6] "/" - Getting value from resource bundle
14:24:22.842 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [7a95921d-a3f2-5075-57be-8dc852977958] "/" - DefaultMessage.getMessage
14:24:22.842 - com.mrhaki.ratpack.RatpackApp    - DEBUG - [b5613756-a599-a884-8460-3beb60a0cd01] "/" - General get handler to return message
14:24:22.842 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [b5613756-a599-a884-8460-3beb60a0cd01] "/" - DefaultMessage.getMessage
14:24:22.842 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [7a95921d-a3f2-5075-57be-8dc852977958] "/" - Getting value from resource bundle
14:24:22.842 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [b5613756-a599-a884-8460-3beb60a0cd01] "/" - Getting value from resource bundle
14:24:22.843 - com.mrhaki.ratpack.RatpackApp    - DEBUG - [1d0a38ac-33b6-90e7-3dea-04d6299dbda9] "/" - General get handler to return message
14:24:22.843 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [1d0a38ac-33b6-90e7-3dea-04d6299dbda9] "/" - DefaultMessage.getMessage
14:24:22.843 - c.mrhaki.ratpack.DefaultMessages - DEBUG - [1d0a38ac-33b6-90e7-3dea-04d6299dbda9] "/" - Getting value from resource bundle

Written with Ratpack 1.1.1.