InMemoryWebSessionStore indirectly causing infinite loop inside tomcat-native OpenSSL under load

[philsttr]

This is a fun one....

When load testing a new app using...

• Spring Boot 2.4.2
• WebFlux 5.3.3
• Spring Security 5.4.2
• Tomcat 9.0.41
• tomcat-native 1.2.25
• APR 1.6.5
• OpenSSL 1.1.1f

...CPU utilization will max out, and stay maxed out even after the load test completes.

When investigating, I found that threads in the global boundedElastic Scheduler are consuming the entire CPU, as seen in top (broken out by threads)...

top - 17:56:42 up 12 min,  0 users,  load average: 0.61, 0.24, 0.15
Threads: 112 total,   3 running, 109 sleeping,   0 stopped,   0 zombie
%Cpu(s): 53.8 us,  0.3 sy,  0.0 ni, 45.7 id,  0.0 wa,  0.0 hi,  0.1 si,  0.1 st
MiB Mem :  11852.9 total,   8478.8 free,   1267.9 used,   2106.2 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.  10278.6 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  212 bogus     20   0 6635460 493008  18064 R  99.9   4.1   0:07.44 boundedElastic-  <--- CPU maxed out
  170 bogus     20   0 6635460 493008  18064 R  99.7   4.1   0:21.02 boundedElastic-  <--- CPU maxed out
   17 bogus     20   0 6635460 493008  18064 S   9.6   4.1   0:26.19 C2 CompilerThre
  235 bogus     20   0 6635460 493008  18064 S   1.3   4.1   0:00.13 boundedElastic-
   18 bogus     20   0 6635460 493008  18064 S   0.7   4.1   0:04.61 C1 CompilerThre
  234 bogus     20   0 6635460 493008  18064 S   0.7   4.1   0:00.79 boundedElastic-
   85 bogus     20   0    9416   2340   1468 R   0.7   0.0   0:00.43 top
   36 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.39 https-openssl-n
   47 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:01.70 https-openssl-n
  166 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.77 parallel-4
  167 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.15 https-openssl-n
  175 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.11 https-openssl-n
  179 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.09 https-openssl-n
  184 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.11 https-openssl-n
  192 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.09 https-openssl-n
  204 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.09 https-openssl-n
  210 bogus     20   0 6635460 493008  18064 S   0.3   4.1   0:00.10 https-openssl-n
...

Taking a stackdump of the process reveals the two threads are inside tomcat's OpenSSLEngine...
(note that nid=0xd4 correlates to PID 212 above)

"boundedElastic-8" #86 daemon prio=5 os_prio=0 cpu=128128.31ms elapsed=215.53s allocated=28746K defined_classes=1 tid=0x00007fee00035800 nid=0xd4 runnable  [0x00007fed91cbe000]
   java.lang.Thread.State: RUNNABLE
	at org.apache.tomcat.util.net.openssl.OpenSSLEngine.unwrap(OpenSSLEngine.java:603)
	- locked <0x00000007576d7df8> (a org.apache.tomcat.util.net.openssl.OpenSSLEngine)
	at javax.net.ssl.SSLEngine.unwrap(java.base@11.0.9.1/SSLEngine.java:637)
	at org.apache.tomcat.util.net.SecureNioChannel.read(SecureNioChannel.java:617)
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1229)
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1141)
	at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:795)
	at org.apache.coyote.http11.Http11InputBuffer.available(Http11InputBuffer.java:675)
	at org.apache.coyote.http11.Http11Processor.available(Http11Processor.java:1201)
	at org.apache.coyote.AbstractProcessor.isReadyForRead(AbstractProcessor.java:838)
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:577)
	at org.apache.coyote.Request.action(Request.java:432)
	at org.apache.catalina.connector.InputBuffer.isReady(InputBuffer.java:305)
	at org.apache.catalina.connector.CoyoteInputStream.isReady(CoyoteInputStream.java:201)
	at org.springframework.http.server.reactive.ServletServerHttpRequest$RequestBodyPublisher.checkOnDataAvailable(ServletServerHttpRequest.java:295)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.changeToDemandState(AbstractListenerReadPublisher.java:222)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.access$1000(AbstractListenerReadPublisher.java:48)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State$2.request(AbstractListenerReadPublisher.java:333)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$ReadSubscription.request(AbstractListenerReadPublisher.java:260)
	...

In a debug session, I discovered that an infinite loop is executing in tomcat's OpenSSLEngine.unwrap where:

• pendingApp = 2
• idx = 1
• endOffset = 1
• capacity = 16384

I would have expected the OpenSSL I/O code to execute on one of the https-openssl-nio-* threads, not the boundedElastic Scheduler. Therefore, I started investigating why this code was executing on the boundedElastic Scheduler.

