How to Log Exception Properly

Logging is simple, but not everyone knows how to do it right.

Junior developers often find their application logs unhelpful because it doesn’t tell how their codes went wrong. Eventually they spam logs between every single method invocation, at every IF junction, and print out every values that they can find, hoping the logs would cover every single step and give a better picture of what is happening in the code. And there we are, having lots of redundant logging and messy code.

There are two common root causes that I observe:

1. Developer does not know how to log exception properly, thus no stack trace is printed when exception occurred.
2. Developer doesn’t know how to do debugging using breakpoint in their IDE.

We will discuss about how to log exception properly today.

Below is a Java Spring Boot snippet. We have a logic in a try statement that throws NullPointerException, then we log it in different formats to see the difference.

public String someMethod() {
    Integer a = null;
    try {
        if (a.toString().equals("1")) {
            a = 0;
        }
    } catch (Exception ex) {
        log.error("someMethod ::" + "exception");
        log.error("Error happened. a is ", a);
        log.error(ex.getMessage());
        log.error("Hello", ex.getMessage());
        log.error("Hello again", ex);
    }
    return "OK";
}

Common Mistake 1: Not logging anything in `catch` statement

try {
    if (a.toString().equals("1")) {
        a = 0;
    }
} catch (Exception ex) {
    return "error";
}
return "OK";

The problem with this is developer would not know that an error has happened.

Common Mistake 2: Only log developer’s message

log.error("someMethod ::" + "exception");
log.error("Error happened. a is ", a);

It might look ridiculous, but these are real-life examples. Without any information about the exception, the log almost always useless.

Common Mistake 3: Log the message of the exception

log.error(ex.getMessage());
log.error("Hello", ex.getMessage());

In this example, the message of NullPointerException is just null. Not helpful.

2019-01-29 08:00:41.009 ERROR 42147 --- [ctor-http-nio-3] com.example.rsocketdemo.DemoController   : null

Best Practice: Log the exception object.

log.error("Hello again", ex);

By logging the developer message together with the whole exception object, we can see the developer message is printed first, followed by the exception name and message, then the stack trace.

This gives us a complete picture of what methods were invoked when exception occurred, down to the library level.

Note: Stack trace below is trimmed with ... because the full one is too long to display here.

2019-01-29 08:30:42.142 ERROR 42218 --- [ctor-http-nio-2] com.example.rsocketdemo.DemoController   : Hello again
java.lang.NullPointerException: null
 at com.example.rsocketdemo.DemoController.someMethod(DemoController.java:14) ~[classes/:na]
 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
 ...
 at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) ~[netty-common-4.1.31.Final.jar:4.1.31.Final]
 at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]