Request.addCompletionListener() may run the listener before the request is fully complete

[lorban]

Jetty version(s)
12.1.x

Description
When using H2, CompletionStreamWrapper.onCompletion() may run while some stream may still have some buffers to write. This can be triggered when the client send a reset frame for a request that is busy downloading a lot of data.

Since all the ee* implementations register a completion listener to call HttpOutput.recycle(), we may recycle a buffer that hasn't been written yet but should.

The symptoms are that the client receives an invalid H2 frame when the bug occurs then reacts by immediately sending a go away frame: Chrome does exactly that and logs a ERR_HTTP2_PROTOCOL_ERROR as the request's status in its Developer Tools' Network tab.

Adding the following log in ee9's HttpOutput:

private void lockedReleaseBuffer()
{
    assert _channelState.isLockHeldByCurrentThread();

    if (_aggregate != null)
    {
        if (_aggregate.remaining() != 0)
            LOG.info("lockedReleaseBuffer aggregate={}", _aggregate, new Throwable());

        _aggregate.release();
        _aggregate = null;
        _pool = null;
    }
}

triggers the following log that got captured while reproducing this problem:

2025-02-19 09:58:32,742 INFO  [qtp1056900554-39] org.eclipse.jetty.ee9.nested.HttpOutput: lockedReleaseBuffer aggregate=ReservedBuffer@3fca1695[52/32768,d=true,r=1]
java.lang.Throwable: null
        at org.eclipse.jetty.ee9.nested.HttpOutput.lockedReleaseBuffer(HttpOutput.java:688)
        at org.eclipse.jetty.ee9.nested.HttpOutput.recycle(HttpOutput.java:1463)
        at org.eclipse.jetty.ee9.nested.Response.recycle(Response.java:192)
        at org.eclipse.jetty.ee9.nested.HttpChannel.recycle(HttpChannel.java:465)
        at org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler.lambda$wrapRequest$0(ContextHandler.java:2838)
        at org.eclipse.jetty.server.internal.CompletionStreamWrapper.onCompletion(CompletionStreamWrapper.java:74)
        at org.eclipse.jetty.server.internal.CompletionStreamWrapper.failed(CompletionStreamWrapper.java:53)
        at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.completeStream(HttpChannelState.java:785)
        at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:708)
        at org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:176)
        at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
        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.produce(AdaptiveExecutionStrategy.java:195)
        at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:231)
        at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:165)
        at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:495)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
        at org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:576)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:391)
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
        at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
        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:840)

Reproducing this error requires downloading large amount of data over a slow WAN link while triggering the client to send H2 resets. A common use-case is to stream a video with the html <video> tag from a handler that supports ranges and repeatedly seeking in the video: each time the video seeking cursor is moved, Chrome cancels the current download and sends a new request to download the appropriate range.

As a workaround, a non-pooling pool can be configured so that the buffers don't get re-pooled and reset while another thread is about to write them.