Application Logging in Java: Putting it all together

23 Jun 2019 • logging

TL;DR I demo a project that uses all the techniques set up previously to show a Logback environment that can be used without modification in different environments.

This blog post is going to discuss an example of a packaged library that you'd set up for your projects, available as the logback-structured-config module in terse-logback. There's more detail in the project itself, but for this post I'm going to be discussing the whys more than the hows.

The one thing I'm adding here that I haven't devoted a post to specifically is logging in JSON – since logstash-logback-encoder was the inspiration for this series and I'm not doing anything fancy with it, I think it's covered in the README. Technically, since there are several JSON objects all in one file / stream, this is called "newline delimited JSON" or NDJSON or jsonlines. In this project, both text and JSON formats are rendered independently, but if you only output JSON it's not a huge deal, because you can read JSON logs as text with a special log viewer such as jl, json-log-viewer, or otros log viewer.

So. This project sets up multiple appenders, and then composes those appenders together in different ways. The appenders are broken out into different resource xml files and then included together: this means that downstream projects have the option of overriding those resources if they need to, by ensuring that their resource appears ahead of the library in classpath search order. Notably, the censors are broken out distinctly, since they can be very application specific.

Starting with the beginning of logback.xml:

<configuration>
    <include resource="terse-logback/initial.xml"/>
    <include resource="terse-logback/censor.xml"/>

    <include resource="terse-logback/appenders/audio-appenders.xml"/>
    <include resource="terse-logback/appenders/console-appenders.xml"/>
    <include resource="terse-logback/appenders/jsonfile-appenders.xml"/>
    <include resource="terse-logback/appenders/textfile-appenders.xml"/>

     <!-- ... -->
</configuration>

The audio appenders are set up to use system beeps, rather than playing with the Java Sound API, as it's hard to justify including sound clips in a library, and developers will no doubt want to use their own. The audio appenders also use a budget evaluator to ensure that they don't beep incessently, and also have EnabledFilter so they can be quickly disabled from configuration.

Past that point, the application will compose appenders together by the environment. For example, the development appender does everything – it writes to the console, plays sounds, writes to a log file, and will write detailed information in JSON. Meanwhile, the test environment will only write out to a log file.

<configuration>
     <!-- ... -->
    <appender name="development" class="com.tersesystems.logback.core.CompositeAppender">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="AUDIO"/>
        <appender-ref ref="ASYNC_TEXTFILE"/>
        <appender-ref ref="ASYNC_JSONFILE"/>
    </appender>

    <appender name="test" class="com.tersesystems.logback.core.CompositeAppender">
        <appender-ref ref="ASYNC_TEXTFILE"/>
    </appender>

    <!-- ... -->
</configuration>

There is a selector appender which will select the appropriate environment: only the appender matching the logback.environment key will be used.

<configuration>

    <appender name="selector" class="com.tersesystems.logback.core.SelectAppender">
        <appenderKey>${logback.environment}</appenderKey>

        <appender-ref ref="development"/>
        <appender-ref ref="production"/>
        <appender-ref ref="test"/>
    </appender>

</configuration>

Typically, you'll set logback.environment in logback.conf, or on the command line as a system property.

local {
    logback.environment = "development"
}

Finally, the selector is wrapped with a UniqueIdEventAppender. This appender decorates ILoggingEvent with a unique id, currently a 128 bit flake id using base-62 encoding, and this decorating appender is used as the one and only appender for root. At the very end, the logging levels are set from HOCON.

<configuration>

    <appender name="selector-with-unique-id" class="com.tersesystems.logback.uniqueid.UniqueIdEventAppender">
        <appender-ref ref="selector"/>
    </appender>

    <root>
        <appender-ref ref="selector-with-unique-id"/>
    </root>

    <!-- sets logging levels through typesafe config -->
    <include resource="terse-logback/ending.xml" />
</configuration>

The bulk of the configuration is done through logback-reference.conf, as described in part 2. A full description is on github, but the overview is that there's levels section that allows the logback levels to be set:

levels {
  ROOT = INFO

  # loggers can be defined here
  # com.example.Foo = DEBUG
}

And then there are local and context properties that are exposed to logback as the appropriate scope. Almost everything goes into the local scope. Again, this allows for downstream projects to override values by adding a logback.conf to the application.

local {

  console {
    enabled = true
    withJansi = true # allow colored logging on windows
    encoder {
      pattern = "%uniqueId %date{H:mm:ss.SSS} [%terseHighlight(%-5level){highlightMap}] %logger{15} -  %censor(%message){text-censor}%n%xException{10}"
    }
  }

  # ...
}

And that about does it! I'm glad to finally get this out, and this concludes the blog posts about Logback configuration. I'm not done yet, though. The next series of posts is going to be about logging APIs, about which there's a whole bunch more to say, and is going to have its own github project to address the issue of what you put into your logs and how.