Automatic MDC Logging in Ktor

A coroutine-safe Ktor plugin that enriches every log message with path parameters, without touching your routes

Photo by Thomas Peham on Unsplash

Engineers read more code than they write, but they may read even more log messages. We read them to see if everything works and, if not, to locate the problem. More often than not, it is hard to find a needle in a haystack, especially when things work in 99% of cases but fail for a single user.

To make the haystack smaller, it is vital to filter log messages efficiently, for example by adding the userID. Doing this by hand for every log message would be tedious, but we can leverage the mapped diagnostic context (MDC).

In this post, I will show how to automatically add useful information to the MDC based on path and query parameters in Ktor. With just a few lines of code, you can enrich log messages with valuable context. But first, let us take a look at what MDC actually is.

TL;DR: If you already know what MDC is and just want the Ktor plugin, feel free to skip ahead to the section on implementing the PathParameterMDCPlugin.

You can find the complete code on GitHub.

Understanding Mapped Diagnostic Context

Before we start, I want to make it clear that the following is based on SLF4J / Logback. MDC is not a concept exclusive to Logback, but this is the setup I have experience with.

So, what is MDC? Simplified, it is a thread-local Map<String, String>. The contents of this map can be added to each log message without explicitly doing so every time; this is configured once in the logger configuration.

Here is a simple example. First, we add %X to the Logback pattern to output the MDC content:

<configuration>
    <appender name=”STDOUT” class=”ch.qos.logback.core.ConsoleAppender”>
        <encoder>
            <pattern>MDC: [ %X ] %-5level - %msg%n</pattern>

        </encoder>
    </appender>
...
</configuration>

We can use MDC’s methods:

import org.slf4j.LoggerFactory
import org.slf4j.MDC

fun main() {
    val logger = LoggerFactory.getLogger(”logger”)
    logger.info(”Hello World!”)
    MDC.put(”key”, “value”)
    logger.info(”Hello again!”)
    MDC.put(”another key”, “new value”)
    logger.info(”Goodbye!”)
}

Which gives us:

MDC: [  ] INFO  - Hello World!
MDC: [ key=value ] INFO  - Hello again!
MDC: [ another key=new value, key=value ] INFO  - Goodbye!

It is easy to see how this can be useful. If we can automatically add the userID to every log message, filtering logs becomes trivial.

However, especially with Kotlin and coroutine-heavy Ktor, there is a problem: the MDC is bound to the thread. We can see this in the following example:

MDC.put(”userID”, “abc”)
logger.info(”Start order creation”)
coroutineScope {
    launch {
        MDC.put(”orderID”, “123”)
        logger.info(”Created order”)
    }

}
logger.info(”Publishing order”)

The output looks like this:

MDC: [ userID=abc ] INFO  - Start order creation
MDC: [ orderID=123 ] INFO  - Created order
MDC: [ userID=abc ] INFO  - Publishing order

We lose important information about how orders relate to users if we rely on the static methods. Fortunately, we can fix this by leveraging the correct coroutine context. To do so, we need to add a dependency and fill the MDC differently.

First, add the following dependency to your build.gradle.kts:

 implementation("org.jetbrains.kotlinx:kotlinx-coroutines-slf4j:1.10.2")

Then adjust the code from above:

...
import kotlinx.coroutines.slf4j.MDCContext
import kotlinx.coroutines.withContext

suspend fun main() {
    // ...
    coroutineScope {
        launch(MDCContext()) {
            MDC.put("orderID", "123")
            logger.info("Created order")

        }.invokeOnCompletion { logger.info("Publishing order") }
    }
    logger.info("End order creation") // new here
    }
}

This now produces more useful logging information:

MDC: [ userID=abc ] INFO  - Start order creation
MDC: [ userID=abc, orderId=123 ] INFO  - Created order
MDC: [ userID=abc, orderId=123 ] INFO  - Publishing order
MDC: [ userID=abc ] INFO  - End order creation

We can make two observations:

• userID is now propagated to the coroutine, as intended.

• Additions to the MDC are not propagated outside of the coroutine implicitly. There is a solution for this, which you can find in the KDoc.

Armed with that knowledge, let us take a look at how to fill the MDC based on your routes.

Deriving MDC Values from Routes

Our goal is to add any useful information present in the routes to the MDC.

For example, your application might have the following routes:

get("/orders/{orderID}/items/{itemID}") {
    logger.info("Processing order")
    call.respond("")
}

get("/items/{itemID}") {
    logger.info("Processing request for item")
    call.respond("")
}

For each call to /orders, we want both orderID and itemID in the MDC; for /items, only itemID. There are several ways to achieve this. The simplest approach is to add these values to the MDC manually, as shown above. This works fine for two or three routes but quickly becomes a hassle as the number of routes grows.

Another option is to leverage the CallLogging plugin, which we will look at next.

Using CallLogging to Populate the MDC

