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.

Ratpacked: Log Request Duration

In a previous post we learned how to log request information in common log or NCSA format. But we can also provide our own implementation of a RequestLogger to log for example the time spent in processing a request. One of the easiest ways to do this is by using the RequestLogger.of method. We can provide a lambda expression or closure for this method with an argument type RequestOutcome. The RequestOutcome class has properties to access the request and sent response objects. And it also contains a Duration object which has the duration of the time spent for the total request (all handlers in the chain). This doesn't include the necessary time to send the request to the client.

import ratpack.handling.RequestLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {

    handlers {

        // Here we use the of method to implement
        // custom request logging.
        all(RequestLogger.of { outcome ->

            // Only log when logger is enabled.
            if (RequestLogger.LOGGER.infoEnabled) {

                // Log how long the request handling took.
                RequestLogger.LOGGER.info(
                        'Request for {} took {}.{} seconds.',
                        outcome.request.uri,
                        outcome.duration.seconds,
                        outcome.duration.nano)
            }
        })

        get {
            render 'Ratpack rules!'
        }

    }

}

Instead of using the RequestLogger.of method we can write our own implementation of the RequestLogger interface. We only have to override the log method that has the argument type RequestOutcome. Let's rewrite our previous example and use a new class RequestDurationLogger:

// File: src/main/groovy/com/mrhaki/ratpack/request/logging/RequestDurationLogger.groovy
package com.mrhaki.ratpack.request.logging

import groovy.transform.CompileStatic
import groovy.util.logging.Slf4j
import ratpack.handling.RequestLogger
import ratpack.handling.RequestOutcome

/**
 * Custom implementation of the {@link RequestLogger} to
 * log how much time is spent on processing a request.
 * The time spent doesn't include the time spent in
 * transportation from and to the client.
 */
@Slf4j(value = 'logger', category = 'ratpack.request.duration')
@CompileStatic
class RequestDurationLogger implements RequestLogger {

    /**
     * Log the duration in seconds spent on processing a request.
     *
     * @param outcome Information about the request and send response, including duration
     */
    @Override
    void log(final RequestOutcome outcome) throws Exception {
        // Only log when logger is enabled.
        if (logger.infoEnabled) {
            // Log how long the request handling took.
            logger.info(
                    'Request for {} took {}.{} seconds.',
                    outcome.request.uri,
                    outcome.duration.seconds,
                    outcome.duration.nano)
        }
    }
}

In the Groovy DSL of our Ratpack application we now use our new class:

import com.mrhaki.ratpack.request.logging.RequestDurationLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {

    handlers {

        // Here we use our RequestLogger implementation.
        all(new RequestDurationLogger())

        get {
            render 'Ratpack rules!'
        }

    }

}

When we look at some sample logging output we see how much time is spent to handle a request:

[ratpack-compute-5-8] INFO ratpack.request.duration - Request for / took 0.1000000 seconds.

Written with Ratpack 1.0.0.

Ratpacked: Request Logging

Ratpack comes with a special handler to log requests in the common log or NCSA format. We need the (default) interface ratpack.handling.RequestLogger which has a method ncsa that returns a handler instance capable of logging our request data.

In the following example code we have a Groovy DSL definition of our Ratpack application. We use the all method to add the request logger. The RequestLogger implementation will make sure the complete handler chain is finished before logging the information.

import ratpack.handling.RequestLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {

    handlers {

        // Here we add the request logger 
        // for logging our request information
        // in common log or NCSA format.
        all(RequestLogger.ncsa())

        get {
            render 'Ratpack rules!'
        }

    }

}

When we run our application with logging enabled we get the following sample output when we request the / path of our application:

[ratpack-compute-5-16] INFO ratpack.request - 0:0:0:0:0:0:0:1 - - [12/Oct/2015:08:57:59 +0200] "GET / HTTP/1.1" 200 - id=133aef4a-2abe-acc0-90a3-783826bad515

We see the request method, path and status code and we see Ratpack adds a unique request identifier to our requests and it is also logged with our request logger. The default logger name is ratpack.request. We can use this to for example redirect the request logging to a file using the configuration of a SLF4J logging implementation. To change the logger implementation we can give our own as an argument for the ncsa method:

