Using Logstash Logback JSON Encoder with Maven

There are many benefits to logging the output of your Maven build to JSON.

Download the Latest Version of Maven

Because most of us aren’t paying attention to what version of Maven we are actually using, I’m suggesting that you give upgrading some consideration.

Colored console output is a worthwhile feature that you may be missing. Many other readability, compatibility, and performance enhancements have been made in recent releases.

Download the latest Maven release and find out what else is new.

Don’t Know Where Maven Is Installed?

You can try this command to find out where Maven is installed in your operating system:

ls -l `which mvn`
lrwxrwxrwx 1 root root 37 Apr  6 10:45 /usr/bin/mvn -> /usr/local/apache-maven-3.5.2/bin/mvn

Because mvn is usually symlinked from a bin directory on your path, this command will reveal the actual location where Maven was installed. Be aware that IDEs, such as Eclipse and STS may have installed their own copy of Maven and not be using the same one accessible from your command shell.

Maven Already Uses Logback

As a Java developer, it’s easy to forget that most of our build tools are also written in Java, and that includes Maven. It turns out that Maven 3.1.x and later uses SLF4J to generate the console output you are watching after you enter the command:

% mvn install

In fact, you will find the default logging configuration for Maven in apache-maven-3.5.2/libexec/conf/simplelogger.properties where Maven has been installed. Out of the box, Maven uses SLF4J SimpleLogger which is a lightweight Logback implementation that can be configured using this property file.

But because SLF4J is implemented upon Logback APIs, it’s possible to supply Maven with the Logback JARs and a logback.xml to completely customize the output from Maven.

Tell Maven Where To Find logback.xml

Maven allows you to specify the location of your Logback XML. Just add this to your .bash_profile using the MAVEN_OPTS environment variable:

export MAVEN_OPTS="$MAVEN_OPTS -Dlogback.configurationFile=$HOME/.m2/logback.xml"

I put my logback.xml in my Maven .m2 settings directory to keep from losing it, but you can put yours wherever you like.

Create a logback.xml

Now that we’ve instructed Maven to look in ~/.m2/logback.xml for the configuration, we need to provide one:

<configuration>

  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
      <providers>
        <timestamp>
	  <fieldName>ts</fieldName>
          <timeZone>UTC</timeZone>
        </timestamp>
        <loggerName>
          <fieldName>logger</fieldName>
        </loggerName>
        <logLevel>
          <fieldName>level</fieldName>
        </logLevel>
        <callerData>
          <classFieldName>class</classFieldName>
          <methodFieldName>method</methodFieldName>
          <lineFieldName>line</lineFieldName>
          <fileFieldName>file</fileFieldName>
        </callerData>
        <threadName>
          <fieldName>thread</fieldName>
        </threadName>
        <mdc />
        <arguments>
          <includeNonStructuredArguments>false</includeNonStructuredArguments>
        </arguments>
        <logstashMarkers />
        <stackTrace>
          <fieldName>stack</fieldName>
          <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
            <maxLength>4096</maxLength>
            <rootCauseFirst>false</rootCauseFirst>
          </throwableConverter>
        </stackTrace>
        <message>
          <fieldName>msg</fieldName>
        </message>
      </providers>
    </encoder>
  </appender>

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

</configuration>

Adding Logback and Logstash to the Maven Classpath

Our logback.xml file uses the Logback ConsoleAppender and the Logstash LoggingEventCompositeJsonEncoder both of which are not part of the default Maven distribution.

Fortunately, there’s a convenient place where we can put the requried JAR files:

apache-maven-3.5.2/lib contains all of the supporting JARs used by Maven.

You’ll need to add some JAR files:

  • logback-core.jar
  • logback-classic.jar
  • logstash-logback-encoder.jar
  • jackson-annotations.jar
  • jackson-core.jar
  • jackson-databind.jar
cd sudo cp ~/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.3/jackson-databind-2.9.3.jar /usr/local/apache-maven-3.5.2/lib/.

sudo cp ~/.m2/repository/ch/qos/logback/logback-core/1.2.3/logback-core-1.2.3.jar .

sudo cp ~/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar .

sudo cp ~/.m2/repository/net/logstash/logback/logstash-logback-encoder/4.11/logstash-logback-encoder-4.11.jar .

