Application Logging in Java: Converters

11 May 2019 • logging

TL;DR: Outputting lines of text happens through converters, which turn ILoggingEvent into String. Converters can be a bit tricky to use at first, but there are techniques that let you make censors, uuids and the like fairly easily.

This is part of the series of blog posts:

Overview

As the manual says, "At the present time, PatternLayoutEncoder is the only really useful encoder. […] However, we hope that with the advent of new and powerful encoders this impression will change." If you are writing JSON, then you should use logstash-logback-encoder, but that's not what we're talking about: for outputting a line of text, the canonical layout is PatternLayout.

PatternLayout uses converters. A converter is associated with a conversion word, and may have options passed into it. All of the out of the box keywords are associated with converters. For example, take the string %date{HH:mm:ss.SSS}. When you see %date{HH:mm:ss.SSS}, that means that an instance of ch.qos.logback.classic.pattern.DateConverter is created. The {HH:mm:ss.SSS} bit is pulled in using getOptionsList() on the converter.

While actions are evaluated once, at configuration time, converters are executed on every logging event, and produce a String. This makes them more akin to functions.

You can do a bunch with the out of the box converters, but if you want to do custom logic, you'll probably be going through converters to do it.

Custom Converters

The way you do this is by writing custom converters. For example, if you wanted to append the phrase "in bed" to the message, you could create an InBedConverter and define it:

public class InBedConverter extends ClassicConverter {
  @Override
  public String convert(ILoggingEvent event) {      
    return event.getFormattedMessage() + " in bed";
  }
}

And then reference it from XML:

<configuration>
<conversionRule conversionWord="bed" converterClass="InBedConverter" />       

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%bed</pattern>
    </encoder>
</appender>
</configuration>

Note that there is some awkwardness in having to call event.getFormattedMessage and append the string here. If you didn't know that you have to call getFormattedMessage and not getMessage, you would end up not going through the formatting pipeline. What we'd really like to do is call %message and then feed that in to add the string.

Fortunately, this is already available in the form of the CompositeConverter. Using a composite converter, we can define the following:

<configuration>
<conversionRule conversionWord="bed" converterClass="InBedCompositeConverter" />       

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%bed(%message)</pattern>
    </encoder>
</appender>
</configuration>

And the implementation is as follows:

public class InBedConverter extends CompositeConverter<ILoggingEvent> {
    public String transform(ILoggingEvent event, String in) {
        return in + " in bed";
    }
}

This lets you string together converters to progressively transform strings.

Converter Configuration

Converters look great on the surface, but they also have some issues. With appenders and encoders, you are using Joran to do configuration, and so anything that is roughly Javabean shaped will work: if you say getFoo()/setFoo() then you can specify a foo and be able to access that specific instance from the LoggerContext using getAppenderByName.

The problem with converters is that they don't go through configuration. Instead, they're instantiated as pure instances, and are not easy to access from the outside. This means that if you have any complex configuration you want to do, you are either looking at long list of options, as exemplified by ShortenedThrowableConverter, or you will be accessing a reference through the context scope.

Personally, I like setting objects in the context scope, because it means I can get richer data. Here, TerseHighlightConverter pulls out a Map<String, String> to determine how to colorize the level.

public class TerseHighlightConverter extends ForegroundCompositeConverterBase<ILoggingEvent> {
    @Override
    protected String getForegroundColorCode(ILoggingEvent event) {
        String configKey = Optional.ofNullable(getFirstOption()).orElse(HIGHLIGHT_CTX_KEY);

        Map<String, String> config = (Map<String, String>) getContext().getObject(configKey);
        if (config == null) {
            addWarn("No map found in context with key " + configKey);
            return Color.BLACK.code;
        }

        Level level = event.getLevel();
        String levelColor = config.get(level.levelStr.toLowerCase()).toUpperCase();
        return Color.valueOf(levelColor).code;
    }
}

This lets us pull the configuration from Typesafe Config, as seen in the previous post, and refer to highlightMap:

<configuration>
  <typesafeConfig>
    <object name="highlightMap" path="highlight" scope="context"/>
  </typesafeConfig>

  <conversionRule conversionWord="terseHighlight" converterClass="com.tersesystems.logback.TerseHighlightConverter"/>

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

You can of course solve all of your converter problems by adding another level of indirection, i.e.

public class FunctionConverter extends ClassicConverter {
    @Override
    public String convert(ILoggingEvent event) {
        return convertFn().apply(event);
    }

    private Function<ILoggingEvent, String> convertFn() {
        return (Function<ILoggingEvent, String>) getContext().getObject(getFirstOption());
    }
}

But now you have the problem of how to set up your functions. We'll go into how to do that a bit later.

Evaluators

There's the option of NOT calling a converter, by requiring an evaluator. Evaluators are basically predicates, and are used in cases where you have an expensive computation such as %caller{3, CALLER_DISPLAY_EVAL}.

