WebFlux with Tomcat, intermittent timeout when creating response

[danielra]

Affects: \5.1.7.RELEASE

---

I am running a spring-boot application which is using WebFlux with Tomcat as the underlying http server. In my real application with fairly high request rate, I noticed in metrics what appeared to be a slow leak in tomcat connections. I have since added a WebFilter to implement a response timeout, and this confirmed that a low volume of responses were never being completed. With the WebFilter in place, the observed connection leak is fixed - but I would like to resolve the response timeouts.

I have created a relatively simple isolated demo project which reproduces the issue here: https://github.com/danielra/webflux_response_timeout_repro

The project can be built via ./gradlew clean build and then run via java -jar ./build/libs/demo-0.0.1-SNAPSHOT.jar. To reproduce the issue with the demo project I have then been using wrk ( https://github.com/wg/wrk ) to throw load against the running application.

For example:

$ ./wrk -c 20 -t 16 -d 300 http://localhost:8080/get --latency
Running 5m test @ http://localhost:8080/get
  16 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.04ms    5.38ms 335.15ms   98.55%
    Req/Sec     1.62k   280.92     4.75k    79.07%
  Latency Distribution
     50%  508.00us
     75%  762.00us
     90%    2.00ms
     99%    7.48ms
  7719452 requests in 5.00m, 28.98GB read
  Socket errors: connect 0, read 7, write 0, timeout 1
Requests/sec:  25723.26
Transfer/sec:     98.89MB

Note that for this 5 minutes of load, 1 timeout was observed. The corresponding application console output was as follows:

$ java -jar ./build/libs/demo-0.0.1-SNAPSHOT.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.5.RELEASE)

2019-06-06 16:41:14.795  INFO 18437 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on machine1 with PID 18437 (/home/daniela/webflux_response_timeout_repro/demo/build/libs/demo-0.0.1-SNAPSHOT.jar started by daniela in /home/daniela/webflux_response_timeout_repro/demo)
2019-06-06 16:41:14.798  INFO 18437 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2019-06-06 16:41:15.642  INFO 18437 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-06-06 16:41:15.676  INFO 18437 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-06-06 16:41:15.676  INFO 18437 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.19]
2019-06-06 16:41:16.229  INFO 18437 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-06-06 16:41:16.231  INFO 18437 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.772 seconds (JVM running for 2.188)
Response timeout after 10001 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
2019-06-06 16:46:09.230 ERROR 18437 --- [io-8080-exec-12] o.s.w.s.adapter.HttpWebHandlerAdapter    : [67fec09] Error [java.lang.IllegalStateException: Async operation timeout.] for HTTP GET "/get", but ServerHttpResponse already committed (200 OK)
2019-06-06 16:46:09.238 ERROR 18437 --- [io-8080-exec-12] o.a.c.c.C.[.[.[/].[httpHandlerServlet]   : Servlet.service() for servlet [httpHandlerServlet] threw exception

java.lang.IllegalStateException: Async operation timeout.
        at org.springframework.http.server.reactive.ServletServerHttpResponse$ResponseAsyncListener.onTimeout(ServletServerHttpResponse.java:208) ~[spring-web-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
        at org.apache.catalina.core.AsyncListenerWrapper.fireOnTimeout(AsyncListenerWrapper.java:44) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:133) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:153) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:241) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:836) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1747) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]

2019-06-06 16:46:09.239 ERROR 18437 --- [io-8080-exec-12] o.a.c.c.C.[.[.[/].[httpHandlerServlet]   : Servlet.service() for servlet [httpHandlerServlet] in context with path [] threw exception [Failed to create response content] with root cause

java.lang.IllegalStateException: Async operation timeout.
        at org.springframework.http.server.reactive.ServletServerHttpResponse$ResponseAsyncListener.onTimeout(ServletServerHttpResponse.java:208) ~[spring-web-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
        at org.apache.catalina.core.AsyncListenerWrapper.fireOnTimeout(AsyncListenerWrapper.java:44) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:133) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:153) ~[tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:241) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:836) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1747) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.19.jar!/:9.0.19]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]

The line Response timeout after 10001 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'. is from the WebFilter included in the demo project. In this case there was also an apparently corresponding IllegalStateException logged, though in other runs I don't always see this sort of exception logged when the WebFilter's log line appears.

For quick reference, the Controller method which handles the relevant requests in the demo project can be seen here: https://github.com/danielra/webflux_response_timeout_repro/blob/master/src/main/java/com/example/demo/controller/DemoController.java#L30
And the WebFilter that implements the response timeout can be seen here: https://github.com/danielra/webflux_response_timeout_repro/blob/master/src/main/java/com/example/demo/filter/DemoWebFilter.java#L25

Note that while the timeout is set to 10 seconds in this example, the responses seem to never be completed regardless of how long is waited. Apparently leaked tomcat connections could be observed building up for more than a week in my real application's metrics.

