I found a probably bug with http2 handling in spring-boot-starter-tomcat.
When I sending HTTP2 POST request with big payload I see below exception. This request is OK when I use Undertow for example or Tomcat with HTTP1.1
I prepared test where you can recreate this problem. Here is link https://github.com/zulk666/demo-http2 To start the demo you have to run com.example.demo.DemoApplication first then run test DemoApplicationTests.
org.apache.coyote.http2.ConnectionException: Invalid frame type [HEADERS]
at org.apache.coyote.http2.FrameType.check(FrameType.java:64) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2Parser.validateFrame(Http2Parser.java:654) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser$FrameCompletionHandler.validate(Http2AsyncParser.java:213) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser$FrameCompletionHandler.callHandler(Http2AsyncParser.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1042) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1556) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase$OperationState.start(SocketWrapperBase.java:1016) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.vectoredOperation(SocketWrapperBase.java:1427) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1270) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1242) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser.readFrame(Http2AsyncParser.java:137) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2Parser.readFrame(Http2Parser.java:71) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:332) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.upgradeDispatch(Http2AsyncUpgradeHandler.java:39) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser$PrefaceCompletionHandler.completed(Http2AsyncParser.java:124) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser$PrefaceCompletionHandler.completed(Http2AsyncParser.java:60) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1064) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1556) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase$OperationState.start(SocketWrapperBase.java:1016) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.vectoredOperation(SocketWrapperBase.java:1427) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1270) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1242) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncParser.readConnectionPreface(Http2AsyncParser.java:55) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2UpgradeHandler.init(Http2UpgradeHandler.java:239) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.init(Http2AsyncUpgradeHandler.java:39) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:314) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.upgradeDispatch(Http2AsyncUpgradeHandler.java:39) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
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.31.jar:9.0.31]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Here is DEBUG log from this request
2020-02-28 13:28:00.922 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Local(client->server)], Parameter type [3] set to [100]
2020-02-28 13:28:00.923 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Local(client->server)], Parameter type [4] set to [65535]
2020-02-28 13:28:00.924 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.Http2UpgradeHandler : Entry, Connection [0], SocketStatus [OPEN_READ]
2020-02-28 13:28:00.924 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.Http2UpgradeHandler : Connection [0], State [NEW]
2020-02-28 13:28:00.936 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [0], Frame type [SETTINGS], Flags [0], Payload size [30]
2020-02-28 13:28:00.937 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Remote(server->client)], Parameter type [1] set to [16384]
2020-02-28 13:28:00.937 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Remote(server->client)], Parameter type [2] set to [1]
2020-02-28 13:28:00.937 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Remote(server->client)], Parameter type [3] set to [100]
2020-02-28 13:28:00.937 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Remote(server->client)], Parameter type [4] set to [16777216]
2020-02-28 13:28:00.938 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.ConnectionSettingsBase : Connection [0], Endpoint [Remote(server->client)], Parameter type [5] set to [16384]
2020-02-28 13:28:00.939 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.Http2UpgradeHandler : Entry, Connection [0], SocketStatus [OPEN_READ]
2020-02-28 13:28:00.939 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.Http2UpgradeHandler : Connection [0], State [CONNECTED]
2020-02-28 13:28:00.940 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [0], Frame type [WINDOW_UPDATE], Flags [0], Payload size [4]
2020-02-28 13:28:00.941 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [0], Window size increment [33488897]
2020-02-28 13:28:00.941 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.AbstractStream : Connection [0], Stream [0], increase flow control window by [33488897] to [33554432]
2020-02-28 13:28:00.941 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Frame type [HEADERS], Flags [4], Payload size [50]
2020-02-28 13:28:00.949 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.StreamStateMachine : Connection [0], Stream [1], State changed from [null] to [IDLE]
2020-02-28 13:28:00.952 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.StreamStateMachine : Connection [0], Stream [1], State changed from [IDLE] to [OPEN]
2020-02-28 13:28:00.953 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Processing headers payload of size [50]
2020-02-28 13:28:00.956 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [:authority], Value [localhost:8443]
2020-02-28 13:28:00.959 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [:method], Value [POST]
2020-02-28 13:28:00.959 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [:path], Value [/do-some]
2020-02-28 13:28:00.960 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [:scheme], Value [https]
2020-02-28 13:28:00.960 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [content-length], Value [100000]
2020-02-28 13:28:00.960 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Connection [0], Stream [1], HTTP header [user-agent], Value [Java-http-client/11.0.6]
2020-02-28 13:28:00.960 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Swallowed [0] bytes
2020-02-28 13:28:00.961 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Frame type [DATA], Flags [0], Payload size [16384]
2020-02-28 13:28:00.963 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Data length, [16384], Padding length [none]
2020-02-28 13:28:00.964 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Data added to inBuffer when read thread is waiting. Signalling that thread to continue
2020-02-28 13:28:00.964 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Frame type [DATA], Flags [0], Payload size [16384]
2020-02-28 13:28:00.965 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Data length, [16384], Padding length [none]
2020-02-28 13:28:00.966 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Data added to inBuffer when read thread is waiting. Signalling that thread to continue
2020-02-28 13:28:00.966 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Frame type [DATA], Flags [0], Payload size [16384]
2020-02-28 13:28:00.968 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Data length, [16384], Padding length [none]
2020-02-28 13:28:00.969 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Data added to inBuffer when read thread is waiting. Signalling that thread to continue
2020-02-28 13:28:00.969 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Frame type [DATA], Flags [0], Payload size [16383]
2020-02-28 13:28:00.969 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [1], Data length, [16383], Padding length [none]
2020-02-28 13:28:00.969 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Stream : Data added to inBuffer when read thread is waiting. Signalling that thread to continue
2020-02-28 13:28:00.969 DEBUG 3492 --- [nio-8443-exec-6] org.apache.coyote.http2.Http2Parser : Connection [0], Stream [0], Frame type [HEADERS], Flags [0], Payload size [4]
2020-02-28 13:28:00.972 DEBUG 3492 --- [nio-8443-exec-6] o.a.coyote.http2.Http2UpgradeHandler : Connection error
Comment From: bclozel
It seems that your sample doesn't really involve Spring Boot: you're using java.net.http.HttpClient client and Tomcat as a server - the stacktrace and DEBUG logs only involve Tomcat and this looks like an HTTP/2 parsing issue (or a wrong request sent by the client).
Could you check whether this does happen with another client, like curl, or another Tomcat version? In this case, you could create this issue against the Tomcat project directly as there's nothing we can do here (besides upgrading if something is fixed as a result in Tomcat).
Thanks!
Comment From: LukaszZu
I checked, with curl is the same. Even with Chrome/Firefox also.
Thanks for information, I will report this issue in Tomcat directly. I thought that some autoconfiguration from spring boot could produce this error.