Terse Systems

Application Logging in Java: Appenders

27 May 2019 • logging

TL;DR: Appenders can be composed and used to decorate ILoggingEvent to add extra functionality to Logback. It's even possible to select a set of appenders at runtime according to your own logic.

This is part of the series of blog posts:

Overview

Appenders are the sinks of Logback, where ILoggingEvent go to get serialized.

There's a lot to say about appenders, because appenders are central to Logback.

The first thing to say is that most of the time, you won't need custom appenders. You'll do fine with the out of the box ones.

However, if you do need to write custom appenders or the base ILoggingEvent API isn't doing it for you, you can use appenders to construct logging pipelines that are very different from anything you'll find out of the box.

The extensible part of appenders comes from the concept of an Attachable. This is not found anywhere in the Logback manual, but a good part of Logback's functionality depends on it.

Attaching Stuff To Appenders

If you want to add things that aren't strings to your appender, then you need to add an Attachable. There are examples of attachables in FilterAttachable and AppenderAttachable, but the general concept applies anywhere you want to attach to a parent element in Logback.

For example, the previous post discussed a Player which could be used to play audio in response to an event.

public interface PlayerAttachable {
    void addPlayer(Player player);

    void clearAllPlayers();
}

and then you can add it to your appender like this:

public class AudioAppender extends AppenderBase<ILoggingEvent> implements PlayerAttachable {
    private Player player;

    @Override
    protected void append(ILoggingEvent eventObject) {
        player.play();
    }

    @Override
    public void addPlayer(Player player) {
        this.player = player;
    }

    @Override
    public void clearAllPlayers() {
        this.player = null;
    }

    @Override
    public void start() {
        if (player == null) {
            addError("No player found!");
        } else {
            super.start();
        }
    }
}

and have a section in the PlayerAction that accounts for it:

public class PlayerAction extends Action {
    Player player;
    private boolean inError = false;

    @Override
    public void begin(InterpretationContext ic, String localName, Attributes attributes) throws ActionException {
        Object o = ic.peekObject();

        if (!(o instanceof PlayerAttachable)) {
            String errMsg = "Could not find a PlayerAttachable at the top of execution stack. Near [" + localName + "] line " + getLineNumber(ic);
            inError = true;
            addInfo(errMsg);
            return;
        }

        PlayerAttachable playerAttachable = (PlayerAttachable) o;
        // ... instantiate player
        playerAttachable.addPlayer(player);
    }
}

and then you can set up appenders by logger, so only messages going to "audio" logger will make a sound:

<configuration>
  <newRule pattern="*/player"
           actionClass="com.tersesystems.logback.audio.PlayerAction"/>

  <appender name="AUDIO" class="com.tersesystems.logback.audio.AudioAppender">
    <player class="com.tersesystems.logback.audio.ResourcePlayer">
      <resource>/ping.ogg</resource>
    </player>
  </appender>

  <logger name="audio" level="INFO">
    <appender-ref ref="AUDIO">
  </logger>

  <root level="INFO">
    <appender-ref ref="STDOUT">
  </logger>
</configuration>

Or you can set up appenders with filters to play only when certain conditions are met:

<configuration>
  <newRule pattern="*/player"
           actionClass="com.tersesystems.logback.audio.PlayerAction"/>

    <!-- AUDIO-DEBUG etc are all set up like this with a filter -->
    <appender name="AUDIO-ERROR" class="com.tersesystems.logback.audio.AudioAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>

        <player class="com.tersesystems.logback.audio.ResourcePlayer">
            <resource>/error.ogg</resource>
        </player>
    </appender>

    <root level="TRACE">
        <appender-ref ref="AUDIO-TRACE"/>
        <appender-ref ref="AUDIO-DEBUG"/>
        <appender-ref ref="AUDIO-INFO"/>
        <appender-ref ref="AUDIO-WARN"/>
        <appender-ref ref="AUDIO-ERROR"/>
    </root>
</configuration>

Composite Appenders

Logback can nest appenders using AppenderAttachable. You can use this to compose appenders together:

