We have many Angular applications, and we currently use Angular 15. I'm
using Apache 2.4.57 and Tomcat 10.1.10/JDK20 on Windows 2019 (don't ask).
For several years now, I've used the following configuration without
issues.
Angular <-H2-> Apache <-MOD_JK/AJP 1.3--> Tomcat
This week I've been working on replacing mod_jk with mod_http2, and for
the most part, things are working, but I'm running into issues where we do
HTTP POSTs of JSON to Rest APIs. We are using Spring Framework 6.0.10. The
only things I have yet to try are upgrading to Tomcat 10.1.11 and
updating to the latest JDK20 release. We are using Amazon Corretto.
Angular <-H2-> Apache <-MOD_HTTP2/H2--> Tomcat
Everything seems to be working fine except for places in our apps where
we do things like a POST of JSON to a Rest API. To debug what's going on,
I've enabled dumpio on Apache, and I can see the entire JSON getting
posted. I've installed Wireshark on the backend where Tomcat is running,
and I've captured the TCP packets containing the JSON, and I can see that
the entire JSON is making it to Tomcat. When I compare the JSON in a diff
tool, the JSON is the same, so I know it's making it intact. So I enabled
FINE logging for HTTP2 on Tomcat, and I see everything looks to come
through to Tomcat fine until it hits...
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.doRead The
Stream input buffer is empty. Waiting for more data
At this point, things hang for 20 seconds until a timeout occurs, and
Tomcat closes the connection.
Here's the odd thing, the same post doesn't always fail. In about 1 out
of 10 attempts, the POST will succeed. When it does succeed and I compare
the HTTP2 logs in Tomcat, everything looks the same until the end of the
connection. Here are the logs showing a POST that succeeds vs. one that
fails. Is there something we should be doing in our Angular apps
differently when HTTP2 is used in place of AJP, or is this potentially a
bug?
Success...
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection
[18], Stream [0], Frame type [HEADERS] resulted in new overhead count of
[-260]
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [18], Stream
[0], Frame type [PING], Flags [1], Payload size [8]
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler$PingManager.receivePing
Connection [18] Round trip time measured as [11,769,300]ns
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [18], Stream
[13], Frame type [DATA], Flags [0], Payload size [8000]
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2Parser.readDataFrame Connection [18], Stream
[13], Data length [8000], Padding length [none]
11-Jul-2023 08:51:45.427 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection
[18], Stream [0], Frame type [DATA] resulted in new overhead count of [-280]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.startRequestBodyFrame
Connection [18], Stream [13] startRequestBodyFrame returned
[java.nio.HeapByteBuffer[pos=0 lim=65535 cap=65535]]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.onDataAvailable
Data added to inBuffer when read thread is waiting. Signalling that thread
to continue
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [18], Stream
[13], Frame type [DATA], Flags [1], Payload size [5878]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2Parser.readDataFrame Connection [18], Stream
[13], Data length [5878], Padding length [none]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection
[18], Stream [0], Frame type [DATA] resulted in new overhead count of [-300]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.startRequestBodyFrame
Connection [18], Stream [13] startRequestBodyFrame returned
[java.nio.HeapByteBuffer[pos=8000 lim=65535 cap=65535]]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.StreamStateMachine.stateChange Connection [18],
Stream [13], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.onDataAvailable
Data added to inBuffer when read thread is waiting. Signalling that thread
to continue
11-Jul-2023 08:51:45.428 FINE [https-openssl-nio-exec-15]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit,
Connection [18], SocketState [ASYNC_IO]
11-Jul-2023 08:51:45.474 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.doRead Copying
[13878] bytes from inBuffer to outBuffer
11-Jul-2023 08:51:45.474 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeWindowUpdate
Connection [18], Sent window update to client increasing window by [13,878]
bytes
11-Jul-2023 08:51:45.474 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeWindowUpdate
Connection [18], Stream [0], Sent window update to client increasing window
by [13,878] bytes
11-Jul-2023 08:51:45.964 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders Connection [18],
Stream [13], Writing the headers, EndOfStream [false]
11-Jul-2023 08:51:45.964 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [:status] with
value [200]
11-Jul-2023 08:51:45.964 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [cache-control]
with value [no-cache, no-store, must-revalidate, max-age=0]
11-Jul-2023 08:51:45.964 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [expires] with
value [0]
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [set-cookie]
with value [XSRF-TOKEN=e6da128f-8fee-48de-bccf-101cb81f7247; Path=/MyApp;
Secure; SameSite=Lax]
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [content-type]
with value [application/json]
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [date] with
value [Tue, 11 Jul 2023 13:51:45 GMT]
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders 100 bytes
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [8192],
writeInProgress [true] and closed [false]
11-Jul-2023 08:51:45.965 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [18],
Stream [13], reduce flow control window by [8192] to [24575]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [18],
Stream [0], reduce flow control window by [8192] to [1065196529]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeBody Connection [18],
Stream [13], Data length [8192], EndOfStream [false]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [5059],
writeInProgress [false] and closed [false]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [18],
Stream [13], reduce flow control window by [5059] to [19516]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.AbstractStream.decrementWindowSize Connection [18],
Stream [0], reduce flow control window by [5059] to [1065191470]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeBody Connection [18],
Stream [13], Data length [5059], EndOfStream [false]
11-Jul-2023 08:51:45.966 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [0], writeInProgress
[false] and closed [false]
11-Jul-2023 08:51:45.967 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [0], writeInProgress
[false] and closed [false]
11-Jul-2023 08:51:45.967 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [0], writeInProgress
[false] and closed [false]
11-Jul-2023 08:51:45.969 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Stream$StreamOutputBuffer.flush Connection [18],
Stream [13], flushing output with buffer at position [0], writeInProgress
[false] and closed [true]
11-Jul-2023 08:51:45.969 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeBody Connection [18],
Stream [13], Data length [0], EndOfStream [true]
11-Jul-2023 08:51:45.969 FINE [https-openssl-nio-exec-5]
org.apache.coyote.http2.StreamStateMachine.stateChange Connection [18],
Stream [13], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
11-Jul-2023 08:51:45.970 FINE [https-openssl-nio-exec-5]
org.apache.coyote.AbstractProcessorLight.process Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6fbdbb24
:org.apache.tomcat.util.net.SecureNioChannel@1108a252:java.nio.channels.SocketChannel[connected
local=/x.x.x.x:18443 remote=/x.x.x.x:57063]], Status in: [OPEN_READ], State
out: [CLOSED]
Failure...
11-Jul-2023 08:27:31.051 FINE [https-openssl-nio-x.x.x.x-18443-exec-9]
org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection
[b], Stream [0], Frame type [HEADERS] resulted in new overhead count of
[-460]
11-Jul-2023 08:27:31.051 FINE [https-openssl-nio-x.x.x.x-18443-exec-9]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry,
Connection [b], SocketStatus [OPEN_READ]
11-Jul-2023 08:27:31.051 FINE [https-openssl-nio-x.x.x.x-18443-exec-9]
org.apache.coyote.http2.Http2UpgradeHandler.init Connection [b], State
[CONNECTED]
11-Jul-2023 08:27:31.052 FINE [https-openssl-nio-x.x.x.x-18443-exec-9]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit,
Connection [b], SocketState [ASYNC_IO]
11-Jul-2023 08:27:31.053 FINE [https-openssl-nio-x.x.x.x-18443-exec-10]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [b], Stream
[0], Frame type [PING], Flags [1], Payload size [8]
11-Jul-2023 08:27:31.053 FINE [https-openssl-nio-x.x.x.x-18443-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler$PingManager.receivePing
Connection [b] Round trip time measured as [1,480,000]ns
11-Jul-2023 08:27:31.053 FINE [https-openssl-nio-x.x.x.x-18443-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry,
Connection [b], SocketStatus [OPEN_READ]
11-Jul-2023 08:27:31.053 FINE [https-openssl-nio-x.x.x.x-18443-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler.init Connection [b], State
[CONNECTED]
11-Jul-2023 08:27:31.053 FINE [https-openssl-nio-x.x.x.x-18443-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit,
Connection [b], SocketState [ASYNC_IO]
11-Jul-2023 08:27:31.166 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.doRead The Stream
input buffer is empty. Waiting for more data
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders Connection [b],
Stream [23], Writing the headers, EndOfStream [false]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [:status] with
value [400]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [cache-control]
with value [no-cache, no-store, must-revalidate, max-age=0]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [expires] with
value [0]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [set-cookie]
with value [XSRF-TOKEN=bc8fe837-fbf7-46e5-8541-0f2c04c0ac73; Path=/MyApp;
Secure; SameSite=Lax]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header
[content-length] with value [0]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.HpackEncoder.encode Encoding header [date] with
value [Tue, 11 Jul 2023 13:27:51 GMT]
11-Jul-2023 08:27:51.170 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Http2UpgradeHandler.doWriteHeaders 103 bytes
11-Jul-2023 08:27:51.171 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_NOW]
reported while processing request
org.apache.coyote.CloseNowException:
org.apache.coyote.http2.StreamException: Timeout waiting to read data from
client
at
org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:1064)
at
org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:69)
at
org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:234)
at
org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386)
at org.apache.coyote.Response.action(Response.java:208)
at
org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:256)
at
org.apache.catalina.connector.Response.finishResponse(Response.java:413)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:370)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:426)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:86)
at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:1623)
Caused by: org.apache.coyote.http2.StreamException: Timeout waiting to
read data from client
at
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.doRead(Stream.java:1194)
at org.apache.coyote.Request.doRead(Request.java:635)
at
org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:313)
at
org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:596)
at
org.apache.catalina.connector.InputBuffer.readByte(InputBuffer.java:326)
at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:85)
at java.base/java.io.FilterInputStream.read(FilterInputStream.java:71)
at
java.base/java.io.PushbackInputStream.read(PushbackInputStream.java:150)
at
org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver$EmptyBodyCheckingHttpInputMessage.<init>(AbstractMessageConverterMethodArgumentResolver.java:331)
at
org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:172)
at
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:163)
at
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:136)
at
org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:122)
at
org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:181)
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:148)
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081)
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590)
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:236)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:212)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
com.myapp.common.authz.filter.AuthzFilter.doFilter(AuthzFilter.java:458)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at com.myapp.common.csrf.filter.CsrfFilter.doFilter(CsrfFilter.java:112)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
com.avlesh.web.filter.responseheaderfilter.ResponseHeaderFilter.doFilter(ResponseHeaderFilter.java:196)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:154)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
at
org.apache.catalina.ha.session.JvmRouteBinderValve.invoke(JvmRouteBinderValve.java:183)
at
org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:329)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:676)
at
org.apache.catalina.valves.LoadBalancerDrainingValve.invoke(LoadBalancerDrainingValve.java:230)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:676)
at
org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:738)
at org.apache.catalina.valves.SSLValve.invoke(SSLValve.java:193)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341)
... 8 more
11-Jul-2023 08:27:51.173 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [b], Stream
[23], Frame type [DATA], Flags [1], Payload size [13878]
11-Jul-2023 08:27:51.173 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_NOW]
reported while processing request
org.apache.coyote.CloseNowException:
org.apache.coyote.http2.StreamException: Timeout waiting to read data from
client
at
org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:1064)
at
org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:69)
at
org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:234)
at
org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:443)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:86)
at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:1623)
Caused by: org.apache.coyote.http2.StreamException: Timeout waiting to
read data from client
at
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.doRead(Stream.java:1194)
at org.apache.coyote.Request.doRead(Request.java:635)
at
org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:313)
at
org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:596)
at
org.apache.catalina.connector.InputBuffer.readByte(InputBuffer.java:326)
at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:85)
at java.base/java.io.FilterInputStream.read(FilterInputStream.java:71)
at
java.base/java.io.PushbackInputStream.read(PushbackInputStream.java:150)
at
org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver$EmptyBodyCheckingHttpInputMessage.<init>(AbstractMessageConverterMethodArgumentResolver.java:331)
at
org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:172)
at
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:163)
at
org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:136)
at
org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:122)
at
org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:181)
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:148)
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081)
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590)
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:236)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:212)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
com.myapp.common.authz.filter.AuthzFilter.doFilter(AuthzFilter.java:458)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at com.myapp.common.csrf.filter.CsrfFilter.doFilter(CsrfFilter.java:112)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
com.avlesh.web.filter.responseheaderfilter.ResponseHeaderFilter.doFilter(ResponseHeaderFilter.java:196)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:154)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
at
org.apache.catalina.ha.session.JvmRouteBinderValve.invoke(JvmRouteBinderValve.java:183)
at
org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:329)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:676)
at
org.apache.catalina.valves.LoadBalancerDrainingValve.invoke(LoadBalancerDrainingValve.java:230)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:676)
at
org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:738)
at org.apache.catalina.valves.SSLValve.invoke(SSLValve.java:193)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:426)
... 7 more
11-Jul-2023 08:27:51.173 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2Parser.readDataFrame Connection [b], Stream
[23], Data length [13878], Padding length [none]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.AbstractProcessorLight.process Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6189bb2c
:org.apache.tomcat.util.net.SecureNioChannel@101e2d78:java.nio.channels.SocketChannel[connected
local=/x.x.x.x:18443 remote=/x.x.x.x:55549]], Status in: [OPEN_READ], State
out: [CLOSED]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Stream.close Connection [b], Stream [23], Reset
sent due to [ENHANCE_YOUR_CALM]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.sendStreamReset Connection
[b], Stream [23], Error [ENHANCE_YOUR_CALM], Message [Timeout waiting to
read data from client], RST (closing stream)
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.StreamStateMachine.stateChange Connection [b],
Stream [23], State changed from [OPEN] to [CLOSED_RST_TX]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2UpgradeHandler.updateOverheadCount Connection
[b], Stream [0], Frame type [DATA] resulted in new overhead count of [-480]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2UpgradeHandler.startRequestBodyFrame
Connection [b], Stream [23] startRequestBodyFrame returned
[java.nio.HeapByteBuffer[pos=0 lim=65535 cap=65535]]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.onDataAvailable
Data added to inBuffer when read thread is waiting. Signalling that thread
to continue
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.WindowAllocationManager.notify Connection [b],
Stream [23], Waiting type [0], Notify type [3]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry,
Connection [b], SocketStatus [OPEN_READ]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2UpgradeHandler.init Connection [b], State
[CONNECTED]
11-Jul-2023 08:27:51.174 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Stream$StandardStreamInputBuffer.swallowUnread
Swallowing [13,878] bytes previously read into input stream buffer
11-Jul-2023 08:27:51.175 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Http2AsyncUpgradeHandler.writeWindowUpdate
Connection [b], Sent window update to client increasing window by [13,878]
bytes
11-Jul-2023 08:27:51.175 FINE [https-openssl-nio-x.x.x.x-18443-exec-6]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit,
Connection [b], SocketState [ASYNC_IO]
11-Jul-2023 08:27:51.175 FINE [https-openssl-nio-x.x.x.x-18443-exec-8]
org.apache.coyote.http2.Stream.recycle Connection [b], Stream [23] has been
recycled
What do you think? Is there a bug here somewhere, or do we need to
tweak an H2 config setting in Apache or Tomcat?
--
Thanks,
Dan
