Cleaner Stack Traces and Error Logging in Kotlin (and Java)

Here’s a brief summary of a couple techniques we use to clean up stack traces and other exception details before logging them. These approaches make troubleshooting via application logs so much easier for our team members. The code is in Kotlin, but the same principles can easily be transferred to other JVM languages.

1. Only Our Code

Thanks to Kotlin’s treatment of exceptions, we get to pick where to catch any exception. Whenever possible, we do that at a single, crucial point “high up” in the request handling hierarchy of our server code. This centralization enables us to communicate exceptions to a user and report them to ourselves in a uniform and consistent way that does not need to be reinvented for each new exception type. Because we always know where the exception is coming from–and because it’s usually our own code that needs fixing–we can safely filter out all entries in the stack trace that are not ours, once we’re tracing through our code.

fun ourCodeOnly(t: Throwable): List<StackTraceElement> {
  var enteredOurCode = false
  return t.stackTrace.filter {
    if (it.className.startsWith("io.dealpoint")) {
      if (!enteredOurCode) {
        enteredOurCode = true
      }
      true
    }
    else !enteredOurCode
  }
}

We accept all stack trace entries until we see the first one for our own code. From there on, we only keep our own entries. We’ve experimented with not showing items further up the stack–i.e. only showing our own trace entries. While we didn’t run into issues with it, we decided it to keep it safe for now.

2. Shortest Path–aka Root Cause Exception

Given the monstrous request handler/filter chains in your typical servlet container, the optional AOP injections, and who knows what else, one quickly ends up with stack traces from hell. Even filtering out everyone else’s code may leave us with several nested exceptions. This is really a bigger issue in Java, where exceptions are more often wrapped and re-thrown than in Kotlin. Nevertheless, we transferred this technique from our previous experience with Java to Kotlin. So, let’s get to the root of it:

fun rootCause(t: Throwable): Throwable {
  var current = t
  var cause: Throwable? = null
  while (current !== cause) {
    cause = current
    val nextCause = current.cause
    if (nextCause !== null) {
      current = nextCause
    }
  }
  return if (cause is SQLException) unwrapSqlException(cause)
  else cause
}

As with the stack trace filtering earlier, we have yet to lose valuable troubleshooting information by doing so. Intermediate exceptions usually don’t add anything new unless they would provide data specific to the failing request, which they typically do not. We get what we need for the sleuthing to commence from the associated request URL in the correlated access logs or from smart logging at the beginning of/throughout critical code sections.

3. More Than One SQL Exception

Many years ago, before I realized that a single SQLException could contain more than one cause that is not reported via the usual cause field, I lost several hours on troubleshooting database-related exceptions–being consistently led down the wrong path and left in bewilderment as to how the errors I saw could even be possible. For whatever reason, the additional information hidden behind SQLException‘s nextException was–excuse me–is not being reported by the logging library du jour. My team members don’t need to waste all that head-banging-against-the-wall time I already put in (aka DRY), so we

fun unwrapSqlException(sqlException: SQLException): Throwable {
  val fullMessage = StringBuilder()
  var next: SQLException? = sqlException
  var cause: SQLException? = null
  var count = 1
  while (next !== null && next !== cause) {
    if (next !== sqlException) {
      fullMessage.append("\n")
    }
    fullMessage.append(count).append(") ").append(next.message)
    count++
    cause = next
    next = next.nextException
  }
  val exception = SQLException(fullMessage.toString())
  // retain original stack trace
  exception.stackTrace = sqlException.stackTrace
  return exception
}

This function neatly lists all SQL exception details in one message, numbered by the order in which the JDBC driver reported them. Unlike with the previous two strategies, here we’re actually adding something to the exception output. Sensibly so–it really has saved us hours of debugging SQL problems.

4. Putting It All Together

While we strive to centralize all exception handling, no complex application has a single entry/exit point. We also occasionally want to catch/handle certain errors deeper in the stack, such as reporting problems before retrying or while processing something in batch that we don’t want to give up on just yet because of problems with individual items in that batch. We do still want to know about it in the logs, though.

fun Logger.cleanError(details: String, t: Throwable) {
  val rootCause = rootCause(t)
  rootCause.stackTrace = ourCodeOnly(rootCause).toTypedArray()
  this.error(details, rootCause)
}

cleanError is defined as an extension function of org.slf4j.Logger, so we can call log.cleanError in all cases where we would have written log.error before. The rule we have is simple: If you caught an exception explicitly, call log.cleanError first no matter what. The result is clean enough that we’d rather over-report than miss an issue.

5. One More Thing

To get a logger instance, we use a utility extension function similar to this:

inline fun <reified T : Any> T.logger(): org.slf4j.Logger {
  val k = this::class
  return org.slf4j.LoggerFactory.getLogger(
    if (k.isCompanion) k.java.enclosingClass.simpleName
    else k.java.simpleName)
}

As a result, our Kotlin components can get a class-specific logger instance with this common line of code:

private companion object { val log = logger() }

… which we think is neat.