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

IllegalStateException when last write fails #11370

Closed
ekupcik opened this issue Feb 2, 2024 · 10 comments · Fixed by #11439
Closed

IllegalStateException when last write fails #11370

ekupcik opened this issue Feb 2, 2024 · 10 comments · Fixed by #11439
Assignees
Labels
Bug For general bugs on Jetty side

Comments

@ekupcik
Copy link

ekupcik commented Feb 2, 2024

Jetty version(s)
12.0.6

Description
This is almost the same as in #11095 but this time the call stack is different. But while it was this call stack there

java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052) ~[jetty-ee10-servlet-12.0.5.jar:12.0.5]
at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$3(ServletChannel.java:553) ~[jetty-ee10-servlet-12.0.5.jar:12.0.5]
at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:162) ~[jetty-util-12.0.5.jar:12.0.5]
at org.eclipse.jetty.ee10.servlet.HttpOutput.complete(HttpOutput.java:424) ~[jetty-ee10-servlet-12.0.5.jar:12.0.5]

...

I got this now with a different call stack. Probably because the requests were cancelled by the browser

java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052)
at org.eclipse.jetty.util.Callback$3.failed(Callback.java:168)
at org.eclipse.jetty.ee10.servlet.HttpOutput.onWriteComplete(HttpOutput.java:252)
at org.eclipse.jetty.ee10.servlet.HttpOutput$WriteCompleteCB.failed(HttpOutput.java:1760)
at org.eclipse.jetty.ee10.servlet.HttpOutput$CompleteWriteCompleteCB.failed(HttpOutput.java:1777)
at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.accept(ContextHandler.java:1179)
at org.eclipse.jetty.server.handler.ContextResponse$1.failed(ContextResponse.java:47)
at org.eclipse.jetty.util.IteratingNestedCallback.onCompleteFailure(IteratingNestedCallback.java:58)

at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback$GzipBufferCB.onCompleteFailure(GzipResponseAndCallback.java:332)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:335)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)
at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.gzip(GzipResponseAndCallback.java:157)
at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.write(GzipResponseAndCallback.java:135)
at org.eclipse.jetty.server.Response$Wrapper.write(Response.java:754)
at org.eclipse.jetty.server.handler.ContextResponse.write(ContextResponse.java:56)
at org.eclipse.jetty.ee10.servlet.ServletContextResponse.write(ServletContextResponse.java:288)
at org.eclipse.jetty.ee10.servlet.HttpOutput.channelWrite(HttpOutput.java:204)
at org.eclipse.jetty.ee10.servlet.HttpOutput.complete(HttpOutput.java:435)
at org.eclipse.jetty.ee10.servlet.ServletContextResponse.completeOutput(ServletContextResponse.java:212)
at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:562)
at org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:464)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:571)
at org.eclipse.jetty.ee10.servlet.SessionHandler.handle(SessionHandler.java:703)
at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:763)
at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:597)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:181)
at org.eclipse.jetty.server.Server.handle(Server.java:179)
at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:619)
at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:410)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322)
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:478)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
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:410)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:971)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1201)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1156)
at java.base/java.lang.Thread.run(Thread.java:833)

I haven't tried to verify whether it was really caused by the GZip filter too in this case yet as that is not as easy to reproduce

@ekupcik ekupcik added the Bug For general bugs on Jetty side label Feb 2, 2024
@joakime
Copy link
Contributor

joakime commented Feb 2, 2024

Do you happen to have a reproduction test case?

@ekupcik
Copy link
Author

ekupcik commented Feb 2, 2024

I can confirm now that this also happens only when I use the GZip Filter like in the original issue.


