diff --git a/ktor-server/ktor-server-netty/jvm/src/io/ktor/server/netty/http1/NettyHttp1Handler.kt b/ktor-server/ktor-server-netty/jvm/src/io/ktor/server/netty/http1/NettyHttp1Handler.kt index cdbc2994828..745fb116d83 100644 --- a/ktor-server/ktor-server-netty/jvm/src/io/ktor/server/netty/http1/NettyHttp1Handler.kt +++ b/ktor-server/ktor-server-netty/jvm/src/io/ktor/server/netty/http1/NettyHttp1Handler.kt @@ -104,7 +104,7 @@ internal class NettyHttp1Handler( override fun exceptionCaught(context: ChannelHandlerContext, cause: Throwable) { when (cause) { is IOException -> { - environment.log.debug("I/O operation failed", cause) + environment.log.trace("I/O operation failed", cause) handlerJob.cancel() context.close() } diff --git a/ktor-server/ktor-server-netty/jvm/test/io/ktor/tests/server/netty/NettySpecificTest.kt b/ktor-server/ktor-server-netty/jvm/test/io/ktor/tests/server/netty/NettySpecificTest.kt index 35703ac1804..084db9cd49a 100644 --- a/ktor-server/ktor-server-netty/jvm/test/io/ktor/tests/server/netty/NettySpecificTest.kt +++ b/ktor-server/ktor-server-netty/jvm/test/io/ktor/tests/server/netty/NettySpecificTest.kt @@ -4,6 +4,10 @@ package io.ktor.tests.server.netty +import ch.qos.logback.classic.Level +import ch.qos.logback.classic.Logger +import ch.qos.logback.classic.spi.ILoggingEvent +import ch.qos.logback.core.read.ListAppender import io.ktor.client.* import io.ktor.client.engine.cio.* import io.ktor.client.plugins.* @@ -16,16 +20,22 @@ import io.ktor.server.application.* import io.ktor.server.application.hooks.* import io.ktor.server.engine.* import io.ktor.server.netty.* +import io.ktor.server.netty.http1.* import io.ktor.server.response.* import io.ktor.server.routing.* import io.ktor.test.dispatcher.* import io.ktor.utils.io.* +import io.mockk.mockk import io.netty.channel.Channel +import io.netty.channel.embedded.EmbeddedChannel import kotlinx.coroutines.* +import org.slf4j.LoggerFactory +import java.io.IOException import java.net.BindException import java.net.ServerSocket import java.util.concurrent.ExecutorService import java.util.concurrent.atomic.AtomicReference +import kotlin.coroutines.EmptyCoroutineContext import kotlin.test.* import kotlin.time.Duration.Companion.milliseconds import kotlin.time.Duration.Companion.seconds @@ -242,6 +252,51 @@ class NettySpecificTest { } } + @Test + fun `client disconnect is logged at trace level`() { + val logger = LoggerFactory.getLogger("io.ktor.tests.server.netty.ClientDisconnectLogging") as Logger + val previousLevel = logger.level + val listAppender = ListAppender().apply { start() } + logger.level = Level.TRACE + logger.addAppender(listAppender) + + val environment = applicationEnvironment { log = logger } + val handler = NettyHttp1Handler( + applicationProvider = { mockk(relaxed = true) }, + enginePipeline = mockk(relaxed = true), + environment = environment, + engineContext = EmptyCoroutineContext, + userContext = EmptyCoroutineContext, + runningLimit = 32 + ) + + // EmbeddedChannel without firing the full pipeline lifecycle: we only + // want to exercise exceptionCaught. Use a fresh channel and add only + // this handler so RequestBodyHandler isn't installed via channelActive. + val channel = EmbeddedChannel() + channel.pipeline().addLast(handler) + try { + channel.pipeline().fireExceptionCaught(IOException("Connection reset by peer")) + + val ioOpFailedEvents = listAppender.list.filter { it.formattedMessage == "I/O operation failed" } + assertEquals( + 1, + ioOpFailedEvents.size, + "Expected one 'I/O operation failed' log entry for client-disconnect IOException, " + + "got ${ioOpFailedEvents.size}" + ) + assertEquals( + Level.TRACE, + ioOpFailedEvents.single().level, + "Client-disconnect IOException must be logged at TRACE to avoid noise in DEBUG logs" + ) + } finally { + logger.detachAppender(listAppender) + logger.level = previousLevel + channel.finishAndReleaseAll() + } + } + @Test fun badRequestOnInvalidQueryString() = runTestWithRealTime { val appStarted = CompletableDeferred()