How to Log an Exception, Part 2

In the last post, I wrote about how to log an exception, and said:

The correct place to put this would be a custom converter, but I don't feel like getting into it now, and the tricky bit would be populating the mapping, which is domain specific. Still, I think this points out where exception logging could be made more useful.

Guess what? I wrote up an exception mapping registry in terse-logback. Turns out, it wasn't that hard after all!

Let's start off with the example and then work our way back.

Assume you have an exception MyCustomException:

public class MyCustomException extends RuntimeException {
    public MyCustomException(String message, String one, String two, String three, Throwable cause) {
       // ...
    }
    public String getOne() { return one; }
    public String getTwo() { return two; }
    public String getThree() { return three; }
}

and you log an error, containing the domain specific exception:

public class Thrower {
    private static final Logger logger = LoggerFactory.getLogger(Thrower.class);

    public static void main(String[] progArgs) {
        try {
            doSomethingExceptional();
        } catch (RuntimeException e) {
            logger.error("domain specific message", e);
        }
    }

    static void doSomethingExceptional() {
        Throwable cause = new BatchUpdateException();
        throw new MyCustomException("This is my message",
           "one is one", 
           "two is more than one", 
           "three is more than two and one", cause);
    }
}

Using the ExceptionMessageWithMappingsConverter converter, you will get the following exception for a single line:

184 ERROR c.t.l.exceptionmapping.Thrower - domain specific message exception=[com.tersesystems.logback.exceptionmapping.MyCustomException(one="one is one" two="two is more than one" three="three is more than two and one" message="This is my message") > java.sql.BatchUpdateException(updateCounts="null" errorCode="0" SQLState="null" message="null")]

Note that BatchUpdateException also contains properties, like updateCounts, errorCode, and SQLState. This is one of the fun bits of exception mapping: you can declare properties on the base type, and then build it up on the child types. This means in the BatchUpdateException case, the errorCode and SQLState properties are inherited from SQLException, so we only need to define it there.

This means that we can specify message itself as a property on java.lang.Throwable, and we can cover lots of ground with just the base cases. Poking around with the JDK gives us some candidates. Here's an incomplete list:

public class ExceptionMappingRegistryAction extends Action {
    // ...

    protected List<ExceptionMapping> initialMappings() {
        return Arrays.asList(
                new BeanExceptionMapping("java.lang.Throwable", asList("message"), handler),
                new BeanExceptionMapping("java.nio.file.FileSystemException", asList("file", "otherFile", "reason"), handler),
                new BeanExceptionMapping("java.sql.BatchUpdateException", asList("updateCounts"), handler),
                new BeanExceptionMapping("java.sql.SQLException", asList("errorCode", "SQLState"), handler),
                new BeanExceptionMapping("java.text.ParseException", asList("errorOffset"), handler),
                new BeanExceptionMapping("java.time.format.DateTimeParseException", asList("parsedString", "errorIndex"), handler)
                // ...
        );
    }
}

The base unit of operation is an ExceptionMapping, which is a function from Throwable to List<ExceptionProperty>. The vast majority involve JavaBean properties, but there's some chrome in there for handling exceptions with exposed fields as well:

mappings.register(XMLStreamException.class, e -> {
    Location l = e.getLocation();
    if (l == null) {
        return Collections.emptyList();
    }
    return asList(
            ExceptionProperty.create("lineNumber", l.getLineNumber()),
            ExceptionProperty.create("columnNumber", l.getColumnNumber()),
            ExceptionProperty.create("systemId", l.getSystemId()),
            ExceptionProperty.create("publicId", l.getPublicId()),
            ExceptionProperty.create("characterOffset", l.getCharacterOffset())
    );
});

This takes care of rendering exceptions, but it still doesn't map through to structured logging directly. To do that, we need to set up a custom JSON provider in logstash-logback-encoder:

public class ExceptionArgumentsProvider extends AbstractFieldJsonProvider<ILoggingEvent> {
    // ...

    private void renderException(JsonGenerator generator, ExceptionMappingRegistry registry, Throwable throwable) throws IOException {
        Map<String, String> propertyMap = new HashMap<>();
        List<ExceptionProperty> properties = registry.apply(throwable);

        for (ExceptionProperty property : properties) {
            if (property instanceof KeyValueExceptionProperty) {
                KeyValueExceptionProperty p = ((KeyValueExceptionProperty) property);
                propertyMap.put(p.getKey(), p.getValue());
            }
        }

        generator.writeStartObject();
        JsonWritingUtils.writeStringField(generator, "name", throwable.getClass().getName());
        JsonWritingUtils.writeMapStringFields(generator, "properties", propertyMap);
        generator.writeEndObject();
    }
}

and then this generates:

{
  "id" : "Fa7lbgUd2Iw6O0Qbm7EAAA",
  "sequence" : 3,
  "@timestamp" : "2019-07-06T21:22:50.754+00:00",
  "@version" : "1",
  "message" : "I am an error",
  "logger_name" : "example.Main$Runner",
  "thread_name" : "pool-1-thread-1",
  "level" : "ERROR",
  "stack_hash" : "eb336a2d",
  "exception" : [ {
    "name" : "example.MySpecialException",
    "properties" : {
      "message" : "Level 1",
      "timestamp" : "2019-07-06T21:22:50.753Z"
    }
  }, {
    "name" : "example.MySpecialException",
    "properties" : {
      "message" : "Level 2",
      "timestamp" : "2019-07-06T21:22:50.753Z"
    }
  } ],
  "stack_trace" : "<#1165e3b1> example.MySpecialException: Level 2\n\tat example.Main$Runner.nestException(Main.java:56)\n\t... 9 common frames omitted\nWrapped by: <#eb336a2d> example.MySpecialException: Level 1\n\tat example.Main$Runner.nestException(Main.java:56)\n\tat example.Main$Runner.nestException(Main.java:57)\n\tat example.Main$Runner.generateException(Main.java:51)\n\tat example.Main$Runner.doError(Main.java:44)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)\n\tat java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)\n\tat java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n"
}

And now you have actual structured information that you can analyze and correlate with lnav or angle-grinder. Compare this with the text stacktrace, which does not break out the message or timestamp, and has the exception class name awkwardly wrapped:

Fa7lbgUd2Iw6O0Qbm7EAAA 2019-07-06T21:22:50.754+0000 [ERROR] example.Main$Runner in pool-1-thread-1 - I am an error
example.MySpecialException: Level 2
	at example.Main$Runner.nestException(Main.java:56)
	... 9 common frames omitted
Wrapped by: example.MySpecialException: Level 1
	at example.Main$Runner.nestException(Main.java:56)
	at example.Main$Runner.nestException(Main.java:57)
	at example.Main$Runner.generateException(Main.java:51)
	at example.Main$Runner.doError(Main.java:44)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

Full source code is available in the logback-exception-mapping and logback-exception-mapping-providers modules.

Okay, seriously, next week is logging APIs.

Comments