search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.86k stars 1.91k forks source link

Numerous stack traces logged at warning level when running under HTTP/2 (regression in 12.0.15) #12520

Open basil opened 4 days ago

basil commented 4 days ago

Jetty version(s)

12.0.15

Jetty Environment

EE 9

Java version/vendor

openjdk version "17.0.12" 2024-07-16
OpenJDK Runtime Environment (build 17.0.12+7-Ubuntu-1ubuntu222.04)
OpenJDK 64-Bit Server VM (build 17.0.12+7-Ubuntu-1ubuntu222.04, mixed mode, sharing)

OS type/version

Ubuntu 22.04.5 LTS x86_64

Context

https://github.com/jenkinsci/jenkins/pull/9951

Steps to reproduce

[!WARNING] My apologies that these steps are not very minimal. Unfortunately, I could not find a minimal reproducible example outside of Jenkins.

Start by pulling down https://github.com/jenkinsci/jenkins/pull/9951. This does nothing other than pull in https://github.com/jenkinsci/winstone/pull/419, which in turn does nothing other than update Jetty from 12.0.14 to 12.0.15.

Compile it with Java 17 by running mvn clean verify -DskipTests.

Run it as follows:

$ wget https://github.com/jenkinsci/winstone/raw/refs/heads/master/src/ssl/wildcard.jks && mv wildcard.jks target
$ java -jar war/target/jenkins.war --http2Port=8000 --httpsKeyStore=target/wildcard.jks --httpsKeyStorePassword=changeit

Once Jenkins comes up, visit https://127.0.0.1:8000 in Firefox and enter the password that was given to you on the console. Click on Install suggested plugins, wait for that to complete, click Skip and continue as admin, click Save and finish, and click Start using Jenkins.

[!WARNING] This appears to be some type of race condition, as I could not find a deterministic way to trigger the issue. However, after doing a few generic actions in the Jenkins UI, I was able to consistently see stack traces within about a minute of clicking around in Firefox.

Do some generic actions in the Jenkins UI. For example, click on New Item, enter a name, select Freestyle Project, click Add Build Step, click Execute Shell, type echo hello, save the project, and build the project a few times.

Check the console where you started Jenkins. You should see the stack traces mentioned below.

If not, open a new tab in Firefox (leaving the old one untouched) and continue clicking around in the UI. Click to go back to the Dashboard, click on the Freestyle project again, build it a few more times, etc. Within a minute, I am always able to see the stack traces mentioned below.

If this bug is being really stubborn, kill the Java process and start Jenkins again, log in again, and browse around again in a new tab. I am always able to reproduce the issue within about a minute after doing this.

Expected results

[!NOTE] These are the actual results with Jenkins at tip-of-trunk, running Jetty 12.0.14.

Back in the console where you started Jenkins, the logs should be clean after:

INFO    hudson.lifecycle.Lifecycle#onReady: Jenkins is fully up and running

Actual results

The console is full of warnings and stack traces like this:

2024-11-12 23:16:13.780+0000 [id=27]    WARNING o.e.jetty.ee9.nested.HttpChannel#handleException: /static/9c13fe00/images/svgs/logo.svg
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:611)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:575)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)
2024-11-12 23:16:13.780+0000 [id=27]    WARNING o.e.j.e.nested.HttpChannelState#onError: onError not handled due to invalid requestState s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannelState.completed(HttpChannelState.java:1025)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.lambda$handle$0(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:170)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpOutput.complete(HttpOutput.java:493)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.Response.completeOutput(Response.java:990)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:634)
    at Jenkins Main ClassLoader//org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2873)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:611)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.Server.handle(Server.java:182)
    at Jenkins Main ClassLoader//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
    at Jenkins Main ClassLoader//org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:575)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
    at Jenkins Main ClassLoader//org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
    at Jenkins Main ClassLoader//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
    at java.base/java.lang.Thread.run(Thread.java:1583)

Evaluation

[!NOTE] The warnings are not related to gzip compression, as they appear whether or not GzipHandler is enabled. In the above example, GzipHandler is enabled (and part of the stack trace), but it can be disabled by starting Jenkins with --compression=none, in which case the problem still appears with a slightly less deep stack trace that does not include GzipHandler.

I bisected this change in behavior to commit f48be0d by @sbordet, part of #12313 and #12370.

I am not comfortable delivering Jetty 12.0.15 to Jenkins users with these stack traces being logged at warning level; in other words, this issue is blocking the Jenkins project from upgrading to the latest release of Jetty.

gregw commented 3 days ago

@basil thanks for this report and the excellent bisection down to a specific commit.

I've not yet tried your reproduction, but am just initially trying to get a general feel for the issue. The stacks indicate that we are trying to normally complete a response that has already been aborted. The strange thing is that the commit you identified was primarily removing unnecessary abort calls? So this suggests that something else is aborting the response??

Since you have an easy reproduction, any chance that you can run this with debug logging turned on for the org.eclipse.jetty.ee9.nested package or if too verbose, just the org.eclipse.jetty.ee9.nested.HttpChannelState class?

thanks

basil commented 3 days ago

@gregw I ran through the scenario described above again, this time with java -Djava.util.logging.config.file=logging.properties -jar war/target/jenkins.war --http2Port=8000 --httpsKeyStore=target/wildcard.jks --httpsKeyStorePassword=changeit, where logging.properties contained

.level=INFO
org.eclipse.jetty.ee9.nested.level=ALL
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
org.eclipse.jetty.ee9.nested.handlers=java.util.logging.ConsoleHandler

It took me almost a minute of clicking around in the Jenkins UI before the IllegalStateExceptions started appearing. The full logs are at: https://basilcrow.com/tmp/debug-logs.txt

This file is 16 MB (!) in size, covering about 1 minute of Jenkins usage. The IllegalStateExceptions described in this issue start at the very end of the file, at line 111525.

gregw commented 3 days ago

@basil Thanks for that log. I can see throughout the log lots of unconsumed content exceptions. These are unrelated and just mean that a response was sent for a request without reading all of the request content. This can be normal, but is something you might want to check.

The actual problem appears to start at 6:54:19 when I can see a write it failed with a reset connection. This them results in an other exception regarding insufficient content written, which is the cause of the abort, which in turn results in the logged exception about the channel being in ABORT state.

Failing gracefully when having a reset slammed in our faces whilst writing a response can be difficult, at least not without accidentally suppressing other exceptions. So we will need to check if a) we can avoid the insufficient content written exception, as that is a result of the resets; and b) should we not log at warning when a response has been aborted before completion?

stand by....