Affects versions: Spring Boot 2.1.8, Spring Boot 2.2.0M6
O/S: Mac 10.12, Also manifests in docker container on various platforms.
Description
Specifically for Spring Webflux, when the response for an actuator endpoint has a length over 8192, the responses sometimes fail. When the failure occurs, it appears that rather than sending the complete response, the first 8192 bytes are sent, and the connection is subsequently terminated. The failure does not occur on every request, but with significant frequency.
This problem was first observed when using Prometheus metrics registry and Spring Actuator in conjunction. Using the default metrics set, querying of the scrape endpoint will eventually result in an error. Using a JMeter client, the response is:
Thread Name: promtest-ThreadStarter 1-9
Sample Start: 2019-10-01 12:00:13 PDT
Load time: 6
Connect Time: 1
Latency: 5
Size in bytes: 1315
Sent bytes:0
Headers size in bytes: 0
Body size in bytes: 1315
Sample Count: 1
Error Count: 1
Data type ("text"|"bin"|""): text
Response code: Non HTTP response code: org.apache.http.ConnectionClosedException
Response message: Non HTTP response message: Premature end of Content-Length delimited message body (expected: 9,000; received: 8,042)
HTTPSampleResult fields:
ContentType: application/vnd.spring-boot.actuator.v2+json;charset=UTF-8
DataEncoding: UTF-8
In the logs, the following can be observed:
2019-10-01 12:00:13.587 ERROR 98826 --- [nio-8080-exec-2] o.a.coyote.http11.Http11NioProtocol : Error reading request, ignored
java.lang.IllegalStateException: Calling [asyncOperation()] is not valid for a request with Async state [COMPLETING]
at org.apache.coyote.AsyncStateMachine.asyncOperation(AsyncStateMachine.java:269) ~[tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:203) ~[tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) ~[tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:834) ~[tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.16.jar:9.0.16]
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.16.jar:9.0.16]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
2019-10-01 12:00:13.587 INFO 98826 --- [nio-8080-exec-2] o.a.catalina.connector.CoyoteAdapter : Encountered a non-recycled request and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException: null
at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:525) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.http11.Http11Processor.recycle(Http11Processor.java:1322) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1016) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:984) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415) [tomcat-embed-core-9.0.16.jar:9.0.16]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.16.jar:9.0.16]
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.16.jar:9.0.16]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Steps to reproduce
- Using Spring initializer, generate a project with the following parameters:
- Gradle project, Kotlin, Spring boot 2.1.8, Add "Spring Reactive Web" and "Spring Boot Actuator".
- Add the following dependencies to
build.gradle.kts:implementation("org.springframework.boot:spring-boot-starter-tomcat")
- Add the following endpoint in
DemoApplication.kt: ``` @WebEndpoint(id = "test") @Component class PrometheusScrapeEndpoint { @ReadOperation fun test(): String { return "a".repeat(8193) } }
4. Expose the created endpoint using the following configuration:
- `management.endpoints.web.exposure.include=test`
5. Run the app, verify tomcat is being used.
6. Make requests to the `/actuator/test` endpoint. For this, I used JMeter @ 10rps and hit the above error repeatedly within a few seconds.
For your convenience, I've attached a demo app that manifest this issue.
**Notes**
- This issue seems specific to Tomcat -- I see no problems when using Netty.
- The latest non-manifesting Spring Boot version is `2.1.4`.
- I can reproduce this on `2.2.0-M6`, but not, for example, on `2.2.0-M1`
- Pinning the Tomcat version to, say, `9.0.16` (Spring Boot `2.1.4` version) does not appear to help
- I explored changing various configuration settings for Tomcat, to no avail.
**Sample app with issue**
[demo.zip](https://github.com/spring-projects/spring-framework/files/3678162/demo.3.zip)
Let me know if there's any additional information / help required to debug this issue. Thanks for your attention.
**Comment From: rstoyanchev**
Could you try with Boot 2.1.9 which is now available and based on Spring Framework 5.1.10 which does include a couple of fixes in the Servlet - Reactive Streams adapters. Another thing to confirm is whether varying the Spring Framework version only can make the issue appear and go away.
**Comment From: erikbeerepoot**
@rstoyanchev Thanks for your attention. Just tried with Spring Boot 2.1.9. Took around ~15 cURL requests for the issue to appear -- same symptoms as listed above. Happy to try varying the spring framework alone, but it does look look it actually pulled in 5.1.10, so I imagine that's not much use.
**Comment From: rstoyanchev**
Boot invokes actuator endpoints with a sync method signature from a different thread to avoid blocking the server thread. If I change to non-blocking signature it works fine:
```kotlin
@ReadOperation
fun test(): Mono<String> {
return Mono.just("a".repeat(8193))
}
So it seems to be related to that thread switch. An exception I see when writing from the Reactor scheduler thread:
java.lang.IllegalArgumentException: null
at java.nio.Buffer.position(Buffer.java:244) ~[na:1.8.0_242]
at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:210) ~[na:1.8.0_242]
at org.apache.tomcat.util.net.SocketWrapperBase.transfer(SocketWrapperBase.java:1517) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.tomcat.util.net.SocketWrapperBase.writeNonBlockingInternal(SocketWrapperBase.java:683) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.tomcat.util.net.SocketWrapperBase.writeNonBlocking(SocketWrapperBase.java:660) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:503) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:538) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:73) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:190) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.coyote.Response.doWrite(Response.java:601) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:339) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.OutputBuffer.appendByteBuffer(OutputBuffer.java:765) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:729) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:404) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:375) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:105) ~[tomcat-embed-core-9.0.24.jar:9.0.24]
at org.springframework.http.server.reactive.TomcatHttpHandlerAdapter$TomcatServerHttpResponse.writeToOutputStream(TomcatHttpHandlerAdapter.java:226) ~[spring-web-5.1.9.RELEASE.jar:5.1.9.RELEASE]
Debugging in HeapByteBuffer I see it's trying to write the first 8042 bytes but the target has a limit of 150 and that causes the IllegalArgumentException. I suspect a Tomcat issue here because the input buffer we passed in is fine, and from there it's all Tomcat taking slices from that as needed.
The same issue cannot be reproduced with Netty, Jetty, and Undertow.
Switching to Boot 2.2.5 (Tomcat 9.0.31) works and likewise Boot 2.1.13 on same version of Tomcat also works without errors. I see a lot of buffer related fixes in SocketWrapperBase that probably fixed this.