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

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

Closed
basil opened this issue Nov 12, 2024 · 5 comments · Fixed by #12545
Closed
Assignees

Comments

@basil
Copy link
Contributor

basil commented Nov 12, 2024

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

jenkinsci/jenkins#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 jenkinsci/jenkins#9951. This does nothing other than pull in jenkinsci/winstone#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
Copy link
Contributor

gregw commented Nov 13, 2024

@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
Copy link
Contributor Author

basil commented Nov 13, 2024

@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
Copy link
Contributor

gregw commented Nov 13, 2024

@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....

lorban added a commit that referenced this issue Nov 18, 2024
Signed-off-by: Ludovic Orban <lorban@bitronix.be>
lorban added a commit that referenced this issue Nov 18, 2024
Signed-off-by: Ludovic Orban <lorban@bitronix.be>
lorban added a commit that referenced this issue Nov 19, 2024
Signed-off-by: Ludovic Orban <lorban@bitronix.be>
lorban added a commit that referenced this issue Nov 19, 2024
Signed-off-by: Ludovic Orban <lorban@bitronix.be>
@lorban
Copy link
Contributor

lorban commented Nov 19, 2024

@basil I've created a pull request that contains a fix for this bug.

While I'm busy ironing out the last details, I'd be glad if you could give it a try to see if it works for you too as I haven't managed to reproduce the problem with a Jenkins build using the Jetty build of that PR. Thanks!

@basil
Copy link
Contributor Author

basil commented Nov 19, 2024

@lorban I can confirm that commit ef453d6 fixes the issue for me in Jenkins. Thanks!

lorban added a commit that referenced this issue Nov 20, 2024
…11210)

Signed-off-by: Ludovic Orban <lorban@bitronix.be>
@sbordet sbordet moved this to 🏗 In progress in Jetty 12.0.16 FROZEN Nov 20, 2024
lorban added a commit that referenced this issue Nov 26, 2024
…11210) (#12545)

Signed-off-by: Ludovic Orban <lorban@bitronix.be>
@github-project-automation github-project-automation bot moved this from 🏗 In progress to ✅ Done in Jetty 12.0.16 FROZEN Nov 26, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: ✅ Done
Development

Successfully merging a pull request may close this issue.

4 participants