Application Logging in Java: Markers

18 May 2019 • logging

TL;DR: Markers can be used to enrich logging events, and enable functionality without changing the SLF4J API. This post demonstrates enriched events by creating an AudioMarker class, and using it to play sound using the javax.sound API through Logback when the marker is attached.

This is part of the series of blog posts:

Overview

Markers are part of the SLF4J API, but they are not well documented. The most documentation you can find on Markers is on Stack Overflow, in Best practices for using Markers in SLF4J/Logback, where markers are listed as being for filtering, and triggering.

This is literally true, but severely understates the case for Markers: SLF4J markers enrich ILoggingEvent. You cannot touch an ILoggingEvent from the Logback API, but you can add and compose as many markers as you want, and those markers can contain both state and behavior. And once you have a marker on the event, you can pattern match on the marker using an appender, and execute on that behavior.

Making a Sound Player

Let's make a simple audio player with the javax.sound API, using the playing trail as a guide:

public interface PlayMethods {

    default void play(Supplier<AudioInputStream> supplier) {
        try (final AudioInputStream in = supplier.get()) {
            AudioFormat baseFormat = in.getFormat();
            AudioFormat targetFormat = new AudioFormat(AudioFormat.Encoding.PCM_SIGNED,
                    baseFormat.getSampleRate(),
                    16,
                    baseFormat.getChannels(),
                    baseFormat.getChannels() * 2,
                    baseFormat.getSampleRate(),
                    false);
            try (final AudioInputStream dataIn = AudioSystem.getAudioInputStream(targetFormat, in)) {
                DataLine.Info info = new DataLine.Info(Clip.class, targetFormat);
                Clip clip = (Clip) AudioSystem.getLine(info);
                if (clip != null) {
                    clip.addLineListener(event -> {
                        if (event.getType() == LineEvent.Type.STOP)
                            clip.close();
                    });

                    clip.open(dataIn);
                    clip.start();
                }
            }
        } catch (LineUnavailableException | IOException e) {
            throw new IllegalStateException(e);
        }
    }
}

And we'll add a Player interface:

public interface Player {
    void play();
}

and a simple implementation:

public class SimplePlayer implements PlayMethods, Player {
    private final Supplier<AudioInputStream> supplier;

    protected SimplePlayer(Supplier<AudioInputStream> supplier) {
        this.supplier = supplier;
    }

    public static Player fromURL(URL url) {
        return new SimplePlayer(() -> {
            try {
                return getAudioInputStream(url);
            } catch (UnsupportedAudioFileException | IOException e) {
                e.printStackTrace();
            }
            return null;
        });
    }
    
    @Override
    public void play() {
        play(supplier);
    }
}

Enriching Events with Markers

Now we've got a player up and running, we can hook it into Logback. Because Marker is an interface, we have to do some work to get a base class implementation up, but that's boring so it's in TerseBasicMarker if you want to see it. The interesting bit is the AudioMarker:

public class AudioMarker extends TerseBasicMarker implements Player {
    private static final String MARKER_NAME = "TS_AUDIO_MARKER";

    private final Player player;

    public AudioMarker(URL url) {
        super(MARKER_NAME);
        player = SimplePlayer.fromURL(url);
    }

    public void play() {
        player.play();
    }
}

Note that the marker name is not significant, so we just use a constant. If we were using this marker with an evaluator, we'd have to do more custom work to disambiguate markers.

Playing AudioMarker with Appender

But this is only half the story. We also need a custom appender that will be aware of markers that it can play:

public class AudioMarkerAppender extends AppenderBase<ILoggingEvent> {

    @Override
    protected void append(ILoggingEvent eventObject) {
        writePlayerMarkerIfNecessary(eventObject.getMarker());
    }

    private void writePlayerMarkerIfNecessary(Marker marker) {
        if (marker != null) {
            if (isPlayerMarker(marker)) {
                ((Player) marker).play();
            }

            if (marker.hasReferences()) {
                for (Iterator<Marker> i = marker.iterator(); i.hasNext();) {
                    writePlayerMarkerIfNecessary(i.next());
                }
            }
        }
    }

    private static boolean isPlayerMarker(Marker marker) {
        return marker instanceof Player;
    }
}

And then we can specify it:

<configuration>

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

    <appender name="AUDIO-MARKER" class="com.tersesystems.logback.audio.AudioMarkerAppender">
    </appender>

    <root>
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="AUDIO-MARKER"/>
    </root>
</configuration>

This lets us indicate that a particular logging event will make your computer bark:

URL audioURL = getClass().getResource("/bark.ogg");
Marker audioMarker = new AudioMarker(audioURL);
logger.info(audioMarker, "Bark!")

Using a PlayerConverter

You are not limited to an appender, of course. You can extract information from anything that takes an ILoggingEvent, such as a converter:

<configuration>
    <conversionRule conversionWord="audio" converterClass="com.tersesystems.logback.audio.PlayerConverter" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-5relative %-5level %logger{35} %audio - %msg%n</pattern>
        </encoder>
    </appender>

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

The source code is available in the logback-audio module.

Needless to say, this can be extended in other directions. Markers are used extensively in logstash-logback-encoder to write to a JSON generator, as described in event specific custom fields.

Next up: Appenders