import org.slf4j.Logger
import org.slf4j.LoggerFactory
import ratpack.handling.RequestLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {
    
    // Create custom Logger implementation for request logging.
    final Logger requestLogger = LoggerFactory.getLogger('com.mrhaki.sample.requestLogger')

    handlers {

        // Instruct NCSA request logger to use 
        // our requestLogger Logger implementation.
        all(RequestLogger.ncsa(requestLogger))

        get {
            render 'Ratpack rules!'
        }

    }

}

If we look at the logging output we see our custom logger name:

[ratpack-compute-13-2] INFO com.mrhaki.sample.requestLogger - 0:0:0:0:0:0:0:1 - - [12/Oct/2015:09:34:26 +0200] "GET / HTTP/1.1" 200 - id=81f996a6-bb41-f683-60e1-1ab19c11a14e

Written with Ratpack 1.0.0.

Ratpacked: Use Asynchronous Logging

Ratpack is from the ground up build to be performant and asynchronous. Let's add a logging implementation that matches the asynchronous nature of Ratpack. Ratpack uses the SLF4J API for logging and if we write logging statement in our own code we should use the same API. For Groovy developers it is nothing more than adding the @Slf4j AST annotation to our classes. The Logback library has an asynchronous appender which has a queue to store incoming logging events. Then a worker on a different thread will invoke a classic blocking appender, like a file or console appender, to actually log the messages. But in our example we don't use the standard async appender from Logback, but use a asynchronous logbook appender from the Reactor project. Now our queue is backed by a very performant reactor ring buffer implementation.

The following Logback configuration file shows how we can configure the reactor.logback.AsyncAppender:

<!-- File: src/main/resources/logback.xml -->
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-30(%d{HH:mm:ss.SSS} [%thread]) %-5level %logger{32} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Create new asynchronous Logback appender backed by Reactor RingBufferProcessor. -->
    <appender name="ASYNC" class="reactor.logback.AsyncAppender">
        <!-- Backlog size for logging events. Change size if they are picked up slowly.
             Default is 1024 * 1024 -->
        <backlog>1048576</backlog>

        <!-- Caller data is relatively slow, so per default disabled -->
        <includeCallerData>false</includeCallerData>

        <!-- Redirect logging messages to STDOUT -->
        <appender-ref ref="STDOUT"/>
    </appender>

    <root level="INFO">
        <appender-ref ref="ASYNC"/>
    </root>

</configuration>

We need to add a runtime dependency for io.projectreactor:reactor-logback in our build.gradle file to use the AsyncAppender:

...
repositories {
    jcenter()
}

dependencies {
    runtime 'ch.qos.logback:logback-classic:1.1.3'
    runtime 'io.projectreactor:reactor-logback:2.0.5.RELEASE'
}
...

Russell Hart mentioned via Twitter that we can also use asynchronous loggers from Log4j 2 as described in Ratpack book examples. First we must add some new runtime dependencies. Log4j 2 has a bridge for SLF4J API so we add that together with other Log4j 2 dependencies. The asynchronous loggers use LMAX disruptor and we need that as a dependency as well. Our build file now looks like this:

...
repositories {
    jcenter()
}

dependencies {
    ext {
        log4jGroup = 'org.apache.logging.log4j'
        log4jVersion = '2.4'
    }

    runtime "$log4jGroup:log4j-slf4j-impl:$log4jVersion"
    runtime "$log4jGroup:log4j-api:$log4jVersion"
    runtime "$log4jGroup:log4j-core:$log4jVersion"
    runtime 'com.lmax:disruptor:3.3.2'
}
...

Next we create a new configuration file, log4j2.xml, which is used by Log4j 2 to configure the loggers. Notice we use <AsyncLogger/> and <AsyncRoot/> to use asynchronous logging. To learn more about the configuration we need to look at the Log4j website.

<?xml version="1.0" encoding="UTF-8"?>
<!-- File: src/main/resources/log4j2.xml -->
<Configuration status="WARN">
    <Appenders>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout pattern="%m%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <AsyncLogger name="ratpack.server.RatpackServer" level="DEBUG" />
        <AsyncRoot level="ERROR">
            <AppenderRef ref="STDOUT"/>
        </AsyncRoot>
    </Loggers>
</Configuration>

Written with Ratpack 1.0.0.