jetty.project icon indicating copy to clipboard operation
jetty.project copied to clipboard

Published 20 hours ago • verified publisher icon jetty

When handling POST request that goes thru a request-wrapping filter: java.lang.IllegalStateException: unreleased buffer

Open flozano opened this issue 1 year ago • 6 comments

Jetty version(s) 12.0.5 Jetty Environment EE10

Java version/vendor (use: java -version) 21.0.1 temurin

OS type/version only reproduced a couple times in ubuntu-latest github actions. never reproduced in mac. Description I'm implementing a servlet filter that does non-standard Content-Encoding handling on request payloads (not responses). I am receiving payloads that are compressed, and I have a filter that uncompresses them.

The initial approach is really naive, to avoid issues, as it reads the entire request in a byte array and uncompresses it. Then closes the original InputStream. Then it wraps the request and:

  • exposes this byte array as the payload
  • Drops Content-Encoding and Transfer-Encoding
  • Adds/overwrites Content-Lenght with the uncompressed payload.

This basic buffering approach is intended as initial step, as the requests are not big at all.

In order to integration-test, I have a implemented a "mirror" servlet (it initially had issues which ended up being a problem of jdk's own http client in test, so I rewrote some parts and my reproducer with Jetty's own client, as per suggestions in #11484). I fully buffer the request in the MirrorServlet now, and write it as-is to the response.

This approach should be simple enough, and works well locally in Mac, but in github actions I've obtained a few times this stack-trace:

[2024-03-18T12:27:47.105Z] [INFO] [Test worker] org.eclipse.jetty.server.Server jetty-12.0.5; built: 2023-12-18T14:06:32.502Z; git: 3aed62e4959bb8c01f5975fe81e078e3ff626126; jvm 21.0.2+13-LTS
[2024-03-18T12:27:47.203Z] [INFO] [Test worker] org.eclipse.jetty.server.handler.ContextHandler Started oeje10s.ServletContextHandler@32f61a31{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@f5c79a6{STARTED}}
[2024-03-18T12:27:47.214Z] [INFO] [Test worker] org.eclipse.jetty.ee10.servlet.ServletContextHandler Started oeje10s.ServletContextHandler@32f61a31{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@f5c79a6{STARTED}}
[2024-03-18T12:27:47.221Z] [INFO] [Test worker] org.eclipse.jetty.server.AbstractConnector Started ServerConnector@4e193d17{HTTP/1.1, (http/1.1)}{127.0.0.1:22526}
[2024-03-18T12:27:47.238Z] [INFO] [Test worker] org.eclipse.jetty.server.Server Started oejs.Server@6d6bc158{STARTING}[12.0.5,sto=20000] @3661ms
[2024-03-18T12:27:47.524Z] [INFO] [Test worker] org.eclipse.jetty.server.Server Stopped oejs.Server@6d6bc158{STOPPING}[12.0.5,sto=20000]
[2024-03-18T12:27:47.525Z] [INFO] [Test worker] org.eclipse.jetty.server.Server Shutdown oejs.Server@6d6bc158{STOPPING}[12.0.5,sto=20000]
[2024-03-18T12:27:47.53Z] [INFO] [Test worker] org.eclipse.jetty.server.AbstractConnector Stopped ServerConnector@4e193d17{HTTP/1.1, (http/1.1)}{127.0.0.1:22526}
[2024-03-18T12:27:47.532Z] [INFO] [Test worker] org.eclipse.jetty.ee10.servlet.ServletContextHandler Stopped oeje10s.ServletContextHandler@32f61a31{ROOT,/,b=null,a=AVAILABLE,h=oeje10s.ServletHandler@f5c79a6{STOPPED}}
[2024-03-18T12:27:47.538Z] [WARN] [testing-jetty-2-36] org.eclipse.jetty.util.thread.QueuedThreadPool Job failed java.lang.IllegalStateException: unreleased buffer Buffer@7b83fcfd[rc=2,DirectByteBuffer@76ee428b[p=0,l=0,c=8192,r=0]={<<<>>>POST / HT...\x00\x00\x00\x00\x00\x00\x00}]
	at org.eclipse.jetty.server.internal.HttpConnection.releaseRequestBuffer(HttpConnection.java:368)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:470)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:971)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1201)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1156)
	at java.base/java.lang.Thread.run(Thread.java:1583)

