Bug Report: HTTP2 Protocol Errors when loading many static files

[marcreichman-pfi]

Brief Summary

When updating to recent versions of Payara 6.x and attempting HTTP2, I've observed HTTP2 protocol errors in one of our main applications, which uses HTML, static JS files, and plenty of XHR. I've seen existing tickets (#2625, #5268) deal with similar topics but not this one. It took me a while to get time to make a reproducer but I have made one now.

I believe this is tied to the file cache being turned on, from the trace, which is new to me to see, maybe in the micro environment it logs differently than in the full environment.

Expected Outcome

Page reloads without any issues loading static content when HTTP2 is enabled

Current Outcome

Periodic HTTP2 Protocol Errors, like in this screenshot:

I don't know the exact moment this stack trace came in but it's likely relevant:

[2025-02-19T11:44:40.751-0600] [] [SEVERE] [AS-WEB-CORE-00037] [jakarta.enterprise.web.core] [tid: _ThreadID=160 _ThreadName=http-thread-pool::https-listener(8)] [timeMillis: 1739987080751] [levelValue: 1000] [[
  An exception or error occurred in the container during the request processing
java.lang.ArrayIndexOutOfBoundsException: Index 139 out of bounds for length 133
	at org.apache.naming.resources.ResourceCache.lookup(ResourceCache.java:337)
	at org.apache.naming.resources.ProxyDirContext.cacheLookup(ProxyDirContext.java:1451)
	at org.apache.naming.resources.ProxyDirContext.lookup(ProxyDirContext.java:274)
	at org.apache.catalina.core.ContextsAdapterUtility$NamingContextAdapter.lookup(ContextsAdapterUtility.java:165)
	at org.glassfish.grizzly.http.server.util.Mapper.internalMapWrapper(Mapper.java:1184)
	at org.glassfish.grizzly.http.server.util.Mapper.internalMap(Mapper.java:956)
	at org.glassfish.grizzly.http.server.util.Mapper.map(Mapper.java:793)
	at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:520)
	at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:310)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:239)
	at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:520)
	at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:217)
	at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:190)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515)
	at java.base/java.lang.Thread.run(Thread.java:1583)
]]

Reproducer

You can reproduce this by building the war in this repo and deploying with the preboot file and commandline provided.

https://github.com/marcreichman-pfi/payara-http2-connection-trouble-repro

Instructions will also show up when you load the URL with the index.html

Operating System

Windows 10 Pro / WSL2 / Linux Docker / Windows Server 2022 (seen in several places over the years)

JDK Version

Oracle JDK 21.0.5

Payara Distribution

Payara Micro

[marcreichman-pfi]

Just a hunch, but since HTTP2 requests tend to come in for multiple files at the "exact" same time due to the multiplexing design, it may just be exposing some kind of thread safety issue in the file caching. I don't see many concurrent classes in that code nor any locks or synchronization. Happy to test more.

[marcreichman-pfi]

Additional log content I missed the first time:

[2025-02-19T13:33:57.725-0600] [] [WARNING] [] [org.glassfish.grizzly.http2.Http2SessionOutputSink] [tid: _ThreadID=191 _ThreadName=http-thread-pool::https-listener(39)] [timeMillis: 1739993637725] [levelValue: 900] UNEXPECTED NULL RECORD. Queue-size: 73,818 byteToTransfer=0 queueSizeToFree=0 queueSize=73,818

[2025-02-19T13:33:57.727-0600] [] [WARNING] [] [org.glassfish.grizzly.http2.Http2SessionOutputSink] [tid: _ThreadID=194 _ThreadName=http-thread-pool::https-listener(42)] [timeMillis: 1739993637727] [levelValue: 900] UNEXPECTED NULL RECORD. Queue-size: 147,636 byteToTransfer=0 queueSizeToFree=0 queueSize=147,636

[2025-02-19T13:33:57.728-0600] [] [WARNING] [] [org.glassfish.grizzly.http2.Http2SessionOutputSink] [tid: _ThreadID=195 _ThreadName=http-thread-pool::https-listener(43)] [timeMillis: 1739993637728] [levelValue: 900] UNEXPECTED NULL RECORD. Queue-size: 221,454 byteToTransfer=0 queueSizeToFree=0 queueSize=221,454

[2025-02-19T13:33:57.729-0600] [] [WARNING] [] [org.glassfish.grizzly.http2.Http2SessionOutputSink] [tid: _ThreadID=174 _ThreadName=http-thread-pool::https-listener(22)] [timeMillis: 1739993637729] [levelValue: 900] UNEXPECTED NULL RECORD. Queue-size: 295,272 byteToTransfer=0 queueSizeToFree=0 queueSize=295,272

[marcreichman-pfi]

Here are a few more details:

• I noticed if I leave the file cache in the default setting, which is supposed to be OFF, it still tends to happen. I tried then turning the file cache ON but zeroing out all the settings, and it seemed to reduce the issue quite a bit, but not totally and thus I cannot consider it a workaround. This screenshot from Payara full is just for reference:

• When I tested some more on a payara full instance (not the micro), I got these when I saw the ERR_HTTP2_PROTOCOL_ERROR:

[2025-02-21T09:25:45.514-0600] [Payara 6.2025.1] [WARNING] [] [jakarta.enterprise.web] [tid: _ThreadID=179 _ThreadName=http-thread-pool::http-listener-2(16)] [timeMillis: 1740151545514] [levelValue: 900] [[
  StandardWrapperValve[default]: Servlet.service() for servlet default threw exception
java.io.IOException: Connection is closed
	at org.glassfish.grizzly.nio.NIOConnection.assertOpen(NIOConnection.java:420)
	at org.glassfish.grizzly.http.io.OutputBuffer.write(OutputBuffer.java:613)
	at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:340)
	at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:327)
	at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:158)
	at org.apache.catalina.servlets.DefaultServlet.copy(DefaultServlet.java:2103)
	at org.apache.catalina.servlets.DefaultServlet.serveResource(DefaultServlet.java:989)
	at org.apache.catalina.servlets.DefaultServlet.doGet(DefaultServlet.java:510)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:527)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
	at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1554)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:259)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:166)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:757)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:577)
	at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:158)
	at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:372)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:239)
	at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:520)
	at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:217)
	at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:190)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.io.IOException: Locally closed
]]

It's possible that whether the issue is a caching thread safety bug (and possibly an enabled-state bug?) or something is overloaded connection-wise (I've tested this on different OSes so it's possible that some network stacks behave differently), when the connection unexpectedly drops in Glassfish, the browser shows it as this error?

Unfortunately it happens organically just due to normal static content loads on a web app (js files, css files, etc.) so even though the extreme case makes it happen MORESO, it still happens enough that I cannot use HTTP2 in normal operation with default settings.

Is anyone able to look at this?