logbook-ktor-server removes Content-Type header from response

[grassehh]

When using logbook-ktor-server with Ktor Content Negotation server plugin, the Content-Type header is not returned in the response.

Description

Content Negotation feature for Ktor server automatically detects the Content-Type based on the data returned.
For instance, configuring it with Jackon as a deserializer allows Ktor server to add the Content-Type: application/json header in the response.
However, also installing logbook-ktor-server result in the header being removed in the response.

Expected Behavior

The Content-Type: application/json header should be returned in the response

Actual Behavior

The Content-Type header is missing in the response

Steps to Reproduce

1. Create a simple Ktor server app with these features installed:

install(ContentNegotiation) {
        jackson()
}
install(LogbookServer) {
        logbook = defaultLogbook
}

2. Add a route that returns some JSON object

data class SomeData(val someProp: String)
route("/test") {
     get {
       call.respond(SomeData("someValue")) 
     }
}

4. Run the server then call the retour

$curl http://localhost:8080/test

Context

I had some integration tests assertions with RestAssured that failed after adding logbook-ktor-server because the Content-Type header was no longer returned, thus RestAssured is no longer able to parse the response.

Your Environment

ktor 2.3.3
logbook 3.4.0

I haven't had time to make a sample yet sorry.

[msdousti]

TLDR: The issue is more general than using the ContentNegotiation plugin. It has to do with requests that don't have a body.

While running the server with a GET endpoint, and sending a GET request, I see this in the logs:

java.lang.IllegalStateException: No instance for key AttributeKey: Logbook.ResponseProcessingStage

The issue is in a map lookup here (where responseProcessingStageKey = AttributeKey("Logbook.ResponseProcessingStage")):

logbook/logbook-ktor-server/src/main/kotlin/org/zalando/logbook/server/LogbookServer.kt

Line 58 in 60314c2

val responseProcessingStage = call.attributes[responseProcessingStageKey]

The map was supposed to be filled by the proper value here:

logbook/logbook-ktor-server/src/main/kotlin/org/zalando/logbook/server/LogbookServer.kt

Line 53 in 60314c2

call.attributes.put(responseProcessingStageKey, responseProcessingStage)

The above line is executed when intercepting the Receive Pipeline during the ApplicationReceivePipeline.Before phase:

logbook/logbook-ktor-server/src/main/kotlin/org/zalando/logbook/server/LogbookServer.kt

Line 40 in 60314c2

pipeline.receivePipeline.intercept(ApplicationReceivePipeline.Before) {

As per Ktor docs for ApplicationReceivePipeline:

A pipeline for processing incoming content. When executed, this pipeline starts with an instance of ByteReadChannel.

Using a debugger, I noted that this phase is only executed when the request has some content (body). The unit tests also set up the server with POST endpoints:

logbook/logbook-ktor-server/src/test/kotlin/org/zalando/logbook/server/LogbookServerTest.kt

Lines 62 to 76 in 60314c2

	private val server = embeddedServer(CIO, port = port) {
	install(LogbookServer) {
	logbook = testLogbook
	}
	routing {
	post("/echo") {
	call.response.headers.append("Content-Type", "Text/Plain", false)
	call.respondText(call.receiveText())
	}
	post("/discard") {
	call.receiveText()
	call.respond(HttpStatusCode.OK)
	}
	}
	}

---

@grassehh Based on the above explanation, do you know how to fix the issue?

[msdousti]

PS: The receive pipeline can be manually triggered by something like this (here, I added call.receiveText() to your code):

data class SomeData(val someProp: String)
route("/test") {
     get {
       call.receiveText()
       call.respond(SomeData("someValue")) 
     }
}

[adarshjhaa100]

Would like to diagnose and fix this issue if its up for grabs

[msdousti]

Would like to diagnose and fix this issue if its up for grabs

@adarshjhaa100 Thanks a lot, true open source spirit!
Any help is appreciated. I did a very preliminary diagnosis in the two comments above yours. For the rest, I'll count on your expertise buddy 💯

[grassehh]

PS: The receive pipeline can be manually triggered by something like this (here, I added call.receiveText() to your code):

data class SomeData(val someProp: String)
route("/test") {
     get {
       call.receiveText()
       call.respond(SomeData("someValue")) 
     }
}

Thanks for the analysis. Indeed we also did notice this issue for GET routes on our project. The workaround as you mentionned is to manually trigger the pipeline by calling one of the call.receive() methods.
However I did not mention that in this issue as we thought this is not related.
Unfortunatly, I don't have enough Ktor expertise (and especially about its pipeline mecanism) in order to find the fix yet.

[grassehh]

Hello, @ChristianLohmann @msdousti, is there any update about the No instance for key AttributeKey: Logbook.ResponseProcessingStage issue ?

[grassehh]

Hello, I just noticed the same issue is true for logbook-ktor-client.
As soon as I as a logback.xml file in my classpath, the Content-Type gets removed.
This also means that using filters like JacksonJsonFieldBodyFilter do not work as they primarily check if there is an Content-Type: application/json header.

EDIT: @ChristianLohmann @sokomishalov shouldn't this line return it instead of ByteArrayContent(content) ? I have tried it and it seems to fix the Content-Type header being lost because Ktor actually carries the Content-Type in the OutgoingContent instance instead of actual context headers (Ktor removes the header, probably to avoid having it twice? I don't know).

I have also slightly modified the ClientRequest.getHeaders() and ClientRequest.getContentType() methods like that (it is in Kotlin sorry but I think you can get the idea):

 override fun getHeaders(): HttpHeaders = HttpHeaders.of(request.headers.build().toMap())
        .also {
            if (it.contains(ContentType).not() && request.body is OutgoingContent) return it.update(
                ContentType,
                (request.body as OutgoingContent).contentType.toString()
            )
        }

    override fun getContentType(): String? =
        request.contentType()?.toString()?.substringBefore(";") ?: (request.body as? OutgoingContent)?.contentType?.toString()

This way, features like the JacksonJsonFieldBodyFilter work again, and it also logs the Content-Type header correctly in the request. I don't know about the ClientResponse though.

[msdousti]

@grassehh: I opened a PR that hopefully addresses the issue with the logbook-ktor-server module; please take a look.

For the issue you reported with the logbook-ktor-client, I prefer to have a separate PR, to keep each PR easier to review. I suggest opening a separate issue for that.

[grassehh]

Thanks @msdousti. I have added some comments.
As for the logbook-ktor-client I have created the issue with a possible fix: #1821

I have detected another issue when sending/receiving requests with large bodies, which leads to some kind of dead locks. I will create it later once I have the unit test.