Using Logstash Logback JSON Encoder with Maven

Search the JSON output by your Maven builds using Splunk.

JSON Output from Maven

If the concept of parsing, let alone reading, the output from Maven seems alien, please refer to my previous blog post concerning the details of Logging Maven to JSON

In a nutshell, we hi-jacked Maven’s Logback Configuration and installed the Logstash Logback JSON Encoder to change the typical text-based output into structured JSON data. Not only is this super-useful for realtime filtering using tools such like jq, but is super-friendly to enterprise-ready search tools such as Splunk

Here are a few things that we considered doing with Splunk:

  • 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.

Note: You don’t specifically need JSON to do these things with Splunk, but I’ve found that it makes constructing Splunk queries more rewarding.

Get a Maven Project

Although the Maven project you choose to build is not important here, Maven can quickly make one for you:

pcunningham ~/demo $ mvn archetype:generate -DgroupId=demo -DartifactId=test -DarchetypeArtifactId=maven-archetype-quickstart -DinteractiveMode=false
{"ts":"2018-07-13T19:22:18.835+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-07-13T19:22:21.928+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"}
pcunningham ~/demo $ find .
.
./test
./test/pom.xml
./test/src
./test/src/test
./test/src/test/java
./test/src/test/java/demo
./test/src/test/java/demo/AppTest.java
./test/src/main
./test/src/main/java
./test/src/main/java/demo
./test/src/main/java/demo/App.java

You will find that Maven has put a pom.xml, App.java, and AppTest.java in the appropriate places for a simple Java JAR project.

Make Some Noise If You’re With Me

The first thing we need are Maven logs. Routing Maven output to a file in your home directory keeps things simple:

pcunningham  ~/demo/test $ mvn > ~/mvn.out

This command should complete with no output after a few seconds. The JSON (and non-JSON) output generated by Maven are simply appended to ~/mvn.out. You can check for yourself:

pcunningham ~/demo/test $ tail ~/mvn.out
{"ts":"2018-07-13T19:28:29.272+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 /Users/pcunningham/demo/test/target/test-1.0-SNAPSHOT.jar to /Users/pcunningham/.m2/repository/demo/test/1.0-SNAPSHOT/test-1.0-SNAPSHOT.jar"}
{"ts":"2018-07-13T19:28:29.274+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 /Users/pcunningham/demo/test/pom.xml to /Users/pcunningham/.m2/repository/demo/test/1.0-SNAPSHOT/test-1.0-SNAPSHOT.pom"}
{"ts":"2018-07-13T19:28:29.284+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":"------------------------------------------------------------------------"}
{"ts":"2018-07-13T19:28:29.285+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":"BUILD SUCCESS"}
{"ts":"2018-07-13T19:28:29.285+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":"------------------------------------------------------------------------"}
{"ts":"2018-07-13T19:28:29.285+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: 1.628 s"}
{"ts":"2018-07-13T19:28:29.286+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-07-13T15:28:29-04:00"}
{"ts":"2018-07-13T19:28:29.372+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: 18M/300M"}
{"ts":"2018-07-13T19:28:29.373+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":"------------------------------------------------------------------------"}

Use jq to filter this into something more readable:

pcunningham ~/demo/test $ tail ~/mvn.out | jq -R -c 'fromjson?|{msg}'
{"msg":"--- maven-install-plugin:2.4:install (default-install) @ test ---"}
{"msg":"Installing /Users/pcunningham/demo/test/target/test-1.0-SNAPSHOT.jar to /Users/pcunningham/.m2/repository/demo/test/1.0-SNAPSHOT/test-1.0-SNAPSHOT.jar"}
{"msg":"Installing /Users/pcunningham/demo/test/pom.xml to /Users/pcunningham/.m2/repository/demo/test/1.0-SNAPSHOT/test-1.0-SNAPSHOT.pom"}
{"msg":"------------------------------------------------------------------------"}
{"msg":"BUILD SUCCESS"}
{"msg":"------------------------------------------------------------------------"}
{"msg":"Total time: 1.628 s"}
{"msg":"Finished at: 2018-07-13T15:28:29-04:00"}
{"msg":"Final Memory: 18M/300M"}
{"msg":"------------------------------------------------------------------------"}

Getting Maven Build Output Into Splunk