If your routes are well defined, you can configure CallLogging to populate the MDC. Well defined means that the path segment before a given ID is always the same. For example, items/ always precedes the {itemID} path parameter. This is necessary because CallLogging does not know about path parameters. Instead, you need to parse the resolved URL and extract the parameters yourself.

fun extractPathParameter(url: String, paramName: String) = when (paramName) {
    “itemID” -> “/items/([^/]+)”.toRegex().find(url)?.groupValues?.get(1)
    “orderID” -> “/orders/([^/]+)”.toRegex().find(url)?.groupValues?.get(1)
    else -> null
}

You can then use this function in the CallLogging plugin:

install(CallLogging) {
    mdc(”itemID”) { call ->
        extractPathParameter(call.request.uri, “itemID”)
    }
    mdc(”orderID”) { call ->
        extractPathParameter(call.request.uri, “orderID”)
    }
}

Note that call.request.uri contains the already resolved URL, which is why the extractPathParameter function is needed. With this setup, calling the endpoints yields:

MDC: [ itemID=123 ] INFO  - Processing request for item
MDC: [ itemID=123 ] INFO  - 200 OK: GET - /items/123 in 240ms
MDC: [ itemID=789, orderID=456 ] INFO  - Processing order
MDC: [ itemID=789, orderID=456 ] INFO  - 200 OK: GET - /orders/456/items/789 in 2ms

Nice, we get our IDs into the MDC without changing the routes. However, this approach only works if your routes are predictable and parameters can be reliably extracted from the resolved URL. In older applications with many past maintainers, the API schema is often less consistent. You could try to handle all cases in extractPathParameter, but that quickly becomes tedious. Luckily, there is another solution.

Implementing a Custom MDC Plugin

So assume the orders endpoint looks like this, using item instead of items:

get(”/orders/{orderID}/item/{itemID}”) {
    logger.info(”Processing order 2”)
    call.respond(”“)
}

Now, adding itemID to the MDC will still work for /items, but not for /orders:

MDC: [ itemID=123 ] INFO  - Processing request for item
MDC: [ itemID=123 ] INFO  - 200 OK: GET - /items/123 in 483ms
MDC: [ orderID=456 ] INFO  - Processing order 2
MDC: [ orderID=456 ] INFO  - 200 OK: GET - /orders/456/item/789 in 1ms

In this simple example, you could extend the extractPathParameter function, but this becomes error-prone and tedious in a real-life scenario with 30+ routes and many different path parameters. It is easier to find a solution that knows the path parameters directly and does not depend on the URL structure.

So it is time to write our own Ktor plugin. The idea is simple: intercept the pipeline at a point where path parameters and their values are known, add them to the MDC, and then let the pipeline continue.

class PathParameterMDCPlugin {
    companion object Plugin : BaseRouteScopedPlugin<Unit, PathParameterMDCPlugin> {
        override val key = AttributeKey<PathParameterMDCPlugin>(”MdcPlugin”)

        override fun install(
            pipeline: ApplicationCallPipeline,
            configure: Unit.() -> Unit,
        ): PathParameterMDCPlugin {
            val plugin = PathParameterMDCPlugin()

            pipeline.intercept(ApplicationCallPipeline.Call) {
                call.parameters.forEach { key, values ->
                    MDC.put(key, values.joinToString())
                }
                withContext(MDCContext()) {
                    proceed()
                }
            }
            return plugin
        }
    }
}

After installing this plugin on the routes, we automatically get an MDC entry for each path parameter:

routing {
    install(PathParameterMDCPlugin)
...
}

MDC: [ itemId=123 ] INFO  - Processing request for item
MDC: [ itemId=123 ] INFO  - 200 OK: GET - /items/123 in 407ms
MDC: [ orderId=456, itemId=789 ] INFO  - Processing order 2
MDC: [ orderId=456, itemId=789 ] INFO  - 200 OK: GET - /orders/456/item/789 in 2ms

There is one final issue. We get itemID in the MDC for /items, but item for /orders. The fix is a one-time cleanup: unify the path parameter names. Unlike changing URLs, for example renaming …/item to …/itemID to satisfy CallLogging, renaming path parameters does not break clients. It is tedious work, but safe and done once.

With that, you now have everything needed to enrich your log messages with just a few lines of code.

The nice part is that most log aggregators, such as Graylog or Datadog, can index the MDC. If you use Datadog, you can simply query @orderID:123 to retrieve all logs for a given orderID.

Final Thoughts

I hope you found this useful. Having the MDC filled more or less automatically helped me a lot when finding the right log messages and filtering out unrelated ones while debugging a problem.

As a side note, neither Claude nor Junie came up with a robust solution for the inconsistent API path problem. Claude even struggled to create a working Ktor plugin without relying on deprecated APIs. So, Claude, if you are reading this, this is how it is done.

For transparency: I used ChatGPT to fix spelling and grammar issues.

---