[Bug 65118] New: Spurious null pointer exception in Http2UpgradeHandler when reloading web page

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

            Bug ID: 65118
           Summary: Spurious null pointer exception in Http2UpgradeHandler
                    when reloading web page
           Product: Tomcat 9
           Version: 9.0.41
          Hardware: PC
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Catalina
          Assignee: [hidden email]
          Reporter: [hidden email]
  Target Milestone: -----

We have a web application using Tomcat configured to use HTTP/2

Sometimes (about 1 out of 10) when reloading a web page one or more resources
fails to load, typically style.css, with error connection reset reported by web
browser.

In the catalina log file the following it logged:

>27-Jan-2021 16:59:02.435 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry, Connection [2], SocketStatus [OPEN_READ]
>27-Jan-2021 16:59:02.435 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.init Connection [2], State [CONNECTED]
>27-Jan-2021 16:59:02.436 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2Parser.validateFrame Connection [2], Stream [1019], Frame type [HEADERS], Flags [37], Payload size [44]
>27-Jan-2021 16:59:02.436 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [2] Starting pruning of old streams. Limit is [100] + 10% and there are currently [509] streams.
>27-Jan-2021 16:59:02.436 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [2] Pruned completed stream [1]
>27-Jan-2021 17:00:23.798 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [2] Pruned completed stream [3]
>27-Jan-2021 17:00:57.370 FINE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [2] Pruned completed stream [1]
>27-Jan-2021 17:01:18.505 SEVERE [https-openssl-apr-0.0.0.0-8443-exec-2] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Error reading request, ignored
> java.lang.NullPointerException
> at org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams(Http2UpgradeHandler.java:1249)
> at org.apache.coyote.http2.Http2UpgradeHandler.createRemoteStream(Http2UpgradeHandler.java:1129)
> at org.apache.coyote.http2.Http2UpgradeHandler.headersStart(Http2UpgradeHandler.java:1508)
> at org.apache.coyote.http2.Http2Parser.readHeadersFrame(Http2Parser.java:225)
> at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:99)
> at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:71)
> at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:339)
> at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60)
> at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
> at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)
> at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:1991)
> at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)

We see this with multiple web browsers including Chrome (88.0.4324.104) and
Firefox (84.0.2)

Tomcat is configured to use HTTP/2 with default values.

In order to reproduce this issue we continuously reload a web page until issue
occurs.

After examining the logs and the code (Http2UpgradeHandler.java:1249) it seems
to me that the same stream is pruned twice, in the same go, and the second time
its parent is already removed resulting in a NPE due to variable parent is
null.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mark Thomas <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 OS|                            |All

--- Comment #1 from Mark Thomas <[hidden email]> ---
The issue looks like concurrent modification of Http2UpgradeHandler.streams to
me. I think pruning needs to be performed while holding the priorityTreeLock
but I want to try and recreate this to confirm that theory before looking at a
fix.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mark Thomas <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #2 from Mark Thomas <[hidden email]> ---
Fixed in:
- 10.0.x for 10.0.3 onwards
- 9.0.x for 9.0.44 onwards
- 8.5.x for 8.5.63 onwards

7.0.x is not affected.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mattias <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|FIXED                       |---

--- Comment #3 from Mattias <[hidden email]> ---
I have now tested the fix for this issue using SNAPSHOT
tomcat-9.0-20210208.120325-3060.

I am afraid that the fix does not solve the issue. I still get a null pointer
exception at the same place in the code (however other row number 1252).

>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Starting pruning of old streams. Limit is [500] and there are currently [509] streams.
>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Pruned completed stream [1]
>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Pruned completed stream [3]
>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Pruned completed stream [5]
>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Pruned completed stream [7]
>08-Feb-2021 14:07:10.564 FINE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [1] Pruned completed stream [5]
>08-Feb-2021 14:07:10.565 SEVERE [https-openssl-apr-0.0.0.0-8443-exec-34] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Error reading request, ignored
> java.lang.NullPointerException
> at org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams(Http2UpgradeHandler.java:1252)
> at org.apache.coyote.http2.Http2UpgradeHandler.createRemoteStream(Http2UpgradeHandler.java:1129)
> at org.apache.coyote.http2.Http2UpgradeHandler.headersStart(Http2UpgradeHandler.java:1512)
> at org.apache.coyote.http2.Http2Parser.readHeadersFrame(Http2Parser.java:225)
> at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:99)
> at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:71)
> at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:339)
> at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60)
> at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
> at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
> at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:1991)
> at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)

For testing purposes I changed the source code in Http2UpgradeHandler line
1252.

From
> while (toClose > 0 && parent.getIdAsInt() > 0 && parent.getIdAsInt() < stream.getIdAsInt() && parent.getChildStreams().isEmpty()) {
To
>  while (toClose > 0 && parent != null && parent.getIdAsInt() > 0 && parent.getIdAsInt() < stream.getIdAsInt() && parent.getChildStreams().isEmpty()) {
In order to avoid the NPE. This fix solved the issue. At least no NPE was
thrown and no problem with loading resources could be seen in the web browsers.
I hope this can help you pin point the root cause.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

--- Comment #4 from Mark Thomas <[hidden email]> ---
That patch looks to be tackling the symptom rather than the root cause. My
concern is that the root cause may trigger other errors.

What would really help here is a test case (ideally a simple WAR) that
demonstrates the issue.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

--- Comment #5 from Mattias <[hidden email]> ---
(In reply to Mark Thomas from comment #4)
> That patch looks to be tackling the symptom rather than the root cause. My
> concern is that the root cause may trigger other errors.
>
> What would really help here is a test case (ideally a simple WAR) that
> demonstrates the issue.

I understand. I will try to create a test case that you can use.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mark Thomas <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|REOPENED                    |NEEDINFO

--- Comment #6 from Mark Thomas <[hidden email]> ---
Moving to NEEDINFO as we need a test case for this.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mark Thomas <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEEDINFO                    |NEW

--- Comment #7 from Mark Thomas <[hidden email]> ---
Woot! I managed to trigger this locally just with Tomcat's default home page.
Investigating...

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

https://bz.apache.org/bugzilla/show_bug.cgi?id=65118

Mark Thomas <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
         Resolution|---                         |FIXED
             Status|NEW                         |RESOLVED

--- Comment #8 from Mark Thomas <[hidden email]> ---
Found it. The priority hierarchy was being corrupted when a closed stream was
replaced with a RecycledStream instance.

Fixed in:
- 10.0.x for 10.0.3 onwards
- 9.0.x for 9.0.44 onwards
- 8.5.x for 8.5.63 onwards

7.0.x is not affected.

--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]