private Handler wrapGzip(WebAppContext aWebContext)
	{
		if(isUseGZip )
		{
			GzipHandler loGzipHandler = new GzipHandler();
			loGzipHandler.setHandler(aWebContext);
			loGzipHandler.addIncludedMimeTypes(
				"text/html",
				"text/plain",
				"text/xml",
				"text/css",
				"application/javascript",
				"application/json",
				"text/javascript");
			loGzipHandler.addIncludedMethods("POST", "GET");

			return loGzipHandler;
		}
		else
		{
			return aWebContext;
		}
	}

I can also reproduce easily in my application. The application is rendering a JSP which references various static resources. When I just keep the reloading the page by keeping CTRL+F5 pressed in Firefox the error occurs all time. Now all the time doesn't mean on each request but within a few seconds I get it multiple times.

In the firefox console i can see the NS_BINDING_ABORTED errors but not each of them causes this error. In this test case it seems happens only for the theme.css and not for the JS files. But the first time I saw the error in my logs it was for the JS files. So this doesn't mean much. And even for the theme.css there are more aborted requests in the browser than errors in the log. So a NS_BINDING_ABORTED doesn't automatically trigger the error

grafik

It also actually quite sensitive to timing. With a longer network console log that or if the console fills almost the whole screen it seems to be much be difficult to reproduce (running Windows on i7 11800)

@joakime
Copy link
Contributor

joakime commented Feb 2, 2024

The NS_BINDING_ABORTED from Firefox just means the resource load was cancelled by Firefox (usually by a page refresh).

See: https://web.archive.org/web/20091005053108/http://markmail.org/message/m6z77uoixf3qu7u6

Constantly (and aggressively) refreshing via the browser is sure to trigger a variety of failed network read / writes from the previous requests that were closed by the browser.

Out of curiosity, what component in your webapp is serving those resources?
Does that technique include an Expires header on the output?
I ask, as the stacktrace is unclear what component is returning the response to the request for those static resources. (A proper Expires header should prevent Firefox from even making the request to the server, and also turn the NS_BINDING_ABORTED to one of a variety of "cache" messages)

@ekupcik
Copy link
Author

ekupcik commented Feb 3, 2024

Actually there was a mix of static and dynamicl content in the previous example. The theme.css I mention is actually a user configurable CSS and served from a servlet filter. But other CSS, JS etc is really static content and served by the Jetty DefaultServlet. The first time I saw this error in the logs it was for such static content but when I tried to reproduce it was reported only for the dynamic content. Don't ask me why. But just to make sure i switched back to the default theme which is a static resource and run then brute force test again. And it is as easy to reproduce as before with the static resources.

What i noticed is that when it happens during the brute force test it is reported only for a single file

2024/02/03 09:10:54.320 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:54.492 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:54.586 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:54.649 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:54.984 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:55.084 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:55.152 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:55.186 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:55.216 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:10:55.245 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

So i changed the order of the references but that didn't change anything. But when I made one of the other files noticeable bigger so that it was even bigger than the jquery.min it started to fail for both files

2024/02/03 09:16:56.278 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:16:56.281 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:16:56.378 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:16:56.381 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/jquery.min.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:16:57.073 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:16:57.363 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

So I started playing with the file size to see whether that really means something. And guess what: up to 32.767 bytes it seems to be fine. But once it reaches 32.768 or more the error starts to appear. I also made a test by referencing two versions of the file in the JSP, one 32.767 bytes and one 32.768 and only the 32.768 version fails

2024/02/03 09:43:18.032 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:43:18.097 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:43:18.623 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:43:18.853 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

