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.