Cannot log status code with MDC

[windoze]

Code snippet:

fun Application.module() {
    install(CallLogging) {
        mdc("status_code") {
            it.response.status()?.toString()
        }
    }
    routing {
        get("/") {
            call.respondText("OK", contentType = ContentType.Text.Plain)
        }
    }
}

The MDC value of "status_code" is always null.

The reason is CallLogging feature evaluates all MDC values before the call gets processed. In CallLogging.kt:

            if (feature.mdcEntries.isNotEmpty()) {
                pipeline.intercept(loggingPhase) {
                    val mdc = feature.setupMdc(call)
                    withContext(MDCSurvivalElement(mdc)) {
                        try {
                            proceed()
                            feature.logSuccess(call)
                        } finally {
                            feature.cleanupMdc()
                        }
                    }
                }
            }

Simply calling feature.setupMdc(call) after proceed() again got the issue fixed, but I'm not sure it's the correct way.

[cy6erGn0m]

Unfortunately it is not going to work properly as we should fill all MDC values before processing to pass them through all coroutines. The second reason is that we don't know how many times and when we should evaluate lambdas. Adding it after proceed() is too ad-hoc.

[cy6erGn0m]

The other question is what for? Why do you need to add status code to MDC? CallLogging feature logs all status codes at trace log level. I simply don't see any reasons to print status code with every log message

[windoze]

Hi, @cy6erGn0m, I'was trying to make Ktor work with Logstash, which supports log in JSON format, so user can add additional key/values along with normal log messages. I checked out the CallLogging code but didn't find any appropriate places to add K/V except MDC, hence the question. If this is going nowhere, maybe a new LogstashCallLogging feature from scratch is needed, looks like some minor modification though.

[cy6erGn0m]

Why it should be MDC? Can't logstash parse regular log messages?

[windoze]

It's not about MDC actually, what I wanted is to log in JSON format and add some customized properties, with Fluentd/Elasticsearch I can dig into logs easily. Logback has a Logstash encoder (net.logstash.logback:logstash-logback-encoder), which can output logs in JSON format and add properties via log.info("message", kv(someKey, someValue)), but I cannot find anywhere to customize format and content with CallLogging. The encoder also supports MDC, which looks like an alternative but turned out it didn't work as I expected.

Given the situation, I guess I should write another CallLogging feature from scratch.

[AndreasVolkmann]

@windoze what about using format?

install(CallLogging) {
    format { "status: ${it.response.status()}" }
}

[windoze]

@AndreasVolkmann no it doesn't work, what I was trying to do is to log in JSON format with additional customizable properties/values, but seems Ktor's CallLogging cannot do.

[lopcode]

I came across this issue whilst debugging why status codes weren't getting added to our Datadog traces. Using MDC tags with explicit values makes log analysis less flaky. They also support a set of common tags for HTTP properties, documented here: https://docs.datadoghq.com/logs/processing/attributes_naming_convention/#common-attributes

[lopcode]

Had a bit of time to look at this. In the end, I've copied the CallLogging feature and added a postEvaluated option to MDC entries. "Post evaluated" entries are set to null to begin with so their lifecycle and cleanup is still handled "for free". Then, the entry is reevaluated after the proceed() call.

mdc("http.status_code", postEvaluated = true) {
    it.response.status()?.value?.toString()
}

Not the prettiest, but works great and hopefully a useful hint to anyone needing this feature.

[impatient]

@CarrotCodes is that code in a place you could share. I know one of our teams has run into that issue for tracking request timings with status.

Would it be worth a PR?

[lopcode]

Thanks for reminding me about this @impatient. I've submitted a pull request for further discussion: https://github.com/ktorio/ktor/pull/1957

[oleg-larshin]

Please check the following ticket on YouTrack for follow-ups to this issue. GitHub issues will be closed in the coming weeks.