�[m2024/02/03 09:43:19.150 �[33mWARN  [ServletChannel                ]  /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0

jetty.log

2024/02/03 09:47:31.875  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput write(array HeapByteBuffer@5e12b804[p=0,l=4096,c=4096,r=4096]={<<<  }\n\t\t\t  }\n\t\t\t});\n\t}*/\n}\n...\n\tregisterCapsLockWarni>>>})
2024/02/03 09:47:31.875  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush Buffer@41e8b4aa[rc=1,DirectByteBuffer@7f7f7824[p=0,l=28672,c=32768,r=28672]={<<<function registerCapsLock...\n\tregisterCapsLockWarni>>>ng();\n\tfi...gskj111}]
2024/02/03 09:47:31.875  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput write(array HeapByteBuffer@1d43bfb[p=0,l=4096,c=4096,r=4096]={<<<ng();\n\tfixPageDivHeight()...}\n\nsdfsdfasdkjfhgskj111>>>})
2024/02/03 09:47:31.875  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput write(array) s=OPEN,api=BLOCKED,sc=false,e=null last=false agg=true flush=true async=false, len=0 Buffer@41e8b4aa[rc=1,DirectByteBuffer@7f7f7824[p=0,l=32768,c=32768,r=32768]={<<<function registerCapsLock...}\n\nsdfsdfasdkjfhgskj111>>>}]
2024/02/03 09:47:31.875  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.HttpOutput onWriteComplete(true,null) s=CLOSING,api=BLOCKED,sc=false,e=null->s=CLOSED,api=BLOCKING,sc=false,e=null c=null cb=Callback@253a046e{NON_BLOCKING, org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1192/0x00000008018e5000@600616b,org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1197/0x00000008018e5aa0@2bfe2958} w=false
2024/02/03 09:47:31.875  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.HttpOutput onWriteComplete(true,null) s=CLOSING,api=BLOCKED,sc=false,e=null->s=CLOSED,api=BLOCKING,sc=false,e=null c=null cb=Callback@3374dc06{NON_BLOCKING, org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1192/0x00000008018e5000@784fab59,org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1197/0x00000008018e5aa0@1fb16a45} w=false
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannelState completed ServletChannelState@57ca552c{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannelState completed ServletChannelState@2a4b01d0{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannelState unhandle ServletChannelState@57ca552c{s=HANDLING rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannelState nextAction(false) TERMINATED ServletChannelState@57ca552c{s=IDLE rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannelState unhandle ServletChannelState@2a4b01d0{s=HANDLING rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannel action TERMINATED ServletChannel@10a29ec{s=ServletChannelState@57ca552c{s=IDLE rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0},r=0,c=true/false,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/js/util-32767.js?1706949786861,age=1}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannel onCompleted for /gatekeeper/ui/gatekeeper/js/util-32767.js written app=32767 net=2166
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannelState nextAction(false) TERMINATED ServletChannelState@2a4b01d0{s=IDLE rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannel action TERMINATED ServletChannel@734e798f{s=ServletChannelState@2a4b01d0{s=IDLE rs=COMPLETED os=OPEN is=IDLE awp=false se=false i=false al=0},r=0,c=true/false,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/themes/default/theme.css?1706949786861,age=1}
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannel onCompleted for /gatekeeper/ui/gatekeeper/themes/default/theme.css written app=11647 net=2549
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput onWriteComplete(false,null) s=OPEN,api=BLOCKED,sc=false,e=null->s=OPEN,api=BLOCKING,sc=false,e=null c=null cb=null w=false
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState unhandle ServletChannelState@1f2677b2{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState nextAction(false) COMPLETE ServletChannelState@1f2677b2{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannel action COMPLETE ServletChannel@5a17429e{s=ServletChannelState@1f2677b2{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0},r=0,c=false/false,a=HANDLING,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/js/util-32768.js?1706949786861,age=1}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput complete(Callback@450792b{NON_BLOCKING, org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1192/0x00000008018e5000@7caa7d15,org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1197/0x00000008018e5aa0@37b3281c}) s=CLOSING,api=BLOCKED,sc=false,e=null s=false e=null, c=HeapByteBufferR@1442f436[p=0,l=0,c=0,r=0]={<<<>>>}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannel !handle TERMINATED ServletChannel@10a29ec{s=ServletChannelState@57ca552c{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=0,c=true/true,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/js/util-32767.js?1706949786861,age=2}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState abort=true ServletChannelState@1f2677b2{s=HANDLING rs=COMPLETING os=ABORTED is=IDLE awp=false se=false i=false al=0}
org.eclipse.jetty.io.EofException: null
	at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:117) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:275) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:254) ~[?:?]
	...
Caused by: java.io.IOException: An established connection was aborted by the software in your host machine
	at java.base/sun.nio.ch.SocketDispatcher.writev0(Native Method) ~[?:?]
	at java.base/sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:58) ~[?:?]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:217) ~[?:?]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:153) ~[?:?]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:563) ~[?:?]
	at java.base/java.nio.channels.SocketChannel.write(SocketChannel.java:642) ~[?:?]
	at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:111) ~[?:?]
	... 50 more
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.ServletChannelState recycle ServletChannelState@57ca552c{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.HttpInput recycle HttpInput@1822207510 cs=ServletChannelState@57ca552c{s=IDLE rs=BLOCKING os=IDLE is=IDLE awp=false se=false i=true al=0} cp=org.eclipse.jetty.ee10.servlet.BlockingContentProducer@1b7aaf58 eof=false
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.BlockingContentProducer recycling org.eclipse.jetty.ee10.servlet.BlockingContentProducer@1b7aaf58
2024/02/03 09:47:31.876  DEBUG [] [http-server-197] org.eclipse.jetty.ee10.servlet.AsyncContentProducer recycling AsyncContentProducer@8efcaf9[c=null]
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpOutput onWriteComplete(true,org.eclipse.jetty.io.EofException) s=CLOSING,api=BLOCKED,sc=false,e=null->s=CLOSED,api=BLOCKING,sc=false,e=null c=null cb=Callback@450792b{NON_BLOCKING, org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1192/0x00000008018e5000@7caa7d15,org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda$1197/0x00000008018e5aa0@37b3281c} w=false
org.eclipse.jetty.io.EofException: null
	at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:117) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:275) ~[?:?]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:254) ~[?:?]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:368) ~[?:?]
	...
