https://kotlinlang.org logo
#ktor
Title
# ktor
a

Anders Sveen

06/09/2022, 10:41 AM
I am trying to upgrade our code to ktor-client 2.0.2, but getting into a weird situation. ContentNegotiation works and sends JSON (setBody(someMap)) on a POST, but the server rejects it (works fine in previous version 1.x). I have turned on full logging, and the only difference I can see is that in the new version the Content-Length header is not set... Any idea why? I think this migt be the issue, but can't really find a way to "trigger" or set it...
a

Aleksei Tirman [JB]

06/09/2022, 10:45 AM
Could you please share a full HTTP request and code snippet to reproduce your issue?
a

Anders Sveen

06/09/2022, 10:45 AM
Here is the client config:
Copy code
HttpClient(OkHttp) {
    install(Logging) {
        level = LogLevel.ALL
    }
    install(ContentNegotiation) {
        jackson()
    }
    install(HttpTimeout) { // set long timeout to avoid timeouts when getting account entries
        requestTimeoutMillis = 60000
    }
    expectSuccess = false
}
Request:
Copy code
post("${apiHostName}/api/consents") {
    header("Authorization", "Bearer ${accessToken.accessToken}")
    header("Content-Type", "application/json")
    header("Idempotency-Key", UUID.randomUUID())
    setBody(json)
}
(json above is a normal map)
(one level string to string)
Output from logging:
Copy code
2022-06-09 11:08:41.418 [Test worker @coroutine#34] [] INFO  io.ktor.client.HttpClient - REQUEST: <https://api.test.com/api/consents>
METHOD: HttpMethod(value=POST)
COMMON HEADERS
-> Accept: application/json
-> Accept-Charset: UTF-8
-> Authorization: Bearer XXX
-> Idempotency-Key: 777eadc5-c8da-47bd-98aa-de7a9a1cb99e
-> PSU-IP-Address: 188.95.241.148
CONTENT HEADERS
-> Content-Type: application/json
2022-06-09 11:08:41.448 [DefaultDispatcher-worker-2 @coroutine#46] [] INFO  io.ktor.client.HttpClient - BODY Content-Type: application/json
BODY START
{"account":"TX99998","callbackUrl":"<https://something>"}
BODY END
2022-06-09 11:08:41.642 [DefaultDispatcher-worker-2 @ktor-okhttp-context#52] [] INFO  io.ktor.client.HttpClient - RESPONSE: 400 
METHOD: HttpMethod(value=POST)
FROM: <https://api.test.com/api/consents>
COMMON HEADERS
-> cache-control: no-store, no-cache, must-revalidate, proxy-revalidate
-> content-length: 0
-> content-security-policy: default-src 'self'
-> date: Thu, 09 Jun 2022 09:08:41 GMT
-> expires: 0
-> pragma: no-cache
-> server: istio-envoy
-> strict-transport-security: max-age=5184000; includeSubDomains; preload
-> surrogate-control: no-store
-> x-content-security-policy: default-src 'self'
-> x-content-type-options: nosniff
-> x-envoy-upstream-service-time: 116
-> x-frame-options: DENY
-> x-webkit-csp: default-src 'self'
-> x-xss-protection: 1; mode=block
BODY Content-Type: null
BODY START

BODY END
a

Aleksei Tirman [JB]

06/09/2022, 10:54 AM
The
Content-Length
header is omitted because the
Transfer-Encoding
is
chunked
https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Transfer-Encoding#chunked
a

Anders Sveen

06/09/2022, 10:55 AM
Is that supposed to be a header? Cause it doesn't seem like it in the actual log....
a

Aleksei Tirman [JB]

06/09/2022, 10:55 AM
I observe the following headers in a request:
Copy code
POST /post HTTP/1.1
Authorization: Bearer token
Idempotency-Key: 320e4bb4-9c73-4d36-8ad1-722ffd3f8203
Accept: application/json
Accept-Charset: UTF-8
User-Agent: Ktor client
Content-Type: application/json
Transfer-Encoding: chunked
Host: <http://httpbin.org|httpbin.org>
Connection: Keep-Alive
Accept-Encoding: gzip
a

Anders Sveen

06/09/2022, 10:56 AM
Hjm... And you get that with the config I set above? So with OkHttp?
a

Aleksei Tirman [JB]

06/09/2022, 10:56 AM
Those are raw request headers from WireShark
Hjm... And you get that with the config I set above? So with OkHttp?
Yes
Copy code
val client = HttpClient(OkHttp) {
    install(Logging) {
        level = LogLevel.ALL
    }
    install(ContentNegotiation) {
        jackson()
    }
    install(HttpTimeout) { // set long timeout to avoid timeouts when getting account entries
        requestTimeoutMillis = 60000
    }
    expectSuccess = false
}

val r = <http://client.post|client.post>("<http://httpbin.org/post>") {
    header("Authorization", "Bearer token")
    header("Content-Type", "application/json")
    header("Idempotency-Key", UUID.randomUUID())
    setBody(mapOf("foo" to "bar"))
}.bodyAsText()

println(r)
a

Anders Sveen

06/09/2022, 10:58 AM
That's weird... It should show up in the log-output I pasted above though? Does it show in your local log output, or just on the receiving end?
a

Aleksei Tirman [JB]

06/09/2022, 10:58 AM
I think some headers are added by an engine so they aren’t present in the log.
a

Anders Sveen

06/09/2022, 11:12 AM
Ah, right. You are right. Some things are not logged in 2.0.2 even though they are sent. So comparing them on webhook.site I see they are identical except for: the new version adds transfer-encoding: chunked . But it also keeps the content-length: 174 header. Could that be an issue? Aren't they mutually exclusive?
a

Aleksei Tirman [JB]

06/09/2022, 11:13 AM
How to reproduce it? I don’t see the
Content-Length
header in my request.
a

Anders Sveen

06/09/2022, 11:24 AM
I have no clue 🙂 Here you can see two requests captured. The oldest one is from 1.6.x and the last one is from 2.0.2: https://webhook.site/#!/f0e752f8-f69c-481f-8ff6-614daa8848c1/f69d5579-e07d-4beb-b3c0-79d560c5e7b7/1
r

rocketraman

06/09/2022, 1:15 PM
@Anders Sveen I was curious about the webhook.site tool so I was playing around and I think I may have deleted one of your requests... sorry.
a

Anders Sveen

06/09/2022, 1:16 PM
No worries. Seems the extra header shouldn't matter either.
a

Aleksei Tirman [JB]

06/09/2022, 3:42 PM
Do you have a control over the server?
a

Anders Sveen

06/09/2022, 4:09 PM
Yeah. Did some tests with curl, and it seems Istio might be reacting to the chunked header. If I leave it out with the same curl request it goes through. Probably because the body isn't correctly chunked? It's just the JSON, but a chunk should be prefixed with it's length? At least according to this. https://en.m.wikipedia.org/wiki/Chunked_transfer_encoding
a

Aleksei Tirman [JB]

06/09/2022, 4:10 PM
Yes. It’s prefixed in my request.
a

Anders Sveen

06/09/2022, 4:13 PM
That's really weird. Might be webhook.site interprets too much. Will have to look at a lower level tomorrow. Thanks for helping so far.
a

Aleksei Tirman [JB]

06/09/2022, 4:13 PM
I suggest using WireShark or any other protocol analyzer.
a

Anders Sveen

06/13/2022, 1:24 PM
Long story short, it seems the new version of Ktor client chooses chunked transfer where the previous one would not. For some weird reason this triggers parts of our infrastructure (unknown, Istio probably, pretty sure chunked works elsewhere). I got the new version to send "un-chunked" by doing:
Copy code
setBody(ByteArrayContent(jsonString.toByteArray(), ContentType.Application.Json, HttpStatusCode.OK))
A bit worrying, but only an issue in our test code. So won't dig further for now. Thanks for helping. 🙂
65 Views