Efficient logging with Spring Boot, Logback and Logstash

Posted by in DevOps, Java

Logging is an important part of any entreprise application and Logback makes an excellent choice: it’s simple, fast, light and very powerful. Spring Boot has a great support for Logback and provides lot of features to configure it. In this article I will present you an integration for an entreprise logging stack using Logback, Spring Boot and Logstash.

WARNING
The Spring Boot recommands to use the -spring variants for your logging configuration (for example logback-spring.xml rather than logback.xml). If you use standard configuration locations (logback.xml), Spring cannot completely control log initialization. All the following configuration is done in logback-spring.xml.

Profiles

The first extension used here is provided by Spring Boot: springProfile. The tag allows you to optionally include or exclude sections of configuration based on the active Spring profiles. Profile sections are supported anywhere within the element.

    <springProfile name="dev, prod">
        <!-- Some appenders... -->
    </springProfile>

Conditional processing

The next extension is not provided by Spring Boot. Logback supports conditional processing of configuration files with the help of , and elements so that a single configuration file can adequately target several environments. Note that conditional processing requires the Janino library, so you need to add:

<dependency>
    <groupId>org.codehaus.janino</groupId>
    <artifactId>janino</artifactId>
    <version>2.7.8</version>
</dependency>

Here is an example:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <if condition='isNull("logging.mode") || property("logging.mode").equals("console")'>
        <then>
            <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
        </then>
    </if>
    <if condition='isDefined("logging.mode") && property("logging.mode").equals("file")'>
        <then>
            <include resource="org/springframework/boot/logging/logback/file-appender.xml"/>
        </then>
    </if>

    <root level="INFO">
        <if condition='isNull("logging.mode") || property("logging.mode").contains("console")'>
            <then>
                <appender-ref ref="CONSOLE"/>
            </then>
        </if>
        <if condition='isDefined("logging.mode") && property("logging.mode").equals("file")'>
            <then>
                <appender-ref ref="FILE"/>
            </then>
        </if>
    </root>
</configuration>

If the property ‘logging.mode’ is null or equals to ‘console’, the default appender is the console, if ‘logging.mode’ is equals to ‘file’ the default appender is the file. Remember that in Spring, a property can be defined via your configuration file (application.yml) or via the JVM “-D…=…”

Log centralization

The last point concerns the log centralization. Logstash is generally deployed as a service, and log shippers such as FileBeat or Rsyslog collect the logs and push them to Logstash. The process has no dependency to Logstash/FileBeat or whatever, it still log in some rolling files and the log shipper parse them. Besides having to deploy an additionnal service – FileBeat, Rsyslog… – and involving to play with some touchy parsing expression, like the Grok filter, the phase during the rolling of the log files may lose some lines.

Logstash provides also an excellent project for sending logs directly from Logback https://github.com/logstash/logstash-logback-encoder. In this configuration, there is no need to deploy a log shipper and may be useful in container environment such as Docker. Even in traditionnal deployment, this logback shipper can be used if you don’t/can’t want play with FileBeat or Rsyslog.

First of all, you need to import the dependency in your project:

<properties>
  <ch.qos.logback.version>1.1.6</ch.qos.logback.version>
</properties>
...

<dependencies>
  <dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>4.7</version>
  </dependency>
  <dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.18</version>
  </dependency>
  <dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>${ch.qos.logback.version}</version>
  </dependency>
  <dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>${ch.qos.logback.version}</version>
    <!--
       Required for logging regular ILoggingEvents with a Logger.
       Not needed if only logging IAccessEvents for access logs.
    -->
    <optional>true</optional>
  </dependency>
  <dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-access</artifactId>
    <version>${ch.qos.logback.version}</version>
    <!--
       Required for logging IAccessEvents for access logs.
       Not needed if only logging regular ILoggingEvents with a Logger.
    -->
    <optional>true</optional>
  </dependency>
</dependencies>

To output JSON for LoggingEvents over TCP, we use a LogstashTcpSocketAppender with a LoggingEventCompositeJsonEncoder. LogstashTcpSocketAppender is an asynchronous TCP appender using the LMAX Disruptor RingBuffer, all the encoding and TCP communication is delegated to a single writer thread. So this appender will never block the logging thread and if the RingBuffer is full (e.g. due to slow network, etc), then events will be dropped. Moreover, LogstashTcpSocketAppender will automatically reconnect if the connection breaks. Just one drawback, events may be lost before Java’s socket realizes the connection has broken, or if the throughput of events can’t be handle by the buffer (overflow).