public class CompositeAppender<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

    protected AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();

    @Override
    protected void append(E eventObject) {
        aai.appendLoopOnAppenders(eventObject);
    }
    
    // AppenderAttachable API delegates to aai in all cases
}

This means you can do things like this, putting two appenders together:

<configuration>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%-5level] %logger{15} -  message%n%xException{10}</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>file.log</file>
        <encoder>
            <pattern>%date - %message</pattern>
        </encoder>
    </appender>

    <appender name="CONSOLE_AND_FILE" class="com.tersesystems.logback.CompositeAppender">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </appender>

    <root level="TRACE">
        <appender-ref ref="CONSOLE_AND_FILE"/>
    </root>
</configuration>

You can leverage nesting to keep your filtering logic under control. For example, you may want to have several things happen when you hit an error in your logs. Appenders will always write when they receive an event, unless they are filtered.

Using nesting, you can declare the filter once, and have the child appenders "inherit" that filter:

<configuration>
    <newRule pattern="*/player"
           actionClass="com.tersesystems.logback.audio.PlayerAction"/>

    <!-- Filter is on the appender chain -->
    <appender name="ERROR-APPENDER" class="com.tersesystems.logback.CompositeAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
      
        <appender class="ch.qos.logback.core.FileAppender">
            <file>error.log</file>
            <encoder>
                <pattern>%date - %message</pattern>
            </encoder>
        </appender>

        <appender class="com.tersesystems.logback.audio.AudioAppender">
            <player class="com.tersesystems.logback.audio.ResourcePlayer">
                <resource>/error.ogg</resource>
            </player>
        </appender>
    </appender>

    <root level="TRACE">
        <appender-ref ref="ALL-APPENDER"/>
        <appender-ref ref="TRACE-APPENDER"/>
        <appender-ref ref="DEBUG-APPENDER"/>
        <appender-ref ref="INFO-APPENDER"/>
        <appender-ref ref="WARN-APPENDER"/>
        <appender-ref ref="ERROR-APPENDER"/>
    </root>
</configuration>

This makes your appender logic much cleaner.

Decorating Appenders

Not only can we compose appenders together, but we can also decorate the logging event at the same time. This involves using the decorator pattern to add extra information to data.

So, given DecoratingAppender like so:

public abstract class DecoratingAppender<E, EE extends E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<EE> {

    protected AppenderAttachableImpl<EE> aai = new AppenderAttachableImpl<EE>();

    protected abstract EE decorateEvent(E eventObject);

    @Override
    protected void append(E eventObject) {
        aai.appendLoopOnAppenders(decorateEvent(eventObject));
    }

    public void addAppender(Appender<EE> newAppender) {
        addInfo("Attaching appender named [" + newAppender.getName() + "] to " + this.toString());
        aai.addAppender(newAppender);
    }

    // ...
}

So, imagine that we want to extend ILoggingEvent so that we can include a unique id along with it.

public interface IUniqueIdLoggingEvent extends ILoggingEvent {
    String uniqueId();
}


public class UniqueIdLoggingEvent extends ProxyLoggingEvent implements IUniqueIdLoggingEvent {
    private final String uniqueId;
    UniqueIdLoggingEvent(ILoggingEvent delegate, String uniqueId) {
        super(delegate);
        this.uniqueId = uniqueId;
    }

    @Override
    public String uniqueId() {
        return this.uniqueId;
    }
}

We can create a UniqueIdEventAppender by extending DecoratingAppender:

public class UniqueIdEventAppender extends DecoratingAppender<ILoggingEvent, IUniqueIdLoggingEvent> {
    private final IdGenerator idGenerator = IdGenerator.getInstance();

    @Override
    protected IUniqueIdLoggingEvent decorateEvent(ILoggingEvent eventObject) {
        return new UniqueIdLoggingEvent(eventObject, idGenerator.generateId());
    }
}

And then use a converter to pull out directly:

public class UniqueIdConverter extends DynamicConverter<IUniqueIdLoggingEvent> {
    @Override
    public String convert(IUniqueIdLoggingEvent event) {
        return event.uniqueId();
    }
}

