Skip to content

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

Open
@Ristop

Description

@Ristop

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.<init>(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

  • Version of this library used: 4.1.1
  • Version of Java used: 17
  • Version of Spring Boot used: 3.1.12
  • Web server used (Tomcat, Jetty, Undertow or Netty): Undertow
  • Web application type used (Servlet Stack or Reactive Stack): Servlet

Metadata

Metadata

Assignees

No one assigned

    Labels

    type:bugA bug report or bug fix.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions