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

Closed
gregw opened this issue Jan 8, 2025 · 11 comments · Fixed by #12710
Closed

CachingHttpContentFactory$CachedHttpContent already released buffer #12681

gregw opened this issue Jan 8, 2025 · 11 comments · Fixed by #12710
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

gregw added a commit that referenced this issue Jan 12, 2025
This is a partial fix for #12681. It does not fix the actual release race on a single content, but by restricting the shrinking to a single thread, make the race less likely to occur.

There is a more comprehensive fix in #12678 for 12.1, but the cache has changed too much for a straight forward back port.
@lorban
Copy link
Contributor

lorban commented Jan 13, 2025

@gregw I think you're right, the CachingHttpContentFactory model is wrong w.r.t retain/release.

I have mixed feelings about your proposed fix in #12678 as using an atomic to avoid concurrent releases will only lower the bug's odds while raising the odds of overshooting the cache, and I think using an AtomicReference to null it out may still be racy, at least in the current form.

Contrary to what the comment on line 233 says, ConcurrentHashMap guarantees that the lambda is executed at most once, so we can rely on compute* methods to atomically modify the retain counter and the cache.

So CachedHttpContent.write() could do a _cache.computeIfPresent() to atomically ensure the content is still cached and increase the retain counter instead of directly calling retain on the buffer, and make sure all accesses to _cache only happen via compute* methods.

@gregw
Copy link
Contributor Author

gregw commented Jan 13, 2025

@lorban my fix is indeed racy, but has a fallback in that if it loses the race, then the retain will fail and it will fall back to the uncached content. So it should work.

However, doing something better would be good. Do you want to have a go of the computeIfPresent approach in write? It still is not perfect, as the write only happens after something is taken from the cache, and then there is no guarantee that write is called once and only once. More over, there is no general HttpContent release mechanism, so any retain done in taking the content from the cache cannot be released once the reference is no longer held.

But please have a go at something better than #12678 if you can.

I can test in #12678 as those demos are at least a way of reproducing the issue.... or maybe review merge #12678 as is to get the demos back in, then we can have a separate PR to try to improve the caching?

lorban added a commit that referenced this issue Jan 13, 2025
…the cache, otherwise delegate to the wrapped content

Signed-off-by: Ludovic Orban <[email protected]>
@lorban
Copy link
Contributor

lorban commented Jan 13, 2025

@gregw I've tried a hybrid approach in #12704 where I use computeIfPresent() to atomically check that the content is still usable and retain it only in write() and I just delegate to the wrapper if computeIfPresent fails.

lorban added a commit that referenced this issue Jan 13, 2025
Signed-off-by: Ludovic Orban <[email protected]>
@lorban
Copy link
Contributor

lorban commented Jan 13, 2025

IMHO we can merge #12678 as-is and fix the caching problem separately.

lorban added a commit that referenced this issue Jan 13, 2025
Signed-off-by: Ludovic Orban <[email protected]>
gregw added a commit that referenced this issue Jan 13, 2025
This is a partial fix for #12681. It does not fix the actual release race on a single content, but by restricting the shrinking to a single thread, make the race less likely to occur.

There is a more comprehensive fix in #12678 and #12704 for 12.1,
lorban added a commit that referenced this issue Jan 14, 2025
…the cache, otherwise retain fails + remove single-threaded shrinking

Signed-off-by: Ludovic Orban <[email protected]>
lorban added a commit that referenced this issue Jan 14, 2025
Signed-off-by: Ludovic Orban <[email protected]>
lorban added a commit that referenced this issue Jan 15, 2025
Signed-off-by: Ludovic Orban <[email protected]>
lorban added a commit that referenced this issue Jan 15, 2025
…er (#12704)

#12681 atomically retain the buffer with a check that it still is in the cache, otherwise delegate to the wrapped content

Signed-off-by: Ludovic Orban <[email protected]>
lorban added a commit that referenced this issue Jan 15, 2025
…the cache, otherwise retain fails + remove single-threaded shrinking

Signed-off-by: Ludovic Orban <[email protected]>
@github-project-automation github-project-automation bot moved this to ✅ Done in Jetty 12.1.0 Jan 15, 2025
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: ✅ Done
Development

Successfully merging a pull request may close this issue.

2 participants