And then refer to it in the layout:

<configuration>
    <conversionRule conversionWord="uniqueId" converterClass="com.tersesystems.logback.UniqueIdConverter" />

    <appender name="DECORATE_WITH_UNIQUEID" class="com.tersesystems.logback.UniqueIdEventAppender">
        <appender class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%-5relative %-5level %uniqueId %logger{35} - %msg%n</pattern>
            </encoder>
        </appender>

        <appender class="ch.qos.logback.core.read.ListAppender">
            <name>LIST</name>
        </appender>
    </appender>

    <root level="TRACE">
        <appender-ref ref="DECORATE_WITH_UNIQUEID"/>
    </root>
</configuration>

This lets us enrich events seamlessly in the logback context.

Appender Selection

Different appenders are useful in different environments.

Development wants:

Want colorized output on their consoles, with line oriented logs.
Would also like to be able to read through logs with debug, info and warnings in them, to track control flow. If you have the logs seperated, that makes it harder.
Generally don't want to run a local ELK stack or TCP appenders to see their logs.

Operations wants:

Really want centralized logging, and a way to drill out on it. Structured logging especially.
May want to have everything write to STDOUT, as is case for Docker / 12 Factor Apps.
May have duplicate logs from the underlying architecture, that need to be dedupped.
May not want redundant / repeated messages, which developers are not as sensitive to.
Really hate getting paged with the same error repeatedly.

Logback is not aware of different environments. There's no out of the box way to say "in this environment I want these sets of appenders, but in this other environment I want these other sets of appenders."

Fortunately, adding this is pretty easy, by leveraging AppenderAttachable and pulling a key to select on:

public class SelectAppender extends AppenderBase<ILoggingEvent> implements AppenderAttachable<ILoggingEvent> {
    private AppenderAttachableImpl<ILoggingEvent> aai = new AppenderAttachableImpl<ILoggingEvent>();
    private String appenderKey;

    @Override
    protected void append(ILoggingEvent eventObject) {
        Appender<ILoggingEvent> appender = aai.getAppender(appenderKey);
        if (appender == null) {
            addError("No appender found for appenderKey " + appenderKey);
        } else {
            appender.doAppend(eventObject);
        }
    }

    // ...
}

The logback appenders under selection must have the name defined as an element, because Logback only looks for the name attribute at the top level, but otherwise they're the same. Here, we select the set of appenders we want based on the LOGBACK_ENVIRONMENT environment variable.

<configuration>
    <appender name="SELECT" class="com.tersesystems.logback.SelectAppender">
        <appenderKey>${LOGBACK_ENVIRONMENT}</appenderKey>

        <appender class="com.tersesystems.logback.CompositeAppender">
            <name>test</name>
            <appender class="ch.qos.logback.core.read.ListAppender">
                <name>test-list</name>
            </appender>
        </appender>

        <appender class="com.tersesystems.logback.CompositeAppender">
            <name>development</name>
            <appender class="ch.qos.logback.core.ConsoleAppender">
                <name>development-console</name>
                <encoder>
                    <pattern>%-5relative %-5level %logger{35} - %msg%n</pattern>
                </encoder>
            </appender>
        </appender>

        <appender class="com.tersesystems.logback.CompositeAppender">
            <name>staging</name>
            <appender class="ch.qos.logback.core.ConsoleAppender">
                <name>staging-console</name>
                <encoder>
                    <pattern>%-5relative %-5level %logger{35} - %msg%n</pattern>
                </encoder>
            </appender>

            <appender class="ch.qos.logback.core.FileAppender">
                <name>staging-file</name>
                <file>file.log</file>
                <encoder>
                    <pattern>%-5relative %-5level %logger{35} - %msg%n</pattern>
                </encoder>
            </appender>
        </appender>
    </appender>

    <root level="TRACE">
        <appender-ref ref="SELECT"/>
    </root>

</configuration>

This is a much cleaner way to organize appenders than putting Janino logic into the configuration.

Conclusions

Appenders are a lot more flexible than you'd believe, and you can do more with them than you think.

Next up: an interlude on SLF4J benchmarks.