Please let me know if there is anything additional from my end that would be helpful in understanding and resolving this issue. Thank you for your time!

[danielra]

As another data point, if I change the Controller get method from the above linked demo project to instead look like the following (leaving the rest of the project the same):

    @RequestMapping(method = RequestMethod.GET, value = "/get", produces = "application/json")
    @ResponseStatus(HttpStatus.OK)
    public Mono<List<Integer>> get() {
        return Mono.fromFuture(CompletableFuture.supplyAsync(this::getIntList))
            .timeout(Duration.ofMillis(50))
            .doOnError(TimeoutException.class, (t) -> System.out.println("The Mono.fromFuture timed out!"));
    }

Running load against the endpoint for 1 hour produced the following output:

From wrk (showing 13 timeout events):

$ ./wrk -c 20 -t 16 -d 3600 http://localhost:8080/get
Running 60m test @ http://localhost:8080/get
  16 threads and 20 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     0.93ms    2.11ms 326.29ms   92.06%
    Req/Sec     1.92k   367.55     3.91k    68.93%
  109568338 requests in 60.00m, 409.52GB read
  Socket errors: connect 0, read 33, write 0, timeout 13
Requests/sec:  30434.94
Transfer/sec:    116.48MB

And from the application console output:

$ java -jar ./build/libs/demo-0.0.1-SNAPSHOT.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.5.RELEASE)

2019-06-11 11:55:04.255  INFO 25847 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on machine1 with PID 25847 (/home/daniela/webflux_response_timeout_repro/demo/build/libs/demo-0.0.1-SNAPSHOT.jar started by daniela in /home/daniela/webflux_response_timeout_repro/demo)
2019-06-11 11:55:04.258  INFO 25847 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2019-06-11 11:55:05.080  INFO 25847 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2019-06-11 11:55:05.113  INFO 25847 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-06-11 11:55:05.113  INFO 25847 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.19]
2019-06-11 11:55:05.666  INFO 25847 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-06-11 11:55:05.669  INFO 25847 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.758 seconds (JVM running for 2.181)
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
Response timeout after 10000 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.

This output appears to indicate that no timeouts occurred (even with the much tighter 50ms timeout) on the Mono instances returned by the Controller get method - but that still in 13 cases the Mono returned by the webFilterChain.filter(serverWebExchange) call in the WebFilter timed out after 10 seconds.

[danielra]

I tried changing the demo project dependencies to use the Netty based server and the Jetty server, and neither saw any repros in hour-long runs.

I also tried updating the demo project dependencies to build against the 2.2.0.M3 spring-boot versions, and still observed the timeouts when using Tomcat as the server.

[rstoyanchev]

First, on WebFlux we make sure the Servlet container doesn't timeout. So you do need to insert a timeout operator somewhere (filter or controller) if request handling might not complete.

The stacktrace shows Tomcat is performing an async dispatch. This happens only in case of a request handling error after the response is committed. In that case we have to dispatch briefly back into the container in order to raise the error from the container thread.

The problem I think is that the onError handler where we dispatch sets the internal isCompleted flag and then when we are notified by the Servlet container of the error we raised, the flag is already set which prevents calling onComplete.

This is all a little convoluted but it's how the Servlet API works. It's possible that Jetty just handles it better and Reactor Netty is completely different.

[danielra]

Interesting. Thank you for taking a look!

For reference, having run the demo many more times with various small changes now, I have only very rarely seen the IllegalStateException shown in my initial report here. Most frequently in repro cases I just see the response timeout message printed by the WebFilter (as well as corresponding timeouts observed by the client sending requests to the server).

[rstoyanchev]

Actually the current behavior is based on #20600. The issue was with a chunked response that fails in the middle of being written, and the client doesn't realize there was a failure because the response just ends with a zero chunk. The change made is explained here:

If the error is an IOError the server will know about it but if it comes from the [response data] publisher, I'm not sure what we can do, besides call AsyncContext#complete(). Possibly dispatch back into a container thread and then raise an exception, which the container would turn into an AsyncListener.onError notification which we would have to leave unhandled.

At this point I'm back to not being sure what root cause is. Perhaps Tomcat isn't performing the async dispatch or failing to dispatch (as in the above stacktrace) leaving the response incomplete. Turning up logging for org.springframework.http.server.reactive.ServletHttpHandlerAdapter to TRACE could help. Also how are you checking for connection leak, i.e. what metric is it? Also if you could use a logger in the WebFilter along with a logPrefix from the ServerWebExchange that would help correlate its messages.

[danielra]

I've updated to used a logger in the WebFilter and added a couple new log calls as well as enabling TRACE level logging for org.springframework.http.server.reactive.ServletHttpHandlerAdapter as suggested (the project with these updates applied can be seen on an additional_logging branch of the demo project here: https://github.com/danielra/webflux_response_timeout_repro/tree/additional_logging ). Here are the relevant log lines from a particular response timeout occurrence correlated via the logPrefix value:

$ find . -name \*.gz -print0 | xargs -0 zgrep "6dd89adc"
./log.txt.2019-06-18.0.gz:2019-06-18 16:22:58.227  INFO 6518 --- [http-nio-8080-exec-18] com.example.demo.filter.DemoWebFilter    : [6dd89adc] Incoming request observed.
./log.txt.2019-06-18.0.gz:2019-06-18 16:22:58.227  INFO 6518 --- [http-nio-8080-exec-18] c.e.demo.controller.DemoController       : [6dd89adc] Controller called.
./log.txt.2019-06-18.0.gz:2019-06-18 16:22:58.228  INFO 6518 --- [ForkJoinPool.commonPool-worker-3] c.e.demo.controller.DemoController       : [6dd89adc] Flux returned from Controller doOnComplete called.
./log.txt.2019-06-18.5.gz:2019-06-18 16:23:08.229 ERROR 6518 --- [parallel-5] com.example.demo.filter.DemoWebFilter    : [6dd89adc] Response timeout after 10001 milliseconds for GET request with uri 'http://localhost:8080/get'. Response status code was already committed: '200 OK'.
./log.txt.2019-06-18.5.gz:2019-06-18 16:23:08.229 TRACE 6518 --- [parallel-5] o.s.h.s.r.ServletHttpHandlerAdapter      : [6dd89adc] Handling completed

Based on the timing, it looks like the only relevant log line from org.springframework.http.server.reactive.ServletHttpHandlerAdapter was noting that handling was completed after the WebFilter had timed out.

Regarding your question about the metric where the mentioned apparent connection leak was observed, this was in a metric emitted by the application with a value based on Tomcat's connectionCount mbean. Again, this apparent leak went away when the WebFilter with timeout was added to ensure request handling eventually completed.

[rstoyanchev]

So perhaps that's all it is then, i.e. making sure request handling does complete? It would be useful to know what part of the chain doesn't complete but aside from that nothing to fix here then.

[danielra]

I'm not sure I follow. As I understand it, the logging seems to indicate that the Flux returned by the handler method in the Controller completed immediately following the handler method being called - but then ~10 seconds later the Mono<Void> that the timeout WebFilter received from its WebFilterChain.filter call still hadn't completed - so, it timed out. What code between the timeout WebFilter and the Controller handler method should have been responsible for completing the Mono<Void> received from down the filter chain in this case? My expectation was that as soon as the Publisher returned by the Controller handler method completed, an attempt should be made to complete/emit the response - which should either succeed or fail, and in either case the Mono received from down the filter chain should eventually terminate.

[rstoyanchev]

Okay I see what you mean. Meanwhile I uncovered #23175 coincidentally and I think it may be related to this issue.

[rstoyanchev]

I wasn't able to dig deeper, and since I don't know that the cause is or whether it's feasible to apply to 5.1.x, I've moved it to 5.2 RC2 for now.

[danielra]

Alright. Thank you for the update. I will try to find some time to dig deeper from my end to try to better understand what is going wrong.

[rstoyanchev]

I suspect something something in the Servlet 3.1 reactive bridge, i.e. the classes used by ServletServerHttpResponse to write to the reponse, since it happens after the controller and before the filter.

[danielra]

Thanks for the pointer. I finally had some time yesterday to dig deeper here, and I believe I have identified the race that is responsible for this issue. It occurs in spring-web/src/main/java/org/springframework/http/server/reactive/AbstractListenerWriteProcessor.java where onComplete can be called on the WRITING or RECEIVED State during execution of the RECEIVED State's onWritePossible method such that processor.subscriberCompleted is set to true after it has already been referenced and observed to be false in onWritePossible leading to the writingPaused branch of logic and indefinite waiting in the REQUESTED State.

A quick fix I applied via synchronization to hopefully make the issue clear can be seen here: danielra@02dfda2

With this fix in place, I ran load against my demo repro project for 15 hours (1,186,638,734 requests) without any repros of the response timeout issue. Whereas in contrast without this fix I typically see multiple repros within a 5 minute run.

[rstoyanchev]

Indeed it looks like there is a race. Thanks for narrowing it down!

I think we can avoid the synchronization blocks. I'll experiment with that. There are also a few similar flags in other related classes, on the reading side and for writing with flush boundaries. Those will also need similar updates.

[rstoyanchev]

Okay, I've come up with something. Give it a try with 5.1.10 snapshots once the build is complete. I ran for 10 minutes with no timeout errors (previously 5 min was giving a timeout consistently).

[danielra]

Great. I'll this out once a snapshot version is available with this change included. Thanks!

[danielra]

I had a chance to test this out. I ran a 15 hour test against the 5.1.10.BUILD-SNAPSHOT version with no response timeout occurrences. So, this looks good to me. Thanks! I am looking forward to the release!

[rstoyanchev]

Thanks for the time to report, debug, and test!