Question regarding logging, in the context of a Sp...

# server

[Stylianos Gakis]

Question regarding logging, in the context of a Spring project, using SLF4J, Coroutines and Datadog, asking here to see if someone else has encountered this before.

When logging our uncaught exceptions in normal non-coroutine code, the exception is logged by slf4j. The logs are picked up by a Datadog agent, and sent to Datadog. When the exception is shown in Datadog, it takes up one line in the logger, with the stacktrace placed in the log entry’s details.

We recently added coroutines to this service, defining an ApplicationScope like

class ApplicationScope(applicationScope: CoroutineScope) : CoroutineScope by applicationScope
// Then provided like
@Bean
fun applicationScope(): ApplicationScope {
  return ApplicationScope(CoroutineScope(SupervisorJob() + <http://Dispatchers.IO|Dispatchers.IO>))
}

then converted an existing function to be fire-and-forget by using `launch`:

fun doSomething(...) = applicationScope.launch {...}

When an unhandled exception is thrown in the coroutine, somehow it doesn’t follow the normal logging/formatting process. Instead of a single error line in the log, we get each line in the stacktrace showing up as a separate line in the logs. This then shows up in the timeline as a whole lot of errors (50-100+) occurring at the same time.

Has someone who uses this combination of coroutines-slf4j-datadog experienced this before?
Could it be that the logger is not picking up these unhandled exceptions and it’s logging to the console? Or maybe we need to add something special to the ApplicationScope to get SLF4J/Datadog to parse/format this error properly?

[dave]

Your suspicion is exactly what is happening. The Datadog agent will be looking for pre-formatted log lines (with a timestamp etc), but anything sent to the console will also be picked up and handled line-by-line.

[Stylianos Gakis]

Okay that sounds like a reasonable explanation thanks!
We now have to consider our options then!

1) Add a CoroutineExceptionHandler { _, exception -> // log here } inside our @Bean providing the ApplicationScope to simply log the exceptions ourselves there. This will come with the problem of not knowing where the error came from as simply as we do now with how we define our loggers per-class with something like private val logger: org.slf4j.Logger = LoggerFactory.getLogger(Foo::class.java). So unless there’s some way to get that information in there from the Throwable for example we probably have to skip this alternative.

2) We add a coroutineLogger pair everywhere where we do LoggerFactory.getLogger with something like

// top level util
fun org.slf4j.Logger.coroutineExceptionHandlerLogger(): CoroutineExceptionHandler {
  return CoroutineExceptionHandler { _, exception ->
    error(exception)
  }
}
// Per class Foo
class Foo(private val applicationScope: CoroutineScope = CoroutineScope(SupervisorJob())) {
  private val logger: org.slf4j.Logger = LoggerFactory.getLogger(Foo::class.java)
  private val coroutineLogger = logger.coroutineExceptionHandlerLogger()

  fun foo() {
    applicationScope.launch(coroutineLogger) {
    }
  }
}

And simply have to remember to never do a launch without providing our extra CoroutineExceptionHandler in the context of those `launch`es.

Do you see some other alternative to this?