Hi, i'm looking for some help on understanding som...

# ktor

[RJ Garcia]

Hi, i'm looking for some help on understanding some peculiar behavior with setting a no content response.
Here's the example app:

val accessLogger = KotlinLogging.logger("access")

fun main() {
    embeddedServer(Netty, configure = {
        connectors.add(
            EngineConnectorBuilder().apply {
                host = "127.0.0.1"
                port = 8080
            },
        )
        connectionGroupSize = 1
        workerGroupSize = 1
        callGroupSize = 1
    }) {
        install(
            createApplicationPlugin("CallLogging") {
                on(ResponseSent) { call ->
                    try {
                        val values = call.response.headers.allValues()
                        accessLogger.info { "headers: $values" }
                    } catch (e: Exception) {
                        accessLogger.atError {
                            cause = e
                            message = "allValues failed"
                        }
                    }
                }
            },
        )

        routing {
            get("/1") {
                call.respond(HttpStatusCode.NoContent)
            }
        }
    }.start(wait = true)
}

• Most of the time each request will print: headers: [Content-Length=[0]] .
• very few times, it'll print headers: []
• And very few times, it'll actually throw an exception like:

java.util.NoSuchElementException: null
	at io.netty.handler.codec.DefaultHeaders$HeaderIterator.next(DefaultHeaders.java:1291)
	at io.netty.handler.codec.DefaultHeaders$HeaderIterator.next(DefaultHeaders.java:1278)
	at io.netty.handler.codec.HeadersUtils$StringEntryIterator.next(HeadersUtils.java:123)
	at io.netty.handler.codec.HeadersUtils$StringEntryIterator.next(HeadersUtils.java:109)
	at io.ktor.server.netty.http1.NettyHttp1ApplicationResponse$headers$1.getEngineHeaderNames(NettyHttp1ApplicationResponse.kt:125)
	at io.ktor.server.response.ResponseHeaders.allValues(ResponseHeaders.kt:50)
	at com.yahoo.finance.ypf.gateway.ApplicationKt.main$lambda$4$lambda$2$lambda$1(Application.kt:50)

This only seems to happen with the NoContent status code, i'm able to replicate this pretty simply with the plow tool:

plow -c 1 <http://localhost:8080/1>

Any ideas on why reading the response headers on the ResponseSent hook for NoContent responses might behave this way?

[Aleksei Tirman [JB]]

As a workaround, you can try to use another server engine. I've filed an issue to address this problem with the Netty engine.

[RJ Garcia]

Thanks for raising this! I spent some time trying to dig in and it's definitely not an obvious bug 😓 . I was able to at least confirm that this isn't a thread concurrency issue it seems, i was able to reproduce with the following netty engine settings:

connectionGroupSize = 1
workerGroupSize = 1
callGroupSize = 1

[RJ Garcia]

a bit more debugging, and it looks like it might be related to:

https://github.com/netty/netty/blob/netty-4.1.119.Final/codec-http/src/main/java/io/netty/handler/codec/http/HttpObjectEncoder.java#L302
https://github.com/netty/netty/blob/netty-4.1.119.Final/codec-http/src/main/java/io/netty/handler/codec/http/HttpResponseEncoder.java#L53

Not totally sure, but when NoContent is present, netty removes the actual headers, but it seems like somehow the same instance is being shared between this http object encoder and the ktor NettyHttp1ApplicationResponse which is wiping the headers.

From debugging, it's clear that the thread ktor is running on is different than the thread for http encoding within netty as well.

[RJ Garcia]

For my workaround, i just won't use the NoContent response type, i don't actually need it, 200 ok would be fine and this would circumvent the weirdness

[RJ Garcia]

https://github.com/ktorio/ktor/blob/main/ktor-server/ktor-server-netty/jvm/src/io/ktor/server/netty/NettyApplicationResponse.kt#L61

So it's this line that triggers the netty engine to actually write out the http response, and it doesn't look like we're awaiting it before just continuing on with handling the response pipeline.

When Looking at the netty header iterator: https://github.com/netty/netty/blob/netty-4.1.118.Final/codec/src/main/java/io/netty/handler/codec/DefaultHeaders.java#L1278, it's clear that this is not a thread safe data structure.

I'm wondering if we're dealing with a race condition where:

1. Most of the time, the ktor response pipeline finishes before the netty thread responsible for encoding/sanitizing the http response and writing the output finishes (which would mean that the headers show Content-Length: 0 in the ktor on response log)
2. a few times, netty finishes sanitizing before the ktor ResponseSent handler is called which is when you'd see empty headers in the logs
3. and a few times, we get a race condition where while we are iterating the headers in the on response hook, netty sanitizes the headers and removes one of the values causing the iteration to get screwed up and we receive that no such element found exception

[Aleksei Tirman [JB]]

Thank you for the investigation.