From fcdedb00b3e3960717cc5eeab953aa6ec7a9d2dd Mon Sep 17 00:00:00 2001 From: "Aleksei.Tirman" Date: Tue, 17 Dec 2024 17:07:50 +0200 Subject: [PATCH] Logging for the HEADERS level --- .../io/ktor/client/plugins/logging/Logging.kt | 106 +++++++++++++----- .../client/plugins/logging/NewFormatTest.kt | 106 ++++++++++++++++++ 2 files changed, 181 insertions(+), 31 deletions(-) diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/common/src/io/ktor/client/plugins/logging/Logging.kt b/ktor-client/ktor-client-plugins/ktor-client-logging/common/src/io/ktor/client/plugins/logging/Logging.kt index 33e6b9c4f2..21d34692df 100644 --- a/ktor-client/ktor-client-plugins/ktor-client-logging/common/src/io/ktor/client/plugins/logging/Logging.kt +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/common/src/io/ktor/client/plugins/logging/Logging.kt @@ -10,6 +10,7 @@ import io.ktor.client.plugins.api.* import io.ktor.client.plugins.observer.* import io.ktor.client.request.* import io.ktor.client.statement.* +import io.ktor.client.utils.EmptyContent import io.ktor.http.* import io.ktor.http.content.* import io.ktor.util.* @@ -173,19 +174,53 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", if (stdFormat) { val uri = URLBuilder().takeFrom(request.url).build().pathQuery() + if (request.method == HttpMethod.Get) { logger.log("--> ${request.method.value} $uri") } else { val headers = HeadersBuilder().apply { appendAll(request.headers) }.build() val (size, content) = calcRequestBodySize(request.body, headers) - logger.log("--> ${request.method.value} $uri ($size-byte body)") + val body = request.body + var contentLength = headers[HttpHeaders.ContentLength]?.toLongOrNull() + if (contentLength == null && request.method != HttpMethod.Get && body is OutgoingContent && body.contentLength != null) { + contentLength = body.contentLength + } + + if (level.headers && contentLength != null) { + logger.log("--> ${request.method.value} $uri") + } else { + logger.log("--> ${request.method.value} $uri ($size-byte body)") + } if (request.body != content) { proceedWith(content) } } + if (level.headers) { + val headers = HeadersBuilder().apply { + val body = request.body + if (body is OutgoingContent && request.method != HttpMethod.Get && body !is EmptyContent) { + body.contentType?.let { + appendIfNameAbsent(HttpHeaders.ContentType, it.toString()) + } + body.contentLength?.let { + appendIfNameAbsent(HttpHeaders.ContentLength, it.toString()) + } + } + appendAll(request.headers) + }.build() + + for ((name, values) in headers.entries()) { + logger.log("$name: ${values.joinToString(separator = ", ")}") + } + + logger.log("--> END ${request.method.value}") + + return@on + } + return@on } @@ -207,34 +242,47 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", on(ResponseAfterEncodingHook) { response -> if (!stdFormat) return@on - val (size, channel) = calcResponseBodySize(response, response.headers) - - if (channel != response.rawContent) { - proceedWith(object : HttpResponse() { - override val call: HttpClientCall - get() = response.call - override val status: HttpStatusCode - get() = response.status - override val version: HttpProtocolVersion - get() = response.version - override val requestTime: GMTDate - get() = response.requestTime - override val responseTime: GMTDate - get() = response.responseTime - - @InternalAPI - override val rawContent: ByteReadChannel - get() = channel - override val headers: Headers - get() = response.headers - override val coroutineContext: CoroutineContext - get() = response.coroutineContext - }) - } - + var contentLength = response.headers[HttpHeaders.ContentLength]?.toLongOrNull() val request = response.request val duration = response.responseTime.timestamp - response.requestTime.timestamp - logger.log("<-- ${response.status} ${request.url.pathQuery()} ${response.version} (${duration}ms, $size-byte body)") + + if (level.headers && contentLength != null) { + logger.log("<-- ${response.status} ${request.url.pathQuery()} ${response.version} (${duration}ms)") + } else { + val (size, channel) = calcResponseBodySize(response, response.headers) + logger.log("<-- ${response.status} ${request.url.pathQuery()} ${response.version} (${duration}ms, $size-byte body)") + + if (channel != response.rawContent) { + proceedWith(object : HttpResponse() { + override val call: HttpClientCall + get() = response.call + override val status: HttpStatusCode + get() = response.status + override val version: HttpProtocolVersion + get() = response.version + override val requestTime: GMTDate + get() = response.requestTime + override val responseTime: GMTDate + get() = response.responseTime + + @InternalAPI + override val rawContent: ByteReadChannel + get() = channel + override val headers: Headers + get() = response.headers + override val coroutineContext: CoroutineContext + get() = response.coroutineContext + }) + } + } + + if (level.headers) { + for ((name, values) in response.headers.entries()) { + logger.log("$name: ${values.joinToString(separator = ", ")}") + } + + logger.log("<-- END HTTP") + } } on(ResponseHook) { response -> @@ -325,10 +373,6 @@ private suspend fun calcRequestBodySize(content: Any, headers: Headers): Pair Pair(content.bytes().size.toLong(), content) is OutgoingContent.ContentWrapper -> calcRequestBodySize(content.delegate(), content.headers) diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/NewFormatTest.kt b/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/NewFormatTest.kt index c72e6443de..752caf4ec2 100644 --- a/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/NewFormatTest.kt +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/NewFormatTest.kt @@ -9,10 +9,12 @@ import io.ktor.client.engine.mock.* import io.ktor.client.plugins.compression.ContentEncoding import io.ktor.client.request.* import io.ktor.client.statement.bodyAsText +import io.ktor.http.ContentType import io.ktor.http.Headers import io.ktor.http.HttpHeaders import io.ktor.http.HttpStatusCode import io.ktor.http.content.OutgoingContent +import io.ktor.http.content.TextContent import io.ktor.util.GZipEncoder import io.ktor.utils.io.ByteReadChannel import io.ktor.utils.io.ByteWriteChannel @@ -237,6 +239,110 @@ class NewFormatTest { } } + @Test + fun headersGet() = testWithLevel(LogLevel.HEADERS, handle = { respondOk() }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / HTTP/1.1 \(\d+ms, 0-byte body\)""")) + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersPost() = testWithLevel(LogLevel.HEADERS, handle = { respondOk() }) { client -> + client.post("/post") { + setBody(TextContent(text = "hello", contentType = ContentType.Text.Plain)) + } + + log.assertLogEqual("--> POST /post") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("Content-Length: 5") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK /post HTTP/1.1 \(\d+ms, 0-byte body\)""")) + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun customHeaders() = testWithLevel(LogLevel.HEADERS, handle = { + respond("hello", headers = Headers.build { + append("Custom-Response", "value") + }) + }) { client -> + client.get("/") { + setBody(TextContent(text = "hello", contentType = ContentType.Text.Plain)) + header("Custom-Request", "value") + } + + log.assertLogEqual("--> GET /") + .assertLogEqual("Custom-Request: value") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / HTTP/1.1 \(\d+ms, 5-byte body\)""")) + .assertLogEqual("Custom-Response: value") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun noBodiesSizesWhenHasContentLengths() = testWithLevel(LogLevel.HEADERS, handle = { + respond("bye", headers = Headers.build { + append("Content-Length", "3") + }) + }) { client -> + client.post("/") { + setBody(TextContent(text = "hello", contentType = ContentType.Text.Plain)) + } + + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("Content-Length: 5") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK / HTTP/1.1 \(\d+ms\)""")) + .assertLogEqual("Content-Length: 3") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersPostWithGzip() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.HEADERS + logger = log + standardFormat = true + } + install(ContentEncoding) { gzip() } + + engine { + addHandler { + val channel = GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + respond(channel, headers = Headers.build { append(HttpHeaders.ContentEncoding, "gzip") }) + } + } + }.use { client -> + client.post("/") + + log.assertLogEqual("--> POST /") + .assertLogEqual("Accept-Encoding: gzip") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK / HTTP/1.1 \(\d+ms, 1024-byte body\)""")) + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + } + private fun testWithLevel(lvl: LogLevel, handle: MockRequestHandler, test: suspend (HttpClient) -> Unit) = runTest { HttpClient(MockEngine) { install(Logging) {