SLF4J/Java logging: Is it possible to add log arguments automatically?

user_4393716 0
Viewed 506

Introduction

We're using SLF4J in combination with Logback in several Spring (Boot) applications and recently started using the logstash-logback-encoder to implement structured logging. As we also still have to support plain text logs, we wondered whether it was possible to append arguments automatically to log messages without having to add them manually to the message using the {} markers.

Example of the desired behaviour

To illustrate the desired behaviour this is what we'd wish for:

log.info("My message", kv("arg1", "firstArgument"), kv("arg2", "secondArgument"))

resulting in the following desired output, where the arguments are automatically appended in parentheses at the end of the message:

My message (arg1="firstArgument", arg2="secondArgument")

Or another example with both explicit arguments in the message and arguments at the end:

log.info("Status changed: {} => {}", v("from", "READY"), v("to", "UNAVAILABLE"), kv("service", "database"))

resulting in the following desired output:

Status changed: READY => UNAVAILABLE (from="READY", to="UNAVAILABLE", service="database")

Question

Is this possible with SLF4J/Logback? And if not, do you know other logging frameworks or ways to achieve this (in Java)?

logstash-logback-encoder slf4j logback logging java
1 Answers

I'm not aware of any log frameworks that let you do this, but you can trivially write your own. Because this really is just a simple API extension, and thus, all you need to duplicate is specifically the various log messages. For example, this one-liner would take care of it:

public static class LoggingExtensions {
    @lombok.Value public static final class LogKeyValue {
        String key, value;
    }

    public static LogKeyValue kv(String key, Object value) {
        return new LogKeyValue(key, String.valueOf(value));
    }

    public static void info(Logger log, String message, Object... args) {
        int extra = 0;
        int len = args.length;

        // Last arg could be a throwable, leave that alone.
        if (len > 0 && args[len - 1] instanceof Throwable) len--;

        for (int i = len - 1; i >= 0; i--) {
            if (!(args[i] instanceof LogKeyValue)) break;
            extra++;
        }
        if (extra > 0) {
          StringBuilder sb = new StringBuilder(message.length() + 2 + (extra.size() - 1) * 2);
          sb.append(message).append("({}");
          for (int i = 1; i < extra; i++) sb.append(", {}");
          message = sb.append(")").toString();
        }
        log.info(message, args);
    }
}

This code tacks ({}, {} {}) at the end of the message, 1 for each 'kv' type. Note that most logging frameworks, including slf4j, do let you tack 1 exception at the end, even without a matching {} in the message, and this method would thus require that you first list all {} args, then any kv args, then 0 or 1 throwables.

Some caveats, though:

  • You'd have to change all your code to invoke these utility methods. You can make it look nice using static imports, but it does make your code less idiomatic, which is a downside.
  • Most log frameworks have an explosion of methods, because varargs cause the creation of arrays. In hotspotted code, the JDK will probably make that sufficiently efficient that it won't matter, but because log statements tend to be ubiquitous, you get a bit of a death-by-a-thousand cuts happening otherwise. It is unlikely that this call by logging frameworks to have a ton of methods to avoid the varargs penalty is a sensible move; generally logs end up on disk and are even fsynced, and the performance impact of that is many orders of magnitude larger. But, log frameworks have to cater to all scenarios, and logs which end up totally ignored due to log level config, in a tight loop, can see some performance improvement due to avoiding the varargs penalty. You can also try to optimize if it comes up that your log frameworks are impacting performance: You can ask the log handlers if the log level that is asked for is even relevant, and if not, just return; immediately. You can then also follow along and create this 'explosion'. See slf4j which has 10 methods for every log level, and many other frameworks have even more (they have a variant for 1, 2, 3, and sometimes even 4 arguments before resorting to varargs).
user_7686440
Related