I don't think evaluators are very useful. They can only be used on evaluator-aware converters like %caller and %ex: you can't simply pass it in to any converter. The assumption is that you'll use the Janino event evaluator:

<evaluator name="DISP_CALLER_EVAL">
    <expression>logger.contains("chapters.layouts") &amp;&amp; \
        message.contains("who calls thee")</expression>
</evaluator>

Personally, I would rather not write my code in an XML file. Given that custom converters aren't hard to write, I think these can be skipped.

Instead, get comfortable with Logback. Use actions to populate the object map from configuration, then pull data from the object map for converters. (Evaluators do get a lot more useful when you are able to decorate ILoggingEvent with your own data. This is covered later in the series with appenders.)

Populating Object Map with Actions

Earlier, the question of "how to push logic into the object map" was raised. The way to do this is with actions, backed through configuration.

As an example, here's the censor converter from terse-logback:

public class CensorConverter extends CompositeConverter<ILoggingEvent> {
    private Censor censor;

    @Override
    public void start() {
        super.start();
        Map<String, Censor> censorBag = (Map<String, Censor>) getContext().getObject(CENSOR_BAG);
        if (censorBag == null || censorBag.isEmpty()) {
            addError("Null or empty censor bag found in context!");
        }

        List<String> optionList = getOptionList();
        addInfo(String.format("Pulling options %s", optionList));
        String censorName = getFirstOption();
        if (censorName == null) {
            censorName = censorBag.keySet().iterator().next();
            addInfo(String.format("Pulling first censor name %s from censor bag converter: ", censorName));
        } else {
            addInfo(String.format("Referencing explicit censor name %s in converter: ", censorName));
        }

        censor = censorBag.get(censorName);
        if (censor == null) {
            addError(String.format("No censor with name %s found in censor bag!", censorName));
        }
    }

    @SuppressWarnings("unchecked")
    public String transform(ILoggingEvent event, String in) {
        return String.valueOf(censor.censorText(in));
    }
}

and the CensorAction that sets up a censor action and sticks it in context (and does the conversionWord addition):

public class CensorAction extends Action {
    Censor censor;
    private boolean inError = false;

    @SuppressWarnings("unchecked")
    public void begin(InterpretationContext ic, String localName, Attributes attributes) throws ActionException {
        censor = null;
        inError = false;

        Map<String, Object> omap = ic.getObjectMap();
        if (! omap.containsKey(CENSOR_BAG)) {
            omap.put(CENSOR_BAG, new HashMap<String, Censor>());
        }

        String className = attributes.getValue(CLASS_ATTRIBUTE);
        if (OptionHelper.isEmpty(className)) {
            addError("Missing class name for censor. Near [" + localName + "] line " + getLineNumber(ic));
            inError = true;
            return;
        }

        try {
            addInfo("About to instantiate censor of type [" + className + "]");
            censor = (Censor) OptionHelper.instantiateByClassName(className, Censor.class, context);
            Context icContext = ic.getContext();
            if (censor != null) {
                censor.setContext(icContext);
            }

            String censorName = ic.subst(attributes.getValue(NAME_ATTRIBUTE));
            if (OptionHelper.isEmpty(censorName)) {
                addWarn("No censor name given for censor of type " + className + "].");
            } else {
                censor.setName(censorName);
                addInfo("Naming censor as [" + censorName + "]");
            }

            HashMap<String, Censor> censorBag = (HashMap<String, Censor>) ic.getObjectMap().get(CENSOR_BAG);
            getContext().putObject(CENSOR_BAG, censorBag);

            censorBag.put(censorName, censor);

            ic.pushObject(censor);
        } catch (Exception oops) {
            inError = true;
            addError("Could not create a Censor of type [" + className + "].", oops);
            throw new ActionException(oops);
        }
    }

    private void addConverter() {
        Map<String, String> ruleRegistry = (Map<String, String>) context.getObject(CoreConstants.PATTERN_RULE_REGISTRY);
        if (ruleRegistry == null) {
            ruleRegistry = new HashMap<String, String>();
            context.putObject(CoreConstants.PATTERN_RULE_REGISTRY, ruleRegistry);
        }
        ruleRegistry.putIfAbsent(CensorConstants.CENSOR_RULE_NAME, CensorConverter.class.getName());
    }

    public void end(InterpretationContext ec, String name) {
        if (inError) {
            return;
        }

        if (censor != null) {
            censor.start();
        }
        Object o = ec.peekObject();

        if (o != censor) {
            addWarn("The object at the end of the stack is not the censor named [" + censor.getName() + "] pushed earlier.");
        } else {
            ec.popObject();
        }
    }
}

So with this configuration, you populate the object map with RegexCensor:

<censor name="text-censor" class="com.tersesystems.logback.censor.RegexCensor">
    <regex>${censor.text.regex}</regex>
    <replacementText>[${censor.text.replacementText}]</replacementText>
</censor>

After that, you can call the censor as follows:

%logger{15} -  %censor(%message){text-censor}

And that's it.