Caused by: java.io.IOException: An established connection was aborted by the software in your host machine
	at java.base/sun.nio.ch.SocketDispatcher.writev0(Native Method) ~[?:?]
	at java.base/sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:58) ~[?:?]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:217) ~[?:?]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:153) ~[?:?]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:563) ~[?:?]
	at java.base/java.nio.channels.SocketChannel.write(SocketChannel.java:642) ~[?:?]
	at org.eclipse.jetty.io.SocketChannelEndPoint.flush(SocketChannelEndPoint.java:111) ~[?:?]
	... 50 more
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState completed ServletChannelState@1f2677b2{s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  WARN  [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannel /gatekeeper/ui/gatekeeper/js/util-32768.js
java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
	at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052) ~[?:?]
	at org.eclipse.jetty.util.Callback$3.failed(Callback.java:168) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput.onWriteComplete(HttpOutput.java:252) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput$WriteCompleteCB.failed(HttpOutput.java:1760) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput$CompleteWriteCompleteCB.failed(HttpOutput.java:1777) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.accept(ContextHandler.java:1179) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextResponse$1.failed(ContextResponse.java:47) ~[?:?]
	at org.eclipse.jetty.util.IteratingNestedCallback.onCompleteFailure(IteratingNestedCallback.java:58) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback$GzipBufferCB.onCompleteFailure(GzipResponseAndCallback.java:332) ~[?:?]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:335) ~[?:?]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.gzip(GzipResponseAndCallback.java:157) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.write(GzipResponseAndCallback.java:135) ~[?:?]
	...
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannel !handle TERMINATED ServletChannel@734e798f{s=ServletChannelState@2a4b01d0{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=0,c=true/true,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/themes/default/theme.css?1706949786861,age=2}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState abort=false ServletChannelState@1f2677b2{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 org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052) ~[?:?]
	at org.eclipse.jetty.util.Callback$3.failed(Callback.java:168) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput.onWriteComplete(HttpOutput.java:252) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput$WriteCompleteCB.failed(HttpOutput.java:1760) ~[?:?]
	at org.eclipse.jetty.ee10.servlet.HttpOutput$CompleteWriteCompleteCB.failed(HttpOutput.java:1777) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.accept(ContextHandler.java:1179) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextResponse$1.failed(ContextResponse.java:47) ~[?:?]
	at org.eclipse.jetty.util.IteratingNestedCallback.onCompleteFailure(IteratingNestedCallback.java:58) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback$GzipBufferCB.onCompleteFailure(GzipResponseAndCallback.java:332) ~[?:?]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:335) ~[?:?]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.gzip(GzipResponseAndCallback.java:157) ~[?:?]
	at org.eclipse.jetty.server.handler.gzip.GzipResponseAndCallback.write(GzipResponseAndCallback.java:135) ~[?:?]
	at org.eclipse.jetty.server.Response$Wrapper.write(Response.java:754) ~[?:?]
	....
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState unhandle ServletChannelState@1f2677b2{s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState nextAction(false) TERMINATED ServletChannelState@1f2677b2{s=IDLE rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannel action TERMINATED ServletChannel@5a17429e{s=ServletChannelState@1f2677b2{s=IDLE rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0},r=0,c=true/false,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/js/util-32768.js?1706949786861,age=1}
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.ServletChannelState recycle ServletChannelState@2a4b01d0{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.876  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannel onCompleted for /gatekeeper/ui/gatekeeper/js/util-32768.js written app=32768 net=2167
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.HttpInput recycle HttpInput@1885870698 cs=ServletChannelState@2a4b01d0{s=IDLE rs=BLOCKING os=IDLE is=IDLE awp=false se=false i=true al=0} cp=org.eclipse.jetty.ee10.servlet.BlockingContentProducer@2a4299a4 eof=false
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.BlockingContentProducer recycling org.eclipse.jetty.ee10.servlet.BlockingContentProducer@2a4299a4
2024/02/03 09:47:31.876  DEBUG [] [http-server-190] org.eclipse.jetty.ee10.servlet.AsyncContentProducer recycling AsyncContentProducer@43c590d7[c=null]
2024/02/03 09:47:31.877  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannel !handle TERMINATED ServletChannel@5a17429e{s=ServletChannelState@1f2677b2{s=IDLE rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0},r=0,c=true/false,a=IDLE,uri=http://localhost:8800/gatekeeper/ui/gatekeeper/js/util-32768.js?1706949786861,age=2}
2024/02/03 09:47:31.877  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.ServletChannelState recycle ServletChannelState@1f2677b2{s=IDLE rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0}
2024/02/03 09:47:31.877  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.HttpInput recycle HttpInput@1559729658 cs=ServletChannelState@1f2677b2{s=IDLE rs=BLOCKING os=ABORTED is=IDLE awp=false se=false i=true al=0} cp=org.eclipse.jetty.ee10.servlet.BlockingContentProducer@2db595f4 eof=false
2024/02/03 09:47:31.877  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.BlockingContentProducer recycling org.eclipse.jetty.ee10.servlet.BlockingContentProducer@2db595f4
2024/02/03 09:47:31.877  DEBUG [] [http-server-204] org.eclipse.jetty.ee10.servlet.AsyncContentProducer recycling AsyncContentProducer@3aaf5874[c=null]

There are is no Expires headers. But in the end that would wouldn't change much about the underlying problem when as the brute force test is using CTRL-F5 to force a complete reload. It doesn't happen with a standard reload even though FF still logs NS_BINDING_ABORTED even on a simple reload with just F5

@ekupcik
Copy link
Author

ekupcik commented Feb 3, 2024

Small addition: the short version of the file ends with sdfsdfasdkjfhgskj11 and the long one with sdfsdfasdkjfhgskj111

@joakime joakime moved this to 🏗 In progress in Jetty 12.0.7 - FROZEN Feb 21, 2024
@sbordet sbordet self-assigned this Feb 22, 2024
@sbordet sbordet changed the title IllegalStateException (when Gzip compression enabled?) when called from Callback$3.failed() IllegalStateException when last write fails Feb 22, 2024
sbordet added a commit that referenced this issue Feb 22, 2024
Removed the call to `ServletChannel.abort()` from the write callback.

As the write was issued from `ServletChannel.handle()` case COMPLETE, it was eventually calling `ServletChannelState.completed(Throwable)`, which is expecting the requestState to be COMPLETING.
However, calling `abort()` would set the requestState to COMPLETED, causing the IllegalStateException.

There should be no need to call `abort()` from the callback of failed writes, since failing the various callbacks should be enough, eventually failing the `HttpStream`, which would take care of tearing down the connection (HTTP/1) or the stream (HTTP/2+).

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
@sbordet sbordet linked a pull request Feb 22, 2024 that will close this issue
@sbordet
Copy link
Contributor

sbordet commented Feb 22, 2024

I was able to reproduce the issue.

It does not depend on gzip, it happens for failed writes also without gzip.

The fix is in #11439, along with analysis and fix.

sbordet added a commit that referenced this issue Feb 23, 2024
Now aborting the response from ServletChannelState.completed(Throwable).
Fixed SizeLimitHandler exception message.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
sbordet added a commit that referenced this issue Feb 23, 2024
Fixed SizeLimitHandlerTest.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
@LarsKrogJensen
Copy link
Contributor

LarsKrogJensen commented Feb 26, 2024

I am also seeing this warning after upgrading 11.0.17 -> 12.0.6 and question is if this is log noise that can be muted until the fix is released OR if it has some real negative impact on user requests?

@sbordet
Copy link
Contributor

sbordet commented Feb 26, 2024

It has no negative impact.

You can tune the logger for that particular class.

The fix will be in the upcoming 12.0.7 release.

sbordet added a commit that referenced this issue Feb 26, 2024
Removed the call to `ServletChannel.abort()` from the write callback.

As the write was issued from `ServletChannel.handle()` case COMPLETE, it was eventually calling `ServletChannelState.completed(Throwable)`, which is expecting the requestState to be COMPLETING.
However, calling `abort()` would set the requestState to COMPLETED, causing the IllegalStateException.

There should be no need to call `abort()` from the callback of failed writes, since failing the various callbacks should be enough, eventually failing the `HttpStream`, which would take care of tearing down the connection (HTTP/1) or the stream (HTTP/2+).

Now aborting the response from ServletChannelState.completed(Throwable).
Fixed SizeLimitHandler exception message.

Signed-off-by: Simone Bordet <simone.bordet@gmail.com>
@github-project-automation github-project-automation bot moved this from 🏗 In progress to ✅ Done in Jetty 12.0.7 - FROZEN Feb 26, 2024
@at01071988
Copy link

at01071988 commented Mar 14, 2024

I am also seeing same issue after upgrading jetty 11.0.17 -> 12.0.5. the same issue is in jetty 12.0.5 also

java.lang.IllegalStateException: s=HANDLING rs=COMPLETED os=ABORTED is=IDLE awp=false se=false i=false al=0
at org.eclipse.jetty.ee10.servlet.ServletChannelState.completed(ServletChannelState.java:1052)
at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$3(ServletChannel.java:553)
at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:162)
at org.eclipse.jetty.ee10.servlet.HttpOutput.complete(HttpOutput.java:424)
at org.eclipse.jetty.ee10.servlet.ServletContextResponse.completeOutput(ServletContextResponse.java:209)

How do i handle it? This exception is coming from jetty.

@sbordet
Copy link
Contributor

sbordet commented Mar 14, 2024

@at01071988 please update to 12.0.7.

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
Projects
No open projects
Status: ✅ Done
Development

Successfully merging a pull request may close this issue.

5 participants