akkinoc / logback-access-spring-boot-starter

Spring Boot Starter for Logback-access.
Apache License 2.0
193 stars 32 forks source link

Undertow logging failing due to UT000005: getRequestChannel() has already been called #479

Open Ristop opened 2 months ago

Ristop commented 2 months ago

Describe the bug

We have a OncePerRequestFilter that under certain conditions sets the response status and doesn't proceed with filterchain

if (...) {
      response.status = statusCode
} else {
      filterChain.doFilter(request, response)
}

When the condition is met and only status is set then there is no access log entry for that line.

It's failing in ch.qos.logback.core.OutputStreamAppender#subAppend where following RuntimeException is thrown when calling event.prepareForDeferredProcessing():

Stacktrace ``` java.io.IOException: java.lang.IllegalStateException: UT000005: getRequestChannel() has already been called at io.undertow.server.handlers.form.FormEncodedDataDefinition$FormEncodedDataParser.parseBlocking(FormEncodedDataDefinition.java:291) at io.undertow.servlet.spec.HttpServletRequestImpl.parseFormData(HttpServletRequestImpl.java:881) at io.undertow.servlet.spec.HttpServletRequestImpl.getParameterMap(HttpServletRequestImpl.java:833) at dev.akkinoc.spring.boot.logback.access.undertow.LogbackAccessUndertowEventSource$requestParameterMap$2.invoke(LogbackAccessUndertowEventSource.kt:133) at dev.akkinoc.spring.boot.logback.access.undertow.LogbackAccessUndertowEventSource$requestParameterMap$2.invoke(LogbackAccessUndertowEventSource.kt:130) at kotlin.UnsafeLazyImpl.getValue(Lazy.kt:81) at dev.akkinoc.spring.boot.logback.access.undertow.LogbackAccessUndertowEventSource.getRequestParameterMap(LogbackAccessUndertowEventSource.kt:130) at dev.akkinoc.spring.boot.logback.access.LogbackAccessEventSource$Fixed.(LogbackAccessEventSource.kt:212) at dev.akkinoc.spring.boot.logback.access.LogbackAccessEventSource.fix(LogbackAccessEventSource.kt:161) at dev.akkinoc.spring.boot.logback.access.LogbackAccessEvent.prepareForDeferredProcessing(LogbackAccessEvent.kt:163) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:235) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.access.spi.AccessContext.callAppenders(AccessContext.java:41) at dev.akkinoc.spring.boot.logback.access.LogbackAccessContext.emit(LogbackAccessContext.kt:69) at dev.akkinoc.spring.boot.logback.access.undertow.LogbackAccessUndertowHttpHandler.log(LogbackAccessUndertowHttpHandler.kt:52) at io.undertow.server.HttpServerExchange$ExchangeCompleteNextListener.proceed(HttpServerExchange.java:1983) at io.undertow.server.handlers.RequestLimit$1.exchangeEvent(RequestLimit.java:83) at io.undertow.server.HttpServerExchange.invokeExchangeCompleteListeners(HttpServerExchange.java:1358) at io.undertow.server.HttpServerExchange.terminateRequest(HttpServerExchange.java:1349) at io.undertow.server.Connectors.terminateRequest(Connectors.java:178) at io.undertow.server.protocol.http.HttpTransferEncoding$1.handleEvent(HttpTransferEncoding.java:179) at io.undertow.server.protocol.http.HttpTransferEncoding$1.handleEvent(HttpTransferEncoding.java:172) at io.undertow.conduits.FixedLengthStreamSourceConduit.invokeFinishListener(FixedLengthStreamSourceConduit.java:378) at io.undertow.conduits.FixedLengthStreamSourceConduit.read(FixedLengthStreamSourceConduit.java:239) at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127) at io.undertow.channels.DetachableStreamSourceChannel.read(DetachableStreamSourceChannel.java:206) at io.undertow.server.HttpServerExchange$ReadDispatchChannel.read(HttpServerExchange.java:2445) at org.xnio.channels.Channels.readBlocking(Channels.java:344) at io.undertow.servlet.spec.ServletInputStreamImpl.readIntoBuffer(ServletInputStreamImpl.java:201) at io.undertow.servlet.spec.ServletInputStreamImpl.close(ServletInputStreamImpl.java:266) at io.undertow.servlet.spec.HttpServletRequestImpl.closeAndDrainRequest(HttpServletRequestImpl.java:731) at io.undertow.servlet.core.ServletBlockingHttpExchange.close(ServletBlockingHttpExchange.java:89) at io.undertow.server.HttpServerExchange.endExchange(HttpServerExchange.java:1709) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:418) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859) at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538) at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282) at java.base/java.lang.Thread.run(Thread.java:840) Caused by: java.lang.IllegalStateException: UT000005: getRequestChannel() has already been called ... 42 more ```

To Reproduce

Create a OncePerRequestFilter that just sets the status and doesn't call filterChain.doFilter(request, response).

Expected behavior

Should log to the access log.

Environment