sudo cp ~/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.9.3/jackson-annotations-2.9.3.jar .

sudo cp ~/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.9.3/jackson-core-2.9.3.jar .

sudo cp ~/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.3/jackson-databind-2.9.3.jar .

I copied these from my local Maven repository, but you can also download them directly from Maven Central if they are not found:

Remove the Default SLF4J Provider

There’s one last thing you need to do to make this work. The default Logback implementation for Maven is supplied by the maven-slf4j-provider.jar. If this JAR file is not removed, SLF4J will complain that there are “SLF4J bindings” and may or may not use the logback implementation we just installed.

% mvn install
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/usr/local/apache-maven-3.5.2/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/usr/local/apache-maven-3.5.2/lib/maven-slf4j-provider-3.5.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
...

Therefore, let’s rename this jar file to avoid this ambiguity:

sudo mv /usr/local/apache-maven-3.5.2/lib/maven-slf4j-provider-3.5.2.jar /usr/local/apache-maven-3.5.2/lib/maven-slf4j-provider-3.5.2.not

Maven JSON Output

With this new Logback configuration correctly installed, we end up with maven install outputting something like this:

{"ts":"2018-04-06T18:38:56.613+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"projectDiscoveryStarted","file":"ExecutionEventLogger.java","line":94,"thread":"main","msg":"Scanning for projects..."}
{"ts":"2018-04-06T18:38:56.967+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"projectStarted","file":"ExecutionEventLogger.java","line":256,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:56.970+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1m------------------------------------------------------------------------\u001B[m"}
{"ts":"2018-04-06T18:38:56.971+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1mBuilding springTest 0.0.1-SNAPSHOT\u001B[m"}
{"ts":"2018-04-06T18:38:56.971+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1m------------------------------------------------------------------------\u001B[m"}
{"ts":"2018-04-06T18:38:57.325+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.326+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-resources-plugin:2.6:resources\u001B[m \u001B[1m(default-resources)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:57.589+00:00","logger":"org.apache.maven.shared.filtering.DefaultMavenResourcesFiltering","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Using 'UTF-8' encoding to copy filtered resources."}
{"ts":"2018-04-06T18:38:57.592+00:00","logger":"org.apache.maven.shared.filtering.DefaultMavenResourcesFiltering","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Copying 1 resource"}
{"ts":"2018-04-06T18:38:57.603+00:00","logger":"org.apache.maven.shared.filtering.DefaultMavenResourcesFiltering","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Copying 0 resource"}
{"ts":"2018-04-06T18:38:57.605+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.605+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-compiler-plugin:3.1:compile\u001B[m \u001B[1m(default-compile)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:57.804+00:00","logger":"org.apache.maven.plugin.compiler.CompilerMojo","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Nothing to compile - all classes are up to date"}
{"ts":"2018-04-06T18:38:57.804+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.805+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-resources-plugin:2.6:testResources\u001B[m \u001B[1m(default-testResources)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:57.809+00:00","logger":"org.apache.maven.shared.filtering.DefaultMavenResourcesFiltering","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Using 'UTF-8' encoding to copy filtered resources."}
{"ts":"2018-04-06T18:38:57.809+00:00","logger":"org.apache.maven.shared.filtering.DefaultMavenResourcesFiltering","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"skip non existing resourceDirectory /home/vagrant/workspace/springTest/src/test/resources"}
{"ts":"2018-04-06T18:38:57.810+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.810+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-compiler-plugin:3.1:testCompile\u001B[m \u001B[1m(default-testCompile)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:57.815+00:00","logger":"org.apache.maven.plugin.compiler.TestCompilerMojo","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"No sources to compile"}
{"ts":"2018-04-06T18:38:57.815+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.815+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-surefire-plugin:2.18.1:test\u001B[m \u001B[1m(default-test)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:57.905+00:00","logger":"org.apache.maven.plugin.surefire.SurefirePlugin","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"No tests to run."}
{"ts":"2018-04-06T18:38:57.916+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:57.916+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-jar-plugin:2.6:jar\u001B[m \u001B[1m(default-jar)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:58.131+00:00","logger":"org.codehaus.plexus.archiver.jar.JarArchiver","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Building jar: /home/vagrant/workspace/springTest/target/springTest-0.0.1-SNAPSHOT.jar"}
{"ts":"2018-04-06T18:38:58.165+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:58.166+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mspring-boot-maven-plugin:1.5.11.RELEASE:repackage\u001B[m \u001B[1m(default)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:58.834+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":283,"thread":"main","msg":""}
{"ts":"2018-04-06T18:38:58.834+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"mojoStarted","file":"ExecutionEventLogger.java","line":290,"thread":"main","msg":"\u001B[1m--- \u001B[0;32mmaven-install-plugin:2.5.2:install\u001B[m \u001B[1m(default-install)\u001B[m @ \u001B[36mspringTest\u001B[0;1m ---\u001B[m"}
{"ts":"2018-04-06T18:38:58.893+00:00","logger":"org.codehaus.plexus.PlexusContainer","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Installing /home/vagrant/workspace/springTest/target/springTest-0.0.1-SNAPSHOT.jar to /home/vagrant/.m2/repository/com/wombat/spring/springTest/0.0.1-SNAPSHOT/springTest-0.0.1-SNAPSHOT.jar"}
{"ts":"2018-04-06T18:38:58.924+00:00","logger":"org.codehaus.plexus.PlexusContainer","level":"INFO","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"info","file":"Slf4jLogger.java","line":59,"thread":"main","msg":"Installing /home/vagrant/workspace/springTest/pom.xml to /home/vagrant/.m2/repository/com/wombat/spring/springTest/0.0.1-SNAPSHOT/springTest-0.0.1-SNAPSHOT.pom"}
{"ts":"2018-04-06T18:38:58.956+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1m------------------------------------------------------------------------\u001B[m"}
{"ts":"2018-04-06T18:38:58.957+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"logResult","file":"ExecutionEventLogger.java","line":210,"thread":"main","msg":"\u001B[1;32mBUILD SUCCESS\u001B[m"}
{"ts":"2018-04-06T18:38:58.957+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1m------------------------------------------------------------------------\u001B[m"}
{"ts":"2018-04-06T18:38:58.958+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"logStats","file":"ExecutionEventLogger.java","line":223,"thread":"main","msg":"Total time: 2.371 s"}
{"ts":"2018-04-06T18:38:58.958+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"logStats","file":"ExecutionEventLogger.java","line":225,"thread":"main","msg":"Finished at: 2018-04-06T14:38:58-04:00"}
{"ts":"2018-04-06T18:38:59.163+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"logStats","file":"ExecutionEventLogger.java","line":233,"thread":"main","msg":"Final Memory: 22M/256M"}
{"ts":"2018-04-06T18:38:59.163+00:00","logger":"org.apache.maven.cli.event.ExecutionEventLogger","level":"INFO","class":"org.apache.maven.cli.event.ExecutionEventLogger","method":"infoMain","file":"ExecutionEventLogger.java","line":86,"thread":"main","msg":"\u001B[1m------------------------------------------------------------------------\u001B[m"}
[vagrant@centos springTest]$

Filtering JSON Using jq

Now that Maven is logging to JSON, this begs the question:

This JSON is nearly unreadable. Why would anyone want to do this?

To get back to a more readable output, I like to use jq which is a lightweight command-line JSON parser you can use to filter the output.

You can also do a yum install to get it:

yum install jq

Some Filtering Examples

Make logs more readable by outputting only the level and msg fields:

mvn install | jq -c -R 'fromjson? | {level,msg}'

Display only Maven error message:

mvn install | jq -c -R 'fromjson? | select(.level=="ERROR") | {msg}'

Display only the BUILD SUCCESS or BUILD FAILURE line

mvn install | jq -c -R 'fromjson? | select(.msg | contains("BUILD")) | {level,msg}'

One More Thing

There’s another reason that I was interested in JSON output from Maven:

I want to use Splunk for monitoring the progress of a long build process.

Typically, monitoring the progress of Maven an epic build involves trying to interpret a lot of scrollback in the console. If you have the output from previous Maven builds in the same console, you will get lost almost immediately.

Using Splunk we can:

  • Highlight BUILD SUCCESS and BUILD FAILURE outcomes.
  • Watch builds in realtime using complex event filters.
  • Benchmark parts of the build process.
  • Create Splunk Alerts that respond to specific error messages.
  • Search specifically for warnings that are often ignored.

This will become the topic for my next blog post…

References