<appender name="STASH" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
    <destination>somehost:5666</destination>
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <providers>
            <mdc/> <!-- MDC variables on the Thread will be written as JSON fields-->
            <context/> <!--Outputs entries from logback's context -->
            <logLevel/>
            <loggerName/>

            <threadName/>
            <message/>

            <logstashMarkers/> <!-- Useful so we can add extra information for specific log lines as Markers-->
            <arguments/> <!--or through StructuredArguments-->
        </providers>
    </encoder>
</appender>

Example

Here is a complete example, with the following behavior:
– in ‘dev’ profile, logs are printed in the console
– in ‘integ’ or ‘prod’ profiles, logs are by default written in file or send to a pool of Logstash serveurs if the property ‘logging.mode’ is defined to ‘logstash’
– some informations are printed in the console at startup about the configuration (debug=true)
– a shutdownHook is added
– the patterns include the principal

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">

    <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <property name="CONSOLE_LOG_PATTERN"
              value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%1.14X{principal:-}]) %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}/}spring.log}"/>
    <property name="FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%X{principal}] [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>

    <springProperty scope="context" name="LOGSTASH" source="logstash.servers"/>
    <springProperty scope="context" name="APP_NAME" source="info.artifact"/>
    <springProperty scope="context" name="APP_VERSION" source="info.version"/>

    <springProfile name="dev">
        <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
    </springProfile>
    <springProfile name="integ, prod">
        <if condition='isDefined("logging.mode") && property("logging.mode").contains("logstash")'>
            <then>
                <appender name="STASH" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
                    <keepAliveDuration>5 minutes</keepAliveDuration>
                    <reconnectionDelay>10 second</reconnectionDelay>
                    <waitStrategyType>sleeping</waitStrategyType>
                    <ringBufferSize>16384</ringBufferSize>
                    <destination>${LOGSTASH}</destination>
                    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                        <providers>
                            <mdc/> <!-- MDC variables on the Thread will be written as JSON fields-->
                            <context/> <!--Outputs entries from logback's context -->
                            <logLevel/>
                            <loggerName/>

                            <pattern>
                                <pattern>
                                    {
                                    "appName": "${APP_NAME}",
                                    "appVersion": "${APP_VERSION}"
                                    }
                                </pattern>
                            </pattern>

                            <threadName/>
                            <message/>

                            <logstashMarkers/> <!-- Useful so we can add extra information for specific log lines as Markers-->
                            <arguments/> <!--or through StructuredArguments-->

                            <stackTrace>
                                <fieldName>stackTrace</fieldName>
                                <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
                                    <exclude>net\.sf\.cglib\..*</exclude>
                                    <maxDepthPerThrowable>30</maxDepthPerThrowable>
                                    <rootCauseFirst>true</rootCauseFirst>
                                </throwableConverter>
                            </stackTrace>
                        </providers>
                    </encoder>
                </appender>
            </then>
            <else>
                <include resource="org/springframework/boot/logging/logback/file-appender.xml"/>
            </else>
        </if>
    </springProfile>

    <root level="INFO">
        <springProfile name="dev">
            <appender-ref ref="CONSOLE"/>
        </springProfile>
        <springProfile name="integ, prod">
            <if condition='isDefined("logging.mode") && property("logging.mode").contains("logstash")'>
                <then>
                    <appender-ref ref="STASH"/>
                </then>
                <else>
                    <appender-ref ref="FILE"/>
                </else>
            </if>
        </springProfile>
    </root>
</configuration>

We also add these properties in the Spring YAML configuration:

info:
  artifact: test
  version: 1.0
logstash:
  servers: somehost:5666

NOTE
Remember that you can use the pl.project13.maven:git-commit-id-plugin in order to set the info.* properties with your Git infos.

Sources:
https://github.com/logstash/logstash-logback-encoder
https://github.com/elastic/logstash
https://lmax-exchange.github.io/disruptor/
http://docs.spring.io/spring-boot/docs/current/reference/html/boot-features-logging.html

Credits:
“Pipes Revisited” by Billie Grace Ward is licensed under CC 2.0 / Resized

Published the - Last update