Using Splunk to monitor your local build assumes that you are also using a local Splunk instance, and this makes the configuration of data inputs relatively simple using the Splunk web interface:

  • Login to the local Splunk web application
  • Navigate to Settings -> Data Inputs
  • Under Files & Directories click on +Add New
  • Enter the full path to your mvn.out file (ie: /Users/pcunningham/mvn.out) and click Next.
  • You will be able to preview the data here. Click Next.
  • Enter maven as the Name when it asks to Save Source Type.
  • Click Create New Index and use Index Name maven.
  • Click Review and Submit and you are ready to start searching:

Use Splunk’s New Search to run the following query to see the results from your previous maven build:

index="maven"

Time Traveling With Splunk

Setting the Splunk time-range to Last 15 Minutes is probably sufficient to view your most recent results, but now that it’s in Splunk you can always go back in time to view them.

If you need to investigate that strange build warning you were having last Friday, Splunk will find it and everything else that happened in that build.

Use This Command To Build

Now anytime you are building a Maven project, use a command similar to this:

pcunningham ~/demo/test $ mvn -B clean install | tee ~/mvn.out | jq -c -R 'fromjson?|{msg}'
{"msg":"Scanning for projects..."}
{"msg":""}
{"msg":"------------------------------------------------------------------------"}
{"msg":"Building test 1.0-SNAPSHOT"}
{"msg":"------------------------------------------------------------------------"}
{"msg":""}
...
{"msg":"Installing /Users/pcunningham/demo/test/pom.xml to /Users/pcunningham/.m2/repository/demo/test/1.0-SNAPSHOT/test-1.0-SNAPSHOT.pom"}
{"msg":"------------------------------------------------------------------------"}
{"msg":"BUILD SUCCESS"}
{"msg":"------------------------------------------------------------------------"}
{"msg":"Total time: 1.888 s"}
{"msg":"Finished at: 2018-07-13T16:12:18-04:00"}
{"msg":"Final Memory: 18M/300M"}
{"msg":"------------------------------------------------------------------------"}

This uses the -B option with Maven to prevent the ANSI color encoded output in the msg field.

It uses the tee command which allows us to continue viewing the output on the console, while simultaneously writing it to ~/mvn.out.

Finally it uses the jq command to filter and pretty-print the JSON in a more readable format.

Watching Events in Real-Time in Splunk

If you change your Time Range to use one of the Real-Time settings, you can watch the build events appear as they are generated. Give Splunk a few seconds to catch up, but it works pretty well when everything is local.

Just do a Real-Time search using 5 minute window to get the latest output:

index="maven"

Building on Success

You can easily search in Splunk to see if it was successful:

index="maven" msg="BUILD SUCCESS"

If you change your time range to use Real-Time (5 minute window works well), your BUILD SUCCESS event will appear as soon as the build is finished. No need to watch everything going by.

Time Tracking

Because your historical Maven output is now available, you can easily find out if your builds are getting longer:

index="maven" method="logStats" msg="Total time*"

From the events output by this search, you can find out the number of seconds each build took.

Looking for Errors and Warnings

You might be watching a particularly long build for errors, or may need to find errors in the build you completed over a week ago:

index="maven" level="ERROR"

This will give you a quick breakdown of all ERRORs that were logged.

A search for WARNs might reveal the following example:

{"ts":"2018-07-13T20:19:59.480+00:00","logger":"org.apache.maven.plugin.compiler.TestCompilerMojo","level":"WARN","class":"org.apache.maven.cli.logging.Slf4jLogger","method":"warn","file":"Slf4jLogger.java","line":74,"thread":"main","msg":"File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent!"}

Very often these errors and warnings go by so fast that they avoid recognition and reconsiliation. Using Splunk to explicitly search for them provides the information in a more useful context and allows you to view them as a group and weigh the overall consequences of leaving them unresolved. Stats and charts are useful for illustrating their effects across multiple builds.

One More Thing

If you change your ~/.m2/logback.xml to this, your JSON will include two additional fields args and project which can discern between different projects and their corresponding maven goals:

<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>
                <pattern>
                    <pattern>{"args":"${MAVEN_CMD_LINE_ARGS}","project":"${MAVEN_PROJECTBASEDIR}"}</pattern>
                </pattern>
                <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>

This logback configuration change uses the pattern provider to feed the environment variables MAVEN_CMD_LINE_ARGS and MAVEN_PROJECTBASEDIR via new fields named args and project.

With this extra bit of information, you can easily search for specific builds:

index="maven" project="*test" args"*clean*"

This would yield only events from the test application that were built with the clean goal.

References