After more debugging I narrowed it down to InMemoryWebSessionStore.createWebSession().
This is the only location in this particular app that uses the boundedElastic Scheduler.

The WebSession is being created because Spring Security's WebSessionServerRequestCache is being used, which persists requests in the WebSession.

If I disable the request cache (which removes the usage of WebSession, which removes the call to InMemoryWebSessionStore.createWebSession(), which removes usage of boundedElastic), then all I/O is performed on the https-openssl-nio-* threads, and the infinite loop does not occur.

I haven't fully investigated why the infinite loop occurs, but I assume there is a threadsafety bug somewhere in tomcat's OpenSSLEngine. (Either that or it was never intended to be used from multiple threads.) Having said that, I don't think that the I/O should be occurring on the boundedElastic thread, so I did not investigate further.

In other words, in my opinion, using InMemoryWebSessionStore should not cause the OpenSSL I/O to occur on a boundedElastic thread.

I have attached a simple application that can be used to reproduce the problem.
After extracting, use docker-compose up to build and start a container with the spring boot app with the above configuration.
Sending a lot of load (>= 2000 calls per second) to the /echo endpoint will reproduce the infinite loop.
However, you can see OpenSSL I/O occurring on the boundedElastic threads with any amount of load.

[philsttr]

I just found spring-projects/spring-security#9200, which also discusses threading concerns when using InMemoryWebSessionStore

[rstoyanchev]

The use of Schedulers.boundedElastic() was introduced in #24027 to avoid blocking in UUID#random reported by Blockhound. We could make it conditional on Schedulers#isInNonBlockingThread() which is false on Tomcat and it wouldn't cause Blockhound violations but as Tomcat uses a limited number of threads for NIO, the issues with potential blocking remains even if Blockhound would no longer report it as a violation.

In other words we have to get off Tomcat's thread and there is no way to get back on it that I can see, so one way or another this should probably be looked at in Tomcat, assuming the loop is in Tomcat code.

At best we could switch back to a thread marked as "non-blocking" via Schedulers.parallel(), which would help spring-projects/spring-security#9200 by not masking other issues with blocking, but it probably won't help with the issue here.

[philsttr]

Yeah, it's a tricky situation since the JVM doesn't have a non-blocking way to retrieve random data.

I feel like the infinite loop is a pretty serious problem, since Spring Security + WebFlux + Tomcat + OpenSSL is a fairly common (I think?) combination, and it easily occurs "out-of-the-box".

I agree that we should probably get the tomcat folks to take a look. I just found https://bz.apache.org/bugzilla/show_bug.cgi?id=64771, which appears to be the same problem. Unfortunately it is currently closed due to inactivity. I'll comment there.

[markt-asf]

I'm unable to recreate this issue with the provided sample application. I'm running the app locally rather than via Docker, I'm using Tomcat Native 1.1.26 rather than 1.1.25 (should not impact this) and my local development build of OpenSSL 3.0.x. Load is running at > 6k req/s.
Threading issues are notoriously susceptible to small timing differences. I'll see if I can get anywhere via code inspection. I might also try with the OpenSSL 1.1.1 branch. Any suggestions on how to improve the reliability of the test case?
I do see occasional errors such as this:
2021-01-21 12:09:19.878 ERROR 25774 --- [nio-8443-exec-1] o.s.w.s.adapter.HttpWebHandlerAdapter : [63c84439] Error [java.io.IOException: The current thread was interrupted] for HTTP POST "/echo", but ServerHttpResponse already committed (200 OK)
That does make me wonder whether the application and/or the libraries it is using are following the requirements regarding thread safety set out in section 2.3.3.4 of the Servlet spec.

[markt-asf]

A code review strongly suggests that the root cause is the non-container thread attempting to read from the socket after the container has completed the request and recycled the various objects. This appears to be consistent with the error message in my previous comment.
One of the effects of recycling the request is that the buffer associated with the Http11InputBuffer has its limit and position set to zero. What I think is happening is:

• at the start of unwrap() the single ByteBuffer is empty (pos=0, limit=16384)
• the non-container thread records the capacity at line 517 as 16384
• the container recycles the connection (capacity drops to zero but non-container thread is unaware of the change)
• non-container thread enters an infinite loop around 569-606 due to the inconsistent state

[markt-asf]

Probably an outside chance but the root cause might be a bug in Tomcat's async error handling that has been fixed since 9.0.41. Since I can't repeat the failure with this test case, it might be worth trying to rebuild the test case with a 9.0.x snapshot from https://repository.apache.org/content/groups/snapshots/

[philsttr]

Thanks for investigating @markt-asf ! I'll take a look at the snapshot, and I'll experiment more to try to narrow down how to best reproduce. As you can imagine, I was experimenting with lots of different variables, so there might be some cases where it reproduces more easily. I'll get back with my results.