and the http client logs:

java.io.IOException: HTTP/1.1 header parser received no bytes
	at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:964)
	at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:133)
	at com.mystuff.server.standalone.PluggableServerTest.testCompressedRequestServlet(PluggableServerTest.java:157)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:112)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:40)
	at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:60)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:52)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at jdk.proxy1/jdk.proxy1.$Proxy2.processTestClass(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker$2.run(TestWorker.java:176)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
	at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:113)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:65)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
	at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:388)
	at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:590)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:182)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:207)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.io.EOFException: EOF reached while reading
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:601)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:648)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:853)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:207)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:280)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:233)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:782)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:965)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:1467)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:1412)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:1412)

How to reproduce? I have no idea, I am not able to consistently reproduce. Looking for hints about what could trigger it so that I can write a full reproducer. Maybe it's also an HTTP client issue? I just would like to confirm, as "unreleased buffer" sounds scary enough to ask.

flozano avatar Mar 18 '24 13:03 flozano

I am receiving payloads that are compressed, and I have a filter that uncompresses them.

That is the biggest red flag in your description. There's a reason that no modern servlet container does compression (inflate or deflate) as a Servlet Filter anymore. The complexities of the Servlet spec (since Servlet 3.0 and the introduction of Async) make it no longer feasible.

Every servlet container now does compression outside of the Servlet layer. We (Eclipse Jetty) do it in a Handler before the ServletContext even called. Tomcat enables Compression at the connector level. Glassfish and Payara enables compression via a network listener.

Every container above used to do compression in a Servlet Filter, but no longer.

joakime avatar Mar 18 '24 14:03 joakime

Is it possible to use the jetty handler for decompression of requests?

Anyway my code is fully synchronous I/O, the servlet does no async operation. I understand the red flag and actually shudder at the idea of implementing proper request wrapping for payloads with async I/O

flozano avatar Mar 18 '24 14:03 flozano

Is it possible to use the jetty handler for decompression of requests?

Yes, it supports that right now. Just set inflate buffer size to a positive value. eg: GzipHandler.setInflateBufferSize(4096)

joakime avatar Mar 18 '24 14:03 joakime

Anyway my code is fully synchronous I/O, the servlet does no async operation. I understand the red flag and actually shudder at the idea of implementing proper request wrapping for payloads with async I/O

Then try again with Jetty 12.0.7. Also, be careful what 3rd party libraries you use, many of them already use/expect/force async-supported on Servlet containers. While you might not be using async in your filter, if you start to use other 3rd party filters (or servlets, or fragments) then the mode of the request might already be in async without you specifying it directly.

joakime avatar Mar 18 '24 14:03 joakime

Then try again with Jetty 12.0.7. Also, be careful what 3rd party libraries you use, many of them already use/expect/force async-supported on Servlet containers. While you might not be using async in your filter, if you start to use other 3rd party filters (or servlets, or fragments) then the mode of the request might already be in async without you specifying it directly.

I am 100% sure I have async-nothing in the pipeline, this is synthetic test with only my filter as a filter and only my mirror servlet to handle the incoming requests.

I will keep trying to reproduce with 12.0.7 (I haven't been able after a few retries - any change in that version that could be related?).

Yes, it supports that right now. Just set inflate buffer size to a positive value. eg: GzipHandler.setInflateBufferSize(4096)

This is great, it works perfect. I can see from code only gzip is supported (no compress and others), but maybe enough this time... The inflateBufferSize must be able to hold the entire request? or just a chunk of data ?

flozano avatar Mar 18 '24 14:03 flozano