diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.api b/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.api index 6f2df7f25fc..cbfee3010e9 100644 --- a/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.api +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.api @@ -37,14 +37,24 @@ public final class io/ktor/client/plugins/logging/LoggerKt { public final class io/ktor/client/plugins/logging/LoggingConfig { public fun ()V public final fun filter (Lkotlin/jvm/functions/Function1;)V + public final fun getFormat ()Lio/ktor/client/plugins/logging/LoggingFormat; public final fun getLevel ()Lio/ktor/client/plugins/logging/LogLevel; public final fun getLogger ()Lio/ktor/client/plugins/logging/Logger; public final fun sanitizeHeader (Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V public static synthetic fun sanitizeHeader$default (Lio/ktor/client/plugins/logging/LoggingConfig;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V + public final fun setFormat (Lio/ktor/client/plugins/logging/LoggingFormat;)V public final fun setLevel (Lio/ktor/client/plugins/logging/LogLevel;)V public final fun setLogger (Lio/ktor/client/plugins/logging/Logger;)V } +public final class io/ktor/client/plugins/logging/LoggingFormat : java/lang/Enum { + public static final field Default Lio/ktor/client/plugins/logging/LoggingFormat; + public static final field OkHttp Lio/ktor/client/plugins/logging/LoggingFormat; + public static fun getEntries ()Lkotlin/enums/EnumEntries; + public static fun valueOf (Ljava/lang/String;)Lio/ktor/client/plugins/logging/LoggingFormat; + public static fun values ()[Lio/ktor/client/plugins/logging/LoggingFormat; +} + public final class io/ktor/client/plugins/logging/LoggingKt { public static final fun Logging (Lio/ktor/client/HttpClientConfig;Lkotlin/jvm/functions/Function1;)V public static synthetic fun Logging$default (Lio/ktor/client/HttpClientConfig;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.klib.api b/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.klib.api index ebccae08f07..db623464b74 100644 --- a/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.klib.api +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/api/ktor-client-logging.klib.api @@ -26,6 +26,17 @@ final enum class io.ktor.client.plugins.logging/LogLevel : kotlin/Enum // io.ktor.client.plugins.logging/LogLevel.values|values#static(){}[0] } +final enum class io.ktor.client.plugins.logging/LoggingFormat : kotlin/Enum { // io.ktor.client.plugins.logging/LoggingFormat|null[0] + enum entry Default // io.ktor.client.plugins.logging/LoggingFormat.Default|null[0] + enum entry OkHttp // io.ktor.client.plugins.logging/LoggingFormat.OkHttp|null[0] + + final val entries // io.ktor.client.plugins.logging/LoggingFormat.entries|#static{}entries[0] + final fun (): kotlin.enums/EnumEntries // io.ktor.client.plugins.logging/LoggingFormat.entries.|#static(){}[0] + + final fun valueOf(kotlin/String): io.ktor.client.plugins.logging/LoggingFormat // io.ktor.client.plugins.logging/LoggingFormat.valueOf|valueOf#static(kotlin.String){}[0] + final fun values(): kotlin/Array // io.ktor.client.plugins.logging/LoggingFormat.values|values#static(){}[0] +} + abstract interface io.ktor.client.plugins.logging/Logger { // io.ktor.client.plugins.logging/Logger|null[0] abstract fun log(kotlin/String) // io.ktor.client.plugins.logging/Logger.log|log(kotlin.String){}[0] @@ -35,6 +46,9 @@ abstract interface io.ktor.client.plugins.logging/Logger { // io.ktor.client.plu final class io.ktor.client.plugins.logging/LoggingConfig { // io.ktor.client.plugins.logging/LoggingConfig|null[0] constructor () // io.ktor.client.plugins.logging/LoggingConfig.|(){}[0] + final var format // io.ktor.client.plugins.logging/LoggingConfig.format|{}format[0] + final fun (): io.ktor.client.plugins.logging/LoggingFormat // io.ktor.client.plugins.logging/LoggingConfig.format.|(){}[0] + final fun (io.ktor.client.plugins.logging/LoggingFormat) // io.ktor.client.plugins.logging/LoggingConfig.format.|(io.ktor.client.plugins.logging.LoggingFormat){}[0] final var level // io.ktor.client.plugins.logging/LoggingConfig.level|{}level[0] final fun (): io.ktor.client.plugins.logging/LogLevel // io.ktor.client.plugins.logging/LoggingConfig.level.|(){}[0] final fun (io.ktor.client.plugins.logging/LogLevel) // io.ktor.client.plugins.logging/LoggingConfig.level.|(io.ktor.client.plugins.logging.LogLevel){}[0] diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/build.gradle.kts b/ktor-client/ktor-client-plugins/ktor-client-logging/build.gradle.kts index edb59c9782f..e0969111f36 100644 --- a/ktor-client/ktor-client-plugins/ktor-client-logging/build.gradle.kts +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/build.gradle.kts @@ -22,6 +22,7 @@ kotlin.sourceSets { jvmTest { dependencies { api(project(":ktor-shared:ktor-serialization:ktor-serialization-jackson")) + api(project(":ktor-client:ktor-client-plugins:ktor-client-encoding")) } } } 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 2665b76d500..517a6f3386b 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 @@ -7,20 +7,39 @@ package io.ktor.client.plugins.logging import io.ktor.client.* import io.ktor.client.call.* import io.ktor.client.plugins.api.* +import io.ktor.client.plugins.isSaved import io.ktor.client.plugins.observer.* import io.ktor.client.request.* import io.ktor.client.statement.* +import io.ktor.client.utils.* import io.ktor.http.* import io.ktor.http.content.* import io.ktor.util.* import io.ktor.util.pipeline.* import io.ktor.utils.io.* import io.ktor.utils.io.charsets.* -import kotlinx.coroutines.* +import io.ktor.utils.io.core.readText +import io.ktor.utils.io.core.writeFully +import kotlinx.coroutines.DelicateCoroutinesApi +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.GlobalScope +import kotlinx.coroutines.async +import kotlinx.coroutines.launch +import kotlinx.io.Buffer private val ClientCallLogger = AttributeKey("CallLogger") private val DisableLogging = AttributeKey("DisableLogging") +public enum class LoggingFormat { + Default, + + /** + * [OkHttp logging format](https://github.com/square/okhttp/blob/parent-4.12.0/okhttp-logging-interceptor/src/main/kotlin/okhttp3/logging/HttpLoggingInterceptor.kt#L48-L105). + * Writes only application-level logs because the low-level HTTP communication is hidden within the engine implementations. + */ + OkHttp +} + /** * A configuration for the [Logging] plugin. */ @@ -31,6 +50,9 @@ public class LoggingConfig { private var _logger: Logger? = null + /** A general format for logging requests and responses. See [LoggingFormat]. */ + public var format: LoggingFormat = LoggingFormat.Default + /** * Specifies a [Logger] instance. */ @@ -69,15 +91,342 @@ public class LoggingConfig { * * You can learn more from [Logging](https://ktor.io/docs/client-logging.html). */ -@OptIn(InternalAPI::class) +@OptIn(InternalAPI::class, DelicateCoroutinesApi::class) public val Logging: ClientPlugin = createClientPlugin("Logging", ::LoggingConfig) { val logger: Logger = pluginConfig.logger val level: LogLevel = pluginConfig.level val filters: List<(HttpRequestBuilder) -> Boolean> = pluginConfig.filters val sanitizedHeaders: List = pluginConfig.sanitizedHeaders + val okHttpFormat = pluginConfig.format == LoggingFormat.OkHttp fun shouldBeLogged(request: HttpRequestBuilder): Boolean = filters.isEmpty() || filters.any { it(request) } + fun isNone(): Boolean = level == LogLevel.NONE + fun isInfo(): Boolean = level == LogLevel.INFO + fun isHeaders(): Boolean = level == LogLevel.HEADERS + fun isBody(): Boolean = level == LogLevel.BODY || level == LogLevel.ALL + + /** + * Detects if the body is a binary data + * @return + * Boolean: true if the body is a binary data. + * Long?: body size if calculated. + * ByteReadChannel: body channel with the original data. + */ + suspend fun detectIfBinary( + body: ByteReadChannel, + contentLength: Long?, + contentType: ContentType?, + headers: Headers + ): Triple { + if (headers.contains(HttpHeaders.ContentEncoding)) { + return Triple(true, contentLength, body) + } + + val charset = if (contentType != null) { + contentType.charset() ?: Charsets.UTF_8 + } else { + Charsets.UTF_8 + } + + var isBinary = false + val firstChunk = ByteArray(1024) + val firstReadSize = body.readAvailable(firstChunk) + + if (firstReadSize < 1) { + return Triple(false, 0L, body) + } + + val buffer = Buffer().apply { writeFully(firstChunk, 0, firstReadSize) } + val firstChunkText = charset.newDecoder().decode(buffer, firstReadSize) + + var lastCharIndex = -1 + for (ch in firstChunkText) { + lastCharIndex += 1 + } + + for ((i, ch) in firstChunkText.withIndex()) { + if (ch == '\ufffd' && i != lastCharIndex) { + isBinary = true + break + } + } + + if (!isBinary) { + val channel = ByteChannel() + + val copied = client.async { + channel.writeFully(firstChunk, 0, firstReadSize) + val copied = body.copyTo(channel) + channel.flushAndClose() + copied + }.await() + + return Triple(isBinary, copied + firstReadSize, channel) + } + + return Triple(isBinary, contentLength, body) + } + + suspend fun logRequestBody( + content: OutgoingContent, + contentLength: Long?, + headers: Headers, + method: HttpMethod, + body: ByteReadChannel + ) { + val (isBinary, size, newBody) = detectIfBinary(body, contentLength, content.contentType, headers) + + if (!isBinary) { + val contentType = content.contentType + val charset = if (contentType != null) { + contentType.charset() ?: Charsets.UTF_8 + } else { + Charsets.UTF_8 + } + + logger.log(newBody.readRemaining().readText(charset = charset)) + logger.log("--> END ${method.value} ($size-byte body)") + } else { + var type = "binary" + if (headers.contains(HttpHeaders.ContentEncoding)) { + type = "encoded" + } + + if (size != null) { + logger.log("--> END ${method.value} ($type $size-byte body omitted)") + } else { + logger.log("--> END ${method.value} ($type body omitted)") + } + } + } + + suspend fun logOutgoingContent( + content: OutgoingContent, + method: HttpMethod, + headers: Headers, + process: (ByteReadChannel) -> ByteReadChannel = { it } + ): OutgoingContent? { + return when (content) { + is OutgoingContent.ByteArrayContent -> { + val bytes = content.bytes() + logRequestBody(content, bytes.size.toLong(), headers, method, ByteReadChannel(bytes)) + null + } + is OutgoingContent.ContentWrapper -> { + logOutgoingContent(content.delegate(), method, headers, process) + } + is OutgoingContent.NoContent -> { + logger.log("--> END ${method.value}") + null + } + is OutgoingContent.ProtocolUpgrade -> { + logger.log("--> END ${method.value}") + null + } + is OutgoingContent.ReadChannelContent -> { + val (origChannel, newChannel) = content.readFrom().split(client) + logRequestBody(content, content.contentLength, headers, method, newChannel) + LoggedContent(content, origChannel) + } + is OutgoingContent.WriteChannelContent -> { + val channel = ByteChannel() + + client.launch { + content.writeTo(channel) + channel.close() + } + + val (origChannel, newChannel) = channel.split(client) + logRequestBody(content, content.contentLength, headers, method, newChannel) + LoggedContent(content, origChannel) + } + } + } + + suspend fun logRequestOkHttpFormat(request: HttpRequestBuilder): OutgoingContent? { + if (isNone()) return null + + val uri = URLBuilder().takeFrom(request.url).build().pathQuery() + val body = request.body + val headers = HeadersBuilder().apply { + if (body is OutgoingContent && + request.method != HttpMethod.Get && + request.method != HttpMethod.Head && + body !is EmptyContent + ) { + body.contentType?.let { + appendIfNameAbsent(HttpHeaders.ContentType, it.toString()) + } + body.contentLength?.let { + appendIfNameAbsent(HttpHeaders.ContentLength, it.toString()) + } + } + appendAll(request.headers) + }.build() + + val contentLength = headers[HttpHeaders.ContentLength]?.toLongOrNull() + val startLine = when { + (request.method == HttpMethod.Get) || + (request.method == HttpMethod.Head) || + ((isHeaders() || isBody()) && contentLength != null) || + (isHeaders() && contentLength == null) || + headers.contains(HttpHeaders.ContentEncoding) -> "--> ${request.method.value} $uri" + + isInfo() && contentLength != null -> "--> ${request.method.value} $uri ($contentLength-byte body)" + + body is OutgoingContent.WriteChannelContent || + body is OutgoingContent.ReadChannelContent -> "--> ${request.method.value} $uri (unknown-byte body)" + + else -> { + val size = computeRequestBodySize(request.body, headers) + "--> ${request.method.value} $uri ($size-byte body)" + } + } + + logger.log(startLine) + + if (!isHeaders() && !isBody()) { + return null + } + + for ((name, values) in headers.entries()) { + if (sanitizedHeaders.find { sh -> sh.predicate(name) } == null) { + logger.log("$name: ${values.joinToString(separator = ", ")}") + } else { + logger.log("$name: ██") + } + } + + if (!isBody() || request.method == HttpMethod.Get || request.method == HttpMethod.Head) { + logger.log("--> END ${request.method.value}") + return null + } + + logger.log("") + + if (body !is OutgoingContent) { + logger.log("--> END ${request.method.value}") + return null + } + + val newContent = if (request.headers[HttpHeaders.ContentEncoding] == "gzip") { + logOutgoingContent(body, request.method, headers) { channel -> + GZipEncoder.decode(channel) + } + } else { + logOutgoingContent(body, request.method, headers) + } + + return newContent + } + + suspend fun logResponseBody(response: HttpResponse, body: ByteReadChannel) { + logger.log("") + + val (isBinary, size, newBody) = detectIfBinary( + body, + response.contentLength(), + response.contentType(), + response.headers + ) + val duration = response.responseTime.timestamp - response.requestTime.timestamp + + if (size == 0L) { + logger.log("<-- END HTTP (${duration}ms, $size-byte body)") + return + } + + if (!isBinary) { + val contentType = response.contentType() + val charset = if (contentType != null) { + contentType.charset() ?: Charsets.UTF_8 + } else { + Charsets.UTF_8 + } + + logger.log(newBody.readRemaining().readText(charset = charset)) + logger.log("<-- END HTTP (${duration}ms, $size-byte body)") + } else { + var type = "binary" + if (response.headers.contains(HttpHeaders.ContentEncoding)) { + type = "encoded" + } + + if (size != null) { + logger.log("<-- END HTTP (${duration}ms, $type $size-byte body omitted)") + } else { + logger.log("<-- END HTTP (${duration}ms, $type body omitted)") + } + } + } + + suspend fun logResponseOkHttpFormat(response: HttpResponse): HttpResponse { + if (isNone()) return response + + val contentLength = response.headers[HttpHeaders.ContentLength]?.toLongOrNull() + val request = response.request + val duration = response.responseTime.timestamp - response.requestTime.timestamp + + val startLine = when { + response.headers[HttpHeaders.TransferEncoding] == "chunked" && + (isInfo() || isHeaders()) -> + "<-- ${response.status} ${request.url.pathQuery()} (${duration}ms, unknown-byte body)" + + isInfo() && contentLength != null -> + "<-- ${response.status} ${request.url.pathQuery()} (${duration}ms, $contentLength-byte body)" + + isBody() || + (isInfo() && contentLength == null) || + (isHeaders() && contentLength != null) || + (response.headers[HttpHeaders.ContentEncoding] == "gzip") -> + "<-- ${response.status} ${request.url.pathQuery()} (${duration}ms)" + + else -> "<-- ${response.status} ${request.url.pathQuery()} (${duration}ms, unknown-byte body)" + } + + logger.log(startLine) + + if (!isHeaders() && !isBody()) { + return response + } + + for ((name, values) in response.headers.entries()) { + if (sanitizedHeaders.find { sh -> sh.predicate(name) } == null) { + logger.log("$name: ${values.joinToString(separator = ", ")}") + } else { + logger.log("$name: ██") + } + } + + if (!isBody()) { + logger.log("<-- END HTTP") + return response + } + + if (contentLength != null && contentLength == 0L) { + logger.log("<-- END HTTP (${duration}ms, $contentLength-byte body)") + return response + } + + if (response.contentType() == ContentType.Text.EventStream) { + logger.log("<-- END HTTP (streaming)") + return response + } + + if (response.isSaved) { + logResponseBody(response, response.rawContent) + return response + } + + val (origChannel, newChannel) = response.rawContent.split(response) + + logResponseBody(response, newChannel) + + val call = response.call.wrapWithContent(origChannel) + return call.response + } + @OptIn(DelicateCoroutinesApi::class) suspend fun logRequestBody( content: OutgoingContent, @@ -165,6 +514,23 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", return@on } + if (okHttpFormat) { + val content = logRequestOkHttpFormat(request) + + try { + if (content != null) { + proceedWith(content) + } else { + proceed() + } + } catch (cause: Throwable) { + logger.log("<-- HTTP FAILED: $cause") + throw cause + } + + return@on + } + val loggedRequest = try { logRequest(request) } catch (_: Throwable) { @@ -180,7 +546,18 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", } } + on(ResponseAfterEncodingHook) { response -> + if (okHttpFormat) { + val newResponse = logResponseOkHttpFormat(response) + if (newResponse != response) { + proceedWith(newResponse) + } + } + } + on(ResponseHook) { response -> + if (okHttpFormat) return@on + if (level == LogLevel.NONE || response.call.attributes.contains(DisableLogging)) return@on val callLogger = response.call.attributes[ClientCallLogger] @@ -201,6 +578,8 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", } on(ReceiveHook) { call -> + if (okHttpFormat) return@on + if (level == LogLevel.NONE || call.attributes.contains(DisableLogging)) { return@on } @@ -217,6 +596,8 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", } } + if (okHttpFormat) return@createClientPlugin + if (!level.body) return@createClientPlugin @OptIn(InternalAPI::class) @@ -239,6 +620,34 @@ public val Logging: ClientPlugin = createClientPlugin("Logging", ResponseObserver.install(ResponseObserver.prepare { onResponse(observer) }, client) } +private fun Url.pathQuery(): String { + return buildString { + if (encodedPath.isEmpty()) { + append("/") + } else { + append(encodedPath) + } + + if (!encodedQuery.isEmpty()) { + append("?") + append(encodedQuery) + } + } +} + +@OptIn(DelicateCoroutinesApi::class) +private fun computeRequestBodySize(content: Any, headers: Headers): Long { + check(content is OutgoingContent) + + return when (content) { + is OutgoingContent.ByteArrayContent -> content.bytes().size.toLong() + is OutgoingContent.ContentWrapper -> computeRequestBodySize(content.delegate(), content.headers) + is OutgoingContent.NoContent -> 0 + is OutgoingContent.ProtocolUpgrade -> 0 + else -> error("Unable to calculate the size for type ${content::class.simpleName}") + } +} + /** * Configures and installs [Logging] in [HttpClient]. */ @@ -268,10 +677,30 @@ private object ResponseHook : ClientHook Unit> { + + class Context(private val context: PipelineContext) { + suspend fun proceedWith(response: HttpResponse) = context.proceedWith(response) + } + + override fun install( + client: HttpClient, + handler: suspend Context.(response: HttpResponse) -> Unit + ) { + val afterState = PipelinePhase("AfterState") + client.receivePipeline.insertPhaseAfter(HttpReceivePipeline.State, afterState) + client.receivePipeline.intercept(afterState) { + handler(Context(this), subject) + } + } +} + private object SendHook : ClientHook Unit> { class Context(private val context: PipelineContext) { suspend fun proceedWith(content: Any) = context.proceedWith(content) + suspend fun proceed() = context.proceed() } override fun install( diff --git a/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/OkHttpFormatTest.kt b/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/OkHttpFormatTest.kt new file mode 100644 index 00000000000..6d3ceb50b0a --- /dev/null +++ b/ktor-client/ktor-client-plugins/ktor-client-logging/jvm/test/io/ktor/client/plugins/logging/OkHttpFormatTest.kt @@ -0,0 +1,1289 @@ +/* + * Copyright 2014-2024 JetBrains s.r.o and contributors. Use of this source code is governed by the Apache 2.0 license. + */ + +package io.ktor.client.plugins.logging + +import io.ktor.client.* +import io.ktor.client.engine.mock.* +import io.ktor.client.plugins.HttpResponseValidator +import io.ktor.client.plugins.compression.ContentEncoding +import io.ktor.client.request.* +import io.ktor.client.statement.bodyAsBytes +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.http.contentType +import io.ktor.util.GZipEncoder +import io.ktor.utils.io.ByteReadChannel +import io.ktor.utils.io.ByteWriteChannel +import io.ktor.utils.io.readText +import io.ktor.utils.io.writeFully +import io.ktor.utils.io.writeStringUtf8 +import kotlinx.coroutines.Job +import kotlinx.coroutines.test.runTest +import kotlinx.io.readByteArray +import org.junit.jupiter.api.BeforeEach +import java.net.UnknownHostException +import kotlin.coroutines.CoroutineContext +import kotlin.test.Test +import kotlin.test.assertContentEquals +import kotlin.test.assertEquals +import kotlin.test.assertFailsWith +import kotlin.test.assertTrue + +class OkHttpFormatTest { + class LogRecorder : Logger { + private val loggedLines = mutableListOf() + private var currentLine = 0 + override fun log(message: String) { + loggedLines.add(message) + } + + fun assertLogEqual(msg: String): LogRecorder { + assertTrue(message = "No more logs to check") { currentLine < loggedLines.size } + assertEquals(msg, loggedLines[currentLine]) + currentLine++ + return this + } + + fun assertLogMatch(regex: Regex): LogRecorder { + assertTrue(message = "No more logs to check") { currentLine < loggedLines.size } + assertTrue(message = "Regex '$regex' doesn't match '${loggedLines[currentLine]}'") { + regex.matches( + loggedLines[currentLine] + ) + } + currentLine++ + return this + } + + fun assertNoMoreLogs(): LogRecorder { + assertTrue( + message = "There are ${loggedLines.size - currentLine} more logs, expected none" + ) { currentLine >= loggedLines.size } + return this + } + } + + private lateinit var log: LogRecorder + + @BeforeEach + fun setup() { + log = LogRecorder() + } + + @Test + fun noLoggingWhenLevelNone() = testWithLevel(LogLevel.NONE, handle = { respondWithLength() }) { client -> + client.get("/") + log.assertNoMoreLogs() + } + + @Test + fun basicGet() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPost() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody("hello") + } + + log.assertLogEqual("--> POST / (5-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGet404() = testWithLevel( + LogLevel.INFO, + handle = { respondWithLength("", HttpStatusCode.NotFound) } + ) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 404 Not Found / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGetNonRoot() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.get("/some/resource") + + log.assertLogEqual("--> GET /some/resource") + .assertLogMatch(Regex("""<-- 200 OK /some/resource \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGetQuery() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.get("/?a=1&b=2&c=3") + + log.assertLogEqual("--> GET /?a=1&b=2&c=3") + .assertLogMatch(Regex("""<-- 200 OK /\?a=1&b=2&c=3 \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGetNonEmptyBody() = testWithLevel(LogLevel.INFO, handle = { respondWithLength("hello") }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 5-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostNoBody() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") + + log.assertLogEqual("--> POST / (0-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostUpgradeProtocol() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(object : OutgoingContent.ProtocolUpgrade() { + override suspend fun upgrade( + input: ByteReadChannel, + output: ByteWriteChannel, + engineContext: CoroutineContext, + userContext: CoroutineContext + ): Job { + output.flushAndClose() + return Job() + } + }) + } + + log.assertLogEqual("--> POST / (0-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostReadChannel() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(object : OutgoingContent.ReadChannelContent() { + override fun readFrom() = ByteReadChannel("hello world") + }) + } + + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostReadChannelWithContentLength() = testWithLevel( + LogLevel.INFO, + handle = { respondWithLength() } + ) { client -> + client.post("/") { + setBody(object : OutgoingContent.ReadChannelContent() { + override val contentLength: Long? + get() = 11 + override fun readFrom() = ByteReadChannel("hello world") + }) + } + + log.assertLogEqual("--> POST / (11-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostConsumedRequestBody() = testWithLevel(LogLevel.INFO, handle = { + respondWithLength(it.body.toByteReadPacket().readByteArray()) + }) { client -> + val response = client.post("/") { + setBody(ByteReadChannel("hello")) + } + + assertEquals("hello", response.bodyAsText()) + + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 5-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostWriteChannel() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(object : OutgoingContent.WriteChannelContent() { + override suspend fun writeTo(channel: ByteWriteChannel) { + channel.writeStringUtf8("hello world") + } + }) + } + + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicPostWriteChannelWithContentLength() = testWithLevel( + LogLevel.INFO, + handle = { respondWithLength() } + ) { client -> + client.post("/") { + setBody(object : OutgoingContent.WriteChannelContent() { + override suspend fun writeTo(channel: ByteWriteChannel) { + channel.writeStringUtf8("hello world") + } + override val contentLength: Long? + get() = 11 + }) + } + + log.assertLogEqual("--> POST / (11-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGetWithResponseContentLength() = testWithLevel(LogLevel.INFO, handle = { + respond("", headers = Headers.build { append(HttpHeaders.ContentLength, "10") }) + }) { client -> + client.prepareGet("/").execute { response -> + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 10-byte body\)""")) + .assertNoMoreLogs() + } + } + + @Test + fun basicGzippedBody() = testWithLevel(LogLevel.INFO, handle = { + val channel = GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + respond( + channel, + headers = Headers.build { + append(HttpHeaders.ContentEncoding, "gzip") + append(HttpHeaders.ContentLength, "29") + } + ) + }) { client -> + client.prepareGet("/").execute { response -> + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 29-byte body\)""")) + .assertNoMoreLogs() + } + } + + @Test + fun basicGzippedBodyContentEncoding() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.INFO + logger = log + format = LoggingFormat.OkHttp + } + install(ContentEncoding) { gzip() } + + engine { + addHandler { + val channel = GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + respond( + channel, + headers = Headers.build { + append(HttpHeaders.ContentEncoding, "gzip") + append(HttpHeaders.ContentLength, "29") + } + ) + } + } + }.use { client -> + val response = client.get("/") + assertEquals("a".repeat(1024), response.bodyAsText()) + + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertNoMoreLogs() + } + } + + @Test + fun basicChunkedResponseBody() = testWithLevel(LogLevel.INFO, handle = { + respond( + ByteReadChannel("test"), + headers = Headers.build { + append(HttpHeaders.TransferEncoding, "chunked") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, unknown-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun headersGet() = testWithLevel(LogLevel.HEADERS, handle = { respondWithLength() }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersPost() = testWithLevel(LogLevel.HEADERS, handle = { respondWithLength() }) { 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 \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersNoLength() = testWithLevel(LogLevel.HEADERS, handle = { respondWithLength() }) { client -> + client.post("/post") { + setBody(object : OutgoingContent.WriteChannelContent() { + override suspend fun writeTo(channel: ByteWriteChannel) { + channel.writeStringUtf8("test") + } + }) + } + + log.assertLogEqual("--> POST /post") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK /post \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun customHeaders() = testWithLevel(LogLevel.HEADERS, handle = { + respondWithLength( + "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 / \(\d+ms\)""")) + .assertLogEqual("Custom-Response: value") + .assertLogEqual("Content-Length: 5") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersResponseBody() = testWithLevel(LogLevel.HEADERS, handle = { + respondWithLength("test", contentType = ContentType.Text.Html) + }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 4") + .assertLogEqual("Content-Type: text/html") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun noBodiesSizesWhenHasContentLengths() = testWithLevel(LogLevel.HEADERS, handle = { + respondWithLength("bye") + }) { 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 / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 3") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersGzippedResponseBody() = testWithLevel(LogLevel.HEADERS, handle = { + val content = "a".repeat(1024) + val channel = GZipEncoder.encode(ByteReadChannel(content)) + respond( + channel, + headers = Headers.build { + append(HttpHeaders.ContentEncoding, "gzip") + append(HttpHeaders.ContentLength, "29") + } + ) + }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Encoding: gzip") + .assertLogEqual("Content-Length: 29") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + @Test + fun headersGzippedResponseBodyContentEncoding() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.HEADERS + logger = log + format = LoggingFormat.OkHttp + } + 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 / \(\d+ms, unknown-byte body\)""")) + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + } + + @Test + fun bodyGzippedResponseBody() = testWithLevel(LogLevel.BODY, handle = { + val channel = GZipEncoder.encode(ByteReadChannel("response".repeat(1024))) + respond( + channel, + headers = Headers.build { + append(HttpHeaders.ContentEncoding, "gzip") + append(HttpHeaders.ContentLength, "55") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Encoding: gzip") + .assertLogEqual("Content-Length: 55") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, encoded 55-byte body omitted\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyResponseBodyBrEncoded() = testWithLevel(LogLevel.BODY, handle = { + respond( + byteArrayOf(0xC3.toByte(), 0x28), + headers = Headers.build { + append(HttpHeaders.ContentEncoding, "br") + append(HttpHeaders.ContentLength, "2") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Encoding: br") + .assertLogEqual("Content-Length: 2") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, encoded 2-byte body omitted\)""")) + .assertNoMoreLogs() + } + + @Test + fun detectResponseBodyAsTextualFor2ByteNonValidUTF8String() = testWithLevel(LogLevel.BODY, handle = { + respond( + byteArrayOf(0xC3.toByte(), 0x28), + headers = Headers.build { + append(HttpHeaders.ContentLength, "2") + } + ) + }) { client -> + + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 2") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, binary 2-byte body omitted\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGzippedResponseBodyContentEncoding() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.BODY + logger = log + format = LoggingFormat.OkHttp + } + install(ContentEncoding) { gzip() } + + engine { + addHandler { + val channel = GZipEncoder.encode(ByteReadChannel("response".repeat(1024))) + respond(channel, headers = Headers.build { append(HttpHeaders.ContentEncoding, "gzip") }) + } + } + }.use { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Encoding: gzip") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("") + .assertLogEqual("response".repeat(1024)) + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 8192-byte body\)""")) + .assertNoMoreLogs() + } + } + + @Test + fun bodyGet() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGet204() = testWithLevel(LogLevel.BODY, handle = { + respond( + "", + status = HttpStatusCode.NoContent, + headers = Headers.build { + append(HttpHeaders.ContentLength, "0") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 204 No Content / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGet205() = testWithLevel(LogLevel.BODY, handle = { + respond( + "", + status = HttpStatusCode.ResetContent, + headers = Headers.build { + append(HttpHeaders.ContentLength, "0") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 205 Reset Content / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPost() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody("test") + } + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Type: text/plain; charset=UTF-8") + .assertLogEqual("Content-Length: 4") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("test") + .assertLogEqual("--> END POST (4-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPostReadChannel() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(ByteReadChannel("test")) + contentType(ContentType.Text.Plain) + } + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("test") + .assertLogEqual("--> END POST (4-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPostReadChannelNotConsumed() = testWithLevel(LogLevel.BODY, handle = { + assertEquals("test", it.body.toByteReadPacket().readText()) + respondWithLength() + }) { client -> + client.post("/") { + setBody(ByteReadChannel("test")) + contentType(ContentType.Text.Plain) + } + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("test") + .assertLogEqual("--> END POST (4-byte body)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPostBinaryReadChannel() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(ByteReadChannel(byteArrayOf(0xC3.toByte(), 0x28))) + } + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogEqual("Content-Type: application/octet-stream") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (binary body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPostBinaryWriteChannel() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(object : OutgoingContent.WriteChannelContent() { + override suspend fun writeTo(channel: ByteWriteChannel) { + channel.writeFully(byteArrayOf(0xC3.toByte(), 0x28)) + channel.flushAndClose() + } + }) + } + log.assertLogEqual("--> POST / (unknown-byte body)") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (binary body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyPostBinaryArrayContent() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + setBody(object : OutgoingContent.ByteArrayContent() { + override fun bytes(): ByteArray { + return byteArrayOf(0xC3.toByte(), 0x28) + } + }) + } + log.assertLogEqual("--> POST / (2-byte body)") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (binary 2-byte body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGetWithResponseBody() = testWithLevel(LogLevel.BODY, handle = { respondWithLength("hello!") }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 6") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("") + .assertLogEqual("hello!") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 6-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyResponseBodyChunked() = testWithLevel( + LogLevel.BODY, + handle = { respondChunked(ByteReadChannel("hello!")) } + ) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Transfer-Encoding: chunked") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("") + .assertLogEqual("hello!") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 6-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyResponseIsStreaming() = testWithLevel(LogLevel.BODY, handle = { + respondChunked( + ByteReadChannel( + """ + |event: add + |data: 73857293 + | + |event: remove + |data: 2153 + | + |event: add + |data: 113411 + | + | + """.trimMargin() + ), + contentType = ContentType.Text.EventStream + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Transfer-Encoding: chunked") + .assertLogEqual("Content-Type: text/event-stream") + .assertLogEqual("<-- END HTTP (streaming)") + .assertNoMoreLogs() + } + + @Test + fun bodyGetMalformedCharset() = testWithLevel(LogLevel.BODY, handle = { + respond( + "test", + headers = Headers.build { + append(HttpHeaders.ContentType, "text/html; charset=0") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Type: text/html; charset=0") + .assertLogEqual("") + .assertLogEqual("test") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 4-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyResponseBodyIsBinary() = testWithLevel(LogLevel.BODY, handle = { + respond( + byteArrayOf((0x89).toByte(), 0x50, 0x4e, 0x47, 0x0d, 0x0a, 0x1a, 0x0a), + headers = Headers.build { + append(HttpHeaders.ContentType, "image/png; charset=utf-8") + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Type: image/png; charset=utf-8") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, binary body omitted\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyResponseBodyIsBinaryContentLength() = testWithLevel(LogLevel.BODY, handle = { + val data = byteArrayOf((0x89).toByte(), 0x50, 0x4e, 0x47, 0x0d, 0x0a, 0x1a, 0x0a) + respond( + data, + headers = Headers.build { + append(HttpHeaders.ContentType, "image/png; charset=utf-8") + append(HttpHeaders.ContentLength, data.size.toString()) + } + ) + }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Type: image/png; charset=utf-8") + .assertLogEqual("Content-Length: 8") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, binary 8-byte body omitted\)""")) + .assertNoMoreLogs() + } + + @Test + fun allResponseBody() = testWithLevel(LogLevel.ALL, handle = { respondWithLength("hello!") }) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 6") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("") + .assertLogEqual("hello!") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 6-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun connectFailed() = testWithLevel(LogLevel.INFO, handle = { respondOk() }) { client -> + client.sendPipeline.intercept(HttpSendPipeline.Engine) { + throw UnknownHostException("reason") + } + + assertFailsWith { + client.get("/") + } + + log.assertLogEqual("--> GET /") + .assertLogEqual("<-- HTTP FAILED: java.net.UnknownHostException: reason") + .assertNoMoreLogs() + } + + @Test + fun headersAreRedacted() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.HEADERS + logger = log + format = LoggingFormat.OkHttp + sanitizeHeader { it == "SeNsItIvE" } + } + + engine { + addHandler { + respondWithLength( + "", + headers = Headers.build { + append("SeNsItIvE", "value") + append("Not-Sensitive", "value") + } + ) + } + } + }.use { client -> + client.get("/") { + header("SeNsItIvE", "value") + header("Not-Sensitive", "value") + } + log.assertLogEqual("--> GET /") + .assertLogEqual("SeNsItIvE: ██") + .assertLogEqual("Not-Sensitive: value") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("SeNsItIvE: ██") + .assertLogEqual("Not-Sensitive: value") + .assertLogEqual("Content-Length: 0") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + } + + @Test + fun responseValidatorReceivesResponseBody() = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = LogLevel.BODY + logger = log + format = LoggingFormat.OkHttp + } + + HttpResponseValidator { + validateResponse { response -> + response.bodyAsText() + } + } + + engine { + addHandler { + respondWithLength("response body") + } + } + }.use { client -> + val response = client.get("/") + assertEquals("response body", response.bodyAsText()) + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 13") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("") + .assertLogEqual("response body") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 13-byte body\)""")) + .assertNoMoreLogs() + } + } + + @Test + fun sizeInBytesForUtf8ResponseBody() = testWithLevel( + LogLevel.BODY, + handle = { respondWithLength("привет") } + ) { client -> + client.get("/") + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 12") + .assertLogEqual("Content-Type: text/plain") + .assertLogEqual("") + .assertLogEqual("привет") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 12-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGzippedRequestBodyContentLength() = testWithLevel( + LogLevel.BODY, + handle = { respondWithLength() } + ) { client -> + client.post("/") { + header(HttpHeaders.ContentEncoding, "gzip") + setBody(object : OutgoingContent.ReadChannelContent() { + override fun readFrom(): ByteReadChannel { + return GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + } + + override val contentLength: Long? + get() = 29 + }) + } + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Length: 29") + .assertLogEqual("Content-Encoding: gzip") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (encoded 29-byte body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyGzippedRequestBody() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") { + header(HttpHeaders.ContentEncoding, "gzip") + setBody(object : OutgoingContent.ReadChannelContent() { + override fun readFrom(): ByteReadChannel { + return GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + } + }) + } + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Encoding: gzip") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (encoded body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun basicGzippedRequestBody() = testWithLevel(LogLevel.INFO, handle = { respondWithLength() }) { client -> + client.post("/") { + header(HttpHeaders.ContentEncoding, "gzip") + setBody(object : OutgoingContent.ReadChannelContent() { + override fun readFrom(): ByteReadChannel { + return GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + } + }) + } + + log.assertLogEqual("--> POST /") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyHead() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.head("/") + + log.assertLogEqual("--> HEAD /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END HEAD") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyEmptyPost() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.post("/") + + log.assertLogEqual("--> POST / (0-byte body)") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun bodyEmptyResponseBody() = testWithLevel(LogLevel.BODY, handle = { respondWithLength() }) { client -> + client.get("/") + + log.assertLogEqual("--> GET /") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END GET") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, 0-byte body\)""")) + .assertNoMoreLogs() + } + + @Test + fun binaryBodiesIntegrity() = testWithLevel(LogLevel.BODY, handle = { + assertContentEquals(genBinary(7777), it.body.toByteArray()) + respondWithLength(genBinary(10 * 1024), contentType = ContentType.Application.OctetStream) + }) { client -> + val data = client.post("/") { + setBody(genBinary(7777)) + }.bodyAsBytes() + + assertContentEquals(genBinary(10 * 1024), data) + + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Type: application/octet-stream") + .assertLogEqual("Content-Length: 7777") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("") + .assertLogEqual("--> END POST (binary 7777-byte body omitted)") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 10240") + .assertLogEqual("Content-Type: application/octet-stream") + .assertLogEqual("") + .assertLogMatch(Regex("""<-- END HTTP \(\d+ms, binary 10240-byte body omitted\)""")) + .assertNoMoreLogs() + } + + private fun genBinary(size: Int): ByteArray { + return ByteArray(size) { + if (it % 2 == 0) { + 0xC3.toByte() + } else { + 0x28 + } + } + } + + @Test + fun headersGzippedRequestBody() = testWithLevel(LogLevel.HEADERS, handle = { respondWithLength() }) { client -> + client.post("/") { + header(HttpHeaders.ContentEncoding, "gzip") + setBody(object : OutgoingContent.ReadChannelContent() { + override fun readFrom(): ByteReadChannel { + return GZipEncoder.encode(ByteReadChannel("a".repeat(1024))) + } + }) + } + + log.assertLogEqual("--> POST /") + .assertLogEqual("Content-Encoding: gzip") + .assertLogEqual("Accept-Charset: UTF-8") + .assertLogEqual("Accept: */*") + .assertLogEqual("--> END POST") + .assertLogMatch(Regex("""<-- 200 OK / \(\d+ms\)""")) + .assertLogEqual("Content-Length: 0") + .assertLogEqual("<-- END HTTP") + .assertNoMoreLogs() + } + + private fun MockRequestHandleScope.respondWithLength(): HttpResponseData { + return respond( + "", + headers = Headers.build { + append("Content-Length", "0") + } + ) + } + + private fun MockRequestHandleScope.respondChunked( + body: ByteReadChannel, + status: HttpStatusCode = HttpStatusCode.OK, + contentType: ContentType = ContentType.Text.Plain, + headers: Headers = Headers.Empty + ): HttpResponseData { + return respond( + body, + headers = Headers.build { + appendAll(headers) + append("Transfer-Encoding", "chunked") + set("Content-Type", contentType.toString()) + }, + status = status + ) + } + + private fun MockRequestHandleScope.respondWithLength( + body: String, + status: HttpStatusCode = HttpStatusCode.OK, + contentType: ContentType = ContentType.Text.Plain, + headers: Headers = Headers.Empty + ): HttpResponseData { + return respond( + ByteReadChannel(body), + headers = Headers.build { + appendAll(headers) + append("Content-Length", body.toByteArray(Charsets.UTF_8).size.toString()) + set("Content-Type", contentType.toString()) + }, + status = status + ) + } + + private fun MockRequestHandleScope.respondWithLength( + body: ByteArray, + status: HttpStatusCode = HttpStatusCode.OK, + contentType: ContentType = ContentType.Text.Plain, + headers: Headers = Headers.Empty + ): HttpResponseData { + return respond( + ByteReadChannel(body), + headers = Headers.build { + appendAll(headers) + append("Content-Length", body.size.toString()) + set("Content-Type", contentType.toString()) + }, + status = status + ) + } + + private fun testWithLevel( + lvl: LogLevel, + handle: MockRequestHandler, + test: suspend (HttpClient) -> Unit + ) = runTest { + HttpClient(MockEngine) { + install(Logging) { + level = lvl + logger = log + format = LoggingFormat.OkHttp + } + + engine { + addHandler(handle) + } + }.use { client -> + test(client) + } + } +}