[philsttr]

I was able to reproduce this more easily with JSON payloads, whereas the original app used text/plain payloads. I don't think it is anything specific to JSON, but perhaps the serialization/deserialization adds subtle timing differences or something. Anyway, here's an updated project that handles JSON.

My load tests used the following request (note that any basic auth creds will work):

POST /echo HTTP/1.1
Host: yourhost:8443
Authorization: Basic Zm9vOmJhcg==
Accept: */*
Content-type: application/json
Content-Length: 22

{"echo":"Hello World"}

I haven't tried the latest tomcat snapshots yet. Will try that next.

[markt-asf]

Thanks but no success so far here. How long does the test need to run before you see the issue?

[philsttr]

Usually reproduces within a few mins.

[philsttr]

I was able to reproduce the infinite loop with the latest tomcat 9.0-SNAPSHOT (reported as 9.0.42-dev on startup). tomcat-ssl-snaphot.zip

In addition, in each run, the app would eventually stop responding to requests during the load test. On some runs, the exception below was reported. However, this exception is not reported during every run, even though the app stopped responding on every run. I did not encounter the exception or the app stopping responding with 9.0.41.

2021-01-21 19:34:21.615 ERROR 1 --- [nio-8443-exec-7] o.apache.coyote.http11.Http11Processor   : Error finishing request

java.lang.IllegalArgumentException: newPosition < 0: (-16362 < 0)
        at java.base/java.nio.Buffer.createPositionException(Buffer.java:318) ~[na:na]
        at java.base/java.nio.Buffer.position(Buffer.java:293) ~[na:na]
        at java.base/java.nio.ByteBuffer.position(ByteBuffer.java:1086) ~[na:na]
        at java.base/java.nio.ByteBuffer.position(ByteBuffer.java:262) ~[na:na]
        at org.apache.coyote.http11.Http11InputBuffer.endRequest(Http11InputBuffer.java:645) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1132) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.coyote.http11.Http11Processor.dispatchEndRequest(Http11Processor.java:1093) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:263) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:887) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1691) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0-SNAPSHOT.jar!/:9.0.42-dev]
        at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

Ideas on where to go from here? Can you try using the docker image I provided to ensure we're testing the exact same app? Any additional debugging I can do or data I can provide on my side?

[markt-asf]

I'm unable to reproduce this after 20 mins. That stack trace is consistent with not following Servlet 2.3.3.4. Given the simplicity of the application, this looks like a library issue at the moment rather than a container issue.

[rstoyanchev]

Thanks for the details @markt-asf.

This is a WebFlux application where the Servlet calls startAsync, registers an ReadListener/WriteListener, and then handles in a Reactive Streams pipeline in stages. It is well protected in respect to Servlet 2.3.3.4 through the use of Project Reactor and our own Servlet to Reactive Streams bridge. Save for any bugs, there should be no concurrent access to the request or response, nor any access after the request completes.

As you said it is a basic scenario. Based on your analysis from Tomcat and mine at the framework level, I suspect a race between the request completing (perhaps with some exceptional reason), and an attempt to read the body as part of handling. @philsttr it could help to know what happens to the request (i.e. why is it complete when we are trying to read the body) perhaps through org.springframework.web and ``org.springframework.http` logging. Unfortunately I have not reproduced it yet either.

From the stacktrace in AbstractListenerReadPublisher i see a reactive streams signal request to read from the request body. This is within a state machine that would not allow this to happen if the request has already completed. However I am now wondering what happens, or rather what should happen, if this attempt to read crosses with a notification from the Servlet container that the request has ended somehow (e.g. connection lost?) where the latter arrives second.

In other words say the application is about to read from the request body and wants to call request.getInputStream().isReady(). Meanwhile it may receive an AsyncListener callback for an error. I don't see a way we can guarantee we will not call isReady() if the request completes in a parallel. A check for whether the request is complete just before the call to isReady would not be sufficient and still leaves the possibility for a race. What do you think?

[rstoyanchev]

@philsttr note a recent change #26434 in this area of the code. It probably won't solve it but worth checking. Are you able to reproduce with more logging, e.g. org.springframework.web at DEBUG, to see what happens for such a request? I suspect a request is getting terminated from the client side and the connection getting closed races with the application trying to handle. There are also TRACE level loggers in the Servlet / Reactive Streams bridge, like the output (and log settings) under #26434.

@markt-asf I'm still interested in your feedback. In Servlet 3.1 non-blocking I/O, how can an application or framework guarantee no residual calls to ServletInputStream#isReady immediately after the request ends? We are generally protected against doing anything when the request has ended but in a race, the request could end immediately after such checks and before the call to isReady().