Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CachingHttpContentFactory$CachedHttpContent already released buffer #12681

Open
gregw opened this issue Jan 8, 2025 · 7 comments
Open

CachingHttpContentFactory$CachedHttpContent already released buffer #12681

gregw opened this issue Jan 8, 2025 · 7 comments
Assignees
Labels
Bug For general bugs on Jetty side High Priority

Comments

@gregw
Copy link
Contributor

gregw commented Jan 8, 2025

Jetty version(s)
12.1.x

Jetty Environment
EE11

Description

Whilst developing PR #12678, I have woken up org.eclipse.jetty.servlet6.embedded.Http2Server even though there is no PushCacheFilter anymore. The intention is to convert it to early hints instead.

However, whilst running the draft Http2Server, I often get exceptions like below when serving the tiles:

2025-01-09 10:46:54.482:WARN :oejs.ResourceService:qtp100555887-48: Failed to serve resource: /tiles/tile19.jpg
java.lang.IllegalStateException: already released ReferenceCounter@650e7559[r=0]
	at org.eclipse.jetty.io.Retainable$ReferenceCounter.lambda$release$2(Retainable.java:226)
	at java.base/java.util.concurrent.atomic.AtomicInteger.updateAndGet(AtomicInteger.java:281)
	at org.eclipse.jetty.io.Retainable$ReferenceCounter.release(Retainable.java:223)
	at org.eclipse.jetty.io.Retainable$Wrapper.release(Retainable.java:149)
	at org.eclipse.jetty.io.ArrayByteBufferPool$PooledBuffer.release(ArrayByteBufferPool.java:665)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory$CachedHttpContent.writeTo(CachingHttpContentFactory.java:365)
	at org.eclipse.jetty.server.ResourceService.sendData(ResourceService.java:669)
	at org.eclipse.jetty.server.ResourceService.doGet(ResourceService.java:206)
	at org.eclipse.jetty.ee11.servlet.ResourceServlet.doGet(ResourceServlet.java:545)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:633)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:723)
	at org.eclipse.jetty.ee11.servlet.ServletHolder.handle(ServletHolder.java:736)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1666)
	at org.eclipse.jetty.servlet6.embedded.Http2Server$PushedTilesFilter.doFilter(Http2Server.java:153)
	at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1638)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1599)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.dispatch(ServletChannel.java:802)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.handle(ServletChannel.java:439)
	at org.eclipse.jetty.ee11.servlet.ServletHandler.handle(ServletHandler.java:469)
	at org.eclipse.jetty.ee11.servlet.SessionHandler.handle(SessionHandler.java:763)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1064)
	at org.eclipse.jetty.server.Server.handle(Server.java:182)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:673)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:411)
	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1688)
	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.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:480)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:443)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	at java.base/java.lang.Thread.run(Thread.java:1575)

How to reproduce?

run the Http2Server class, hit http://localhost:8080, do shift reload a few times

@gregw gregw added the Bug For general bugs on Jetty side label Jan 8, 2025
@gregw
Copy link
Contributor Author

gregw commented Jan 9, 2025

@lorban if I remove the setting of maxCacheSize, the problem goes away, so it is likely a problem with cache flushing?

@lorban
Copy link
Contributor

lorban commented Jan 9, 2025

@gregw I unfortunately cannot reproduce this locally, however the exception is thrown from CachedHttpContent.writeTo()'s catch Throwable block, which AFAICT can only be triggered when BufferUtil.slice() throws. I'm surprised the stack trace does not contain a suppressed exception as the root exception is overwritten by IllegalStateException thrown by release.

Can you put a breakpoint on that catch block's release() call to see what the actual failure is?

@gregw
Copy link
Contributor Author

gregw commented Jan 9, 2025

@lorban I modified the method to:

        @Override
        public void writeTo(Content.Sink sink, long offset, long length, Callback callback)
        {
            try
            {
                _buffer.retain();
                sink.write(true, BufferUtil.slice(_buffer.getByteBuffer(), (int)offset, (int)length), Callback.from(_buffer::release, callback));
            }
            catch (Throwable x)
            {
                // BufferUtil.slice() may fail if offset and/or length are out of bounds.
                try
                {
                    _buffer.release();
                }
                catch (Throwable x2)
                {
                    x2.addSuppressed(x);
                    throw x2;
                }
                callback.failed(x);
            }
        }

and now it reports:

2025-01-10 08:16:13.544:WARN :oejs.ResourceService:qtp1053782781-79: Failed to serve resource: /tiles/tile40.jpg
java.lang.IllegalStateException: already released ReferenceCounter@62a6eec5[r=0]
	at org.eclipse.jetty.io.Retainable$ReferenceCounter.lambda$release$2(Retainable.java:226)
	at java.base/java.util.concurrent.atomic.AtomicInteger.updateAndGet(AtomicInteger.java:281)
	at org.eclipse.jetty.io.Retainable$ReferenceCounter.release(Retainable.java:223)
	at org.eclipse.jetty.io.Retainable$Wrapper.release(Retainable.java:149)
	at org.eclipse.jetty.io.ArrayByteBufferPool$PooledBuffer.release(ArrayByteBufferPool.java:665)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory$CachedHttpContent.writeTo(CachingHttpContentFactory.java:367)
	at org.eclipse.jetty.server.ResourceService.sendData(ResourceService.java:669)
	at org.eclipse.jetty.server.ResourceService.doGet(ResourceService.java:206)
	at org.eclipse.jetty.ee11.servlet.ResourceServlet.doGet(ResourceServlet.java:545)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:633)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:723)
	at org.eclipse.jetty.ee11.servlet.ServletHolder.handle(ServletHolder.java:736)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1666)
	at org.eclipse.jetty.servlet6.embedded.Http2Server$PushedTilesFilter.doFilter(Http2Server.java:150)
	at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1638)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1599)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.dispatch(ServletChannel.java:802)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.handle(ServletChannel.java:439)
	at org.eclipse.jetty.ee11.servlet.ServletHandler.handle(ServletHandler.java:469)
	at org.eclipse.jetty.ee11.servlet.SessionHandler.handle(SessionHandler.java:763)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1064)
	at org.eclipse.jetty.server.Server.handle(Server.java:182)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:673)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:411)
	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1688)
	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.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:480)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:443)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	at java.base/java.lang.Thread.run(Thread.java:1575)
Suppressed: 
	|java.lang.IllegalStateException: released ReferenceCounter@62a6eec5[r=0]
	|	at org.eclipse.jetty.io.Retainable$ReferenceCounter.retain(Retainable.java:212)
	|	at org.eclipse.jetty.io.Retainable$Wrapper.retain(Retainable.java:143)
	|	at org.eclipse.jetty.http.content.CachingHttpContentFactory$CachedHttpContent.writeTo(CachingHttpContentFactory.java:359)
	|	at org.eclipse.jetty.server.ResourceService.sendData(ResourceService.java:669)
	|	at org.eclipse.jetty.server.ResourceService.doGet(ResourceService.java:206)
	|	at org.eclipse.jetty.ee11.servlet.ResourceServlet.doGet(ResourceServlet.java:545)
	|	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:633)
	|	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:723)
	|	at org.eclipse.jetty.ee11.servlet.ServletHolder.handle(ServletHolder.java:736)
	|	at org.eclipse.jetty.ee11.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1666)
	|	at org.eclipse.jetty.servlet6.embedded.Http2Server$PushedTilesFilter.doFilter(Http2Server.java:150)
	|	at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
	|	at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1638)
	|	at org.eclipse.jetty.ee11.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1599)
	|	at org.eclipse.jetty.ee11.servlet.ServletChannel.dispatch(ServletChannel.java:802)
	|	at org.eclipse.jetty.ee11.servlet.ServletChannel.handle(ServletChannel.java:439)
	|	at org.eclipse.jetty.ee11.servlet.ServletHandler.handle(ServletHandler.java:469)
	|	at org.eclipse.jetty.ee11.servlet.SessionHandler.handle(SessionHandler.java:763)
	|	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1064)
	|	at org.eclipse.jetty.server.Server.handle(Server.java:182)
	|	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:673)
	|	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:411)
	|	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1688)
	|	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.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:480)
	|	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:443)
	|	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	|	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	|	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	|	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	|	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	|	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	|	at java.base/java.lang.Thread.run(Thread.java:1575)

So the buffer has already been released, but not nulled?

@gregw
Copy link
Contributor Author

gregw commented Jan 9, 2025

The release is happening from:

java.lang.Throwable
	at org.eclipse.jetty.http.content.CachingHttpContentFactory$CachedHttpContent.release(CachingHttpContentFactory.java:381)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory.removeFromCache(CachingHttpContentFactory.java:181)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory.shrinkCache(CachingHttpContentFactory.java:166)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory.getContent(CachingHttpContentFactory.java:262)
	at org.eclipse.jetty.server.ResourceService.getContent(ResourceService.java:88)
	at org.eclipse.jetty.ee11.servlet.ResourceServlet.doGet(ResourceServlet.java:481)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:633)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:723)
	at org.eclipse.jetty.ee11.servlet.ServletHolder.handle(ServletHolder.java:736)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1666)
	at org.eclipse.jetty.servlet6.embedded.Http2Server$PushedTilesFilter.doFilter(Http2Server.java:150)
	at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1638)
	at org.eclipse.jetty.ee11.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1599)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.dispatch(ServletChannel.java:802)
	at org.eclipse.jetty.ee11.servlet.ServletChannel.handle(ServletChannel.java:439)
	at org.eclipse.jetty.ee11.servlet.ServletHandler.handle(ServletHandler.java:469)
	at org.eclipse.jetty.ee11.servlet.SessionHandler.handle(SessionHandler.java:763)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1064)
	at org.eclipse.jetty.server.Server.handle(Server.java:182)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:673)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:411)
	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1688)
	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.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:480)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:443)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	at java.base/java.lang.Thread.run(Thread.java:1575)

@gregw
Copy link
Contributor Author

gregw commented Jan 9, 2025

@lorban the issue is that the content is being released from the cache in the shrink, immediately after it has been added and before it has been used.

@gregw
Copy link
Contributor Author

gregw commented Jan 9, 2025

@lorban the model for the CachedHttpContent is not good, as it only does an extra retain when writing. Really it should do a retain whenever it is taken from the cache and should always be released after that, as another thread can always release it from the cache just before it is written.

@gregw
Copy link
Contributor Author

gregw commented Jan 10, 2025

@lorban I have pushed a possible fix to the #12678 branch. If you think it is viable, it should be moved to its own branch and applied to 12.0.x as well

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For general bugs on Jetty side High Priority
Projects
Status: No status
Development

No branches or pull requests

2 participants