ktor-client-logging has problems handling large response content

[Syrou]

Ktor Version

1.0.1

Ktor Engine Used(client or server and name)

Client

JVM Version, Operating System and Relevant Context

Android

Feedback

Doing a request, if the request creates an error (Code 500) at the backend and the backend response is a large (9000+ character) error content, I would like to be able to see this in the log but currently this does not seem to be supported because no content what so ever is printed out.

Currently it will get stuck at:

INFO io.ktor.client.HttpClient - BODY Content-Type: application/json; charset=utf-8
INFO io.ktor.client.HttpClient - BODY START

[Syrou]

Follow up: I tried to run the response content directly with println in kotlin, and it does print it.
So the limitation does not seem to be println it self. So kind of clueless as to why the json response is not printed

[jonasbark]

That was something that was fixed with version 1.1.0 (1.1.1 is the newest version). Can you try that?

Unfortunately the new version has the downside that it uses several println for the same request / response. If you have multiple concurrent requests it will be harder to read without grouping.

[Syrou]

Updated ktor client to 1.1.1 and it now get this instead: W/System.err: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".

This with using:

commonMain:
implementation "io.ktor:ktor-client-logging:1.1.1"
jvmMain:
implementation "io.ktor:ktor-client-logging-jvm:1.1.1"

[Syrou]

Added:

implementation "org.slf4j:slf4j-simple:1.6.1"

to the dependency which solved the above issue.
Now I'm still stuck at:

NFO io.ktor.client.HttpClient - BODY Content-Type: application/json; charset=utf-8
INFO io.ktor.client.HttpClient - BODY START

But i'm not sure if this is an error on my side while implementing ktor or not, i've made a wrapper around ktor-client which ends up a builder looking like this(this is commonMain code):

        protected suspend inline fun <reified T> buildInner(): T =
                coroutineScope {
                    var deferred: Deferred<T> = GlobalScope.async {

                        val httpClient = HttpClient(mBlockHttpClientConfig)
                        return@async httpClient.request<T> {

                            method = mHttpMethod
                            url {
                                takeFrom(restUrl)
                                encodedPath = mPath
                            }
                            mContentType?.let {
                                accept(it)
                            }

                            mParameters.takeIf { it.size > 0 } ?: let {
                                mParameters.forEach { param ->
                                    parameter(param.first, param.second)
                                }
                            }
                            body = mBody
                        }
                    }
                    return@coroutineScope deferred.await()
                }

        inline fun <reified T> build(): RestResult<T> {
            var restResult: RestResult<T> = RestResult()
            GlobalScope.launch {
                try {
                    restResult.broadcastSuccess(buildInner())
                } catch (e: Exception) {
                    restResult.broadcastFailure(e)
                }
            }
            return restResult
        }

[Syrou]

Ran a debugger and it does reach

    private suspend fun logResponseBody(contentType: ContentType?, content: ByteReadChannel) {
        with(logger) {
            log("BODY Content-Type: $contentType")
            log("BODY START")
            val message = content.readText(contentType?.charset() ?: Charsets.UTF_8)
            log(message)
            log("BODY END")
        }
    }

in Logging.kt, but it never gets out of:

val message = content.readText(contentType?.charset() ?: Charsets.UTF_8)

And somehow never enters:

private suspend inline fun ByteReadChannel.readText(charset: Charset): String {
    val packet = readRemaining(Long.MAX_VALUE, 0)
    return packet.readText(charset = charset)
}

[Syrou]

Sorry for the spam. I managed to fix this in the end by implementing a platform specific wrapper around runBlocking called runOnceDone:

      inline fun <reified T> buildAsync(): RestResult<T> {
            val restResult: RestResult<T> = RestResult()
            GlobalScope.launch {
                runOnceDone {
                    try {
                        val makeRequestAsync: Deferred<T> = makeRequest()
                        val requestResult: T = makeRequestAsync.await()
                        restResult.broadcastSuccess(requestResult)
                    } catch (e: Exception) {
                        restResult.broadcastFailure(e)
                    }
                }
            }
            return restResult
        }

runOnceDone is just:

expect fun runOnceDone(block: suspend () -> Unit)

And then platform implementation:
actual fun runOnceDone(block: suspend () -> Unit) = runBlocking { block() }

This does not totally make sense to me, but i figure the issue is that the coroutine never understands when the thread work is done otherwise.

[nasahapps]

@Syrou what was the reason you closed this issue? This problem was never fixed on neither the ktor side or the kotlinx-io side of things, and your workaround is very vague as it almost entirely relies on your RestResult implementation.

[Syrou]

@nasahapps I ended up recreating this issue under https://github.com/ktorio/ktor/issues/1042

I was able to find why the error happened in the first place and it was because of the data making the request was faulty. But I noticed that the large response content was still an issue later so hopefully its fixed soon