On 09/12/2022 15:15, Rainer Jung wrote:
I observe the following behavior for 10.1.4, but it might neither be a
regression nor version specific at all.
I am calling a JSP which writes a few bytes, then does
"Thread.sleep(20000);" and then writes the remaining things.
When calling it with HTTP/1.1 it works for all connector types.
When calling it with HTTP/2 it works for NIO, but not for NIO2. After a
shorter time than the 20 seconds, I get an "empty reply from server" in
curl and the browser. The request processing actually continues, but of
course the stream is closed so the trying to write the result after 20
seconds fails.
It happens for JSSE and tcnative.
The behavior seems to be related to the NIO2 readTimeout setting. The
empty repky error happens exactly after the amount of time set there and
when increasing it slightly above the sleep time in the JSP, I get the
correct result.
Using trace logging and looking at the http2 log lines, all of those are
the same for NIO and for NIO2.
Should I open an Issue (BZ or GH)?
BZ please. This looks valid to me.
Thanks for reporting.
Mark
At the end of the mail you can find the full log for one failing
request. The problem happens at the SocketTimeout at 12:50:40.
Best regards,
Rainer
12:51:30,382 [exec-0] util.threads.LimitLatch (LimitLatch.java:115) -
Counting up[exec-0] latch=1
12:51:30,407 [exec-0] util.net.SecureNio2Channel
(SecureNio2Channel.java:432) - The SNI host name extracted for
connection [sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/0.2.3.4:8244 remote=/1.2.3.1:58186]] was [myserver]
12:51:30,471 [exec-1] http11.Http11Nio2Protocol
(AbstractProtocol.java:761) - Processing socket
[org.apache.tomcat.util.net.SecureNio2Channel@39a7a1e8:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/1.2.3.4:8244 remote=/1.2.3.1:58186]] with status [OPEN_READ]
12:51:30,472 [exec-1] http11.Http11Nio2Protocol
(AbstractProtocol.java:777) - Found processor [null] for socket
[org.apache.tomcat.util.net.SecureNio2Channel@39a7a1e8:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/1.2.3.4:8244 remote=/1.2.3.1:58186]]
12:51:30,473 [exec-1] http2.ConnectionSettingsBase
(ConnectionSettingsBase.java:66) - Connection [1], Endpoint
[Local(client->server)], Parameter type [3] set to [100]
12:51:30,473 [exec-1] http2.ConnectionSettingsBase
(ConnectionSettingsBase.java:66) - Connection [1], Endpoint
[Local(client->server)], Parameter type [4] set to [65535]
12:51:30,473 [exec-1] http11.Http11Nio2Protocol
(AbstractProtocol.java:812) - Created new processor
[org.apache.coyote.http11.upgrade.UpgradeProcessorInternal@376048ac]
12:51:30,473 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:331) - Entry, Connection [1], SocketStatus
[OPEN_READ]
12:51:30,473 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:202) - Connection [1], State [NEW]
12:51:30,480 [exec-1] http2.Http2Parser (Http2Parser.java:669) -
Connection [1], Stream [0], Frame type [SETTINGS], Flags [0], Payload
size [18]
12:51:30,480 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:1520) - Connection [1], Stream [0], Frame type
[SETTINGS] resulted in new overhead count of [-90]
12:51:30,480 [exec-1] http2.ConnectionSettingsBase
(ConnectionSettingsBase.java:66) - Connection [1], Endpoint
[Remote(server->client)], Parameter type [3] set to [100]
12:51:30,481 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:1520) - Connection [1], Stream [0], Frame type
[SETTINGS] resulted in new overhead count of [-80]
12:51:30,481 [exec-1] http2.ConnectionSettingsBase
(ConnectionSettingsBase.java:66) - Connection [1], Endpoint
[Remote(server->client)], Parameter type [4] set to [1073741824]
12:51:30,481 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:1520) - Connection [1], Stream [0], Frame type
[SETTINGS] resulted in new overhead count of [-70]
12:51:30,481 [exec-1] http2.ConnectionSettingsBase
(ConnectionSettingsBase.java:66) - Connection [1], Endpoint
[Remote(server->client)], Parameter type [2] set to [0]
12:51:30,482 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:331) - Entry, Connection [1], SocketStatus
[OPEN_READ]
12:51:30,482 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:202) - Connection [1], State [CONNECTED]
12:51:30,483 [exec-1] http2.Http2Parser (Http2Parser.java:669) -
Connection [1], Stream [0], Frame type [WINDOW_UPDATE], Flags [0],
Payload size [4]
12:51:30,483 [exec-1] http2.Http2Parser (Http2Parser.java:430) -
Connection [1], Stream [0], Window size increment [1073676289]
12:51:30,483 [exec-1] http2.AbstractStream (AbstractStream.java:130) -
Connection [1], Stream [0], increase flow control window by [1073676289]
to [1073741824]
12:51:30,483 [exec-1] http2.Http2Parser (Http2Parser.java:669) -
Connection [1], Stream [1], Frame type [HEADERS], Flags [5], Payload
size [52]
12:51:30,484 [exec-1] http2.StreamStateMachine
(StreamStateMachine.java:115) - Connection [1], Stream [1], State
changed from [null] to [IDLE]
12:51:30,484 [exec-1] http2.StreamStateMachine
(StreamStateMachine.java:115) - Connection [1], Stream [1], State
changed from [IDLE] to [OPEN]
12:51:30,485 [exec-1] http2.Http2Parser (Http2Parser.java:481) -
Connection [1], Stream [1], Processing headers payload of size [52]
12:51:30,485 [exec-1] http2.HpackDecoder (HpackDecoder.java:302) - Using
header from index [2] of static table
12:51:30,485 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [:method] and value [GET]
12:51:30,485 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [:method], Value [GET]
12:51:30,486 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [:path] and value [/qs/sleep.jsp]
12:51:30,486 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [:path], Value [/qs/sleep.jsp]
12:51:30,486 [exec-1] http2.HpackDecoder (HpackDecoder.java:302) - Using
header from index [7] of static table
12:51:30,486 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [:scheme] and value [https]
12:51:30,486 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [:scheme], Value [https]
12:51:30,486 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [:authority] and value [myserver:8244]
12:51:30,487 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [:authority], Value [myserver:8244]
12:51:30,487 [exec-1] http2.HpackDecoder (HpackDecoder.java:330) -
Adding header to index [0] of dynamic table with name [:authority] and
value [myserver:8244]
12:51:30,487 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [user-agent] and value [curl/7.61.1]
12:51:30,487 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [user-agent], Value [curl/7.61.1]
12:51:30,488 [exec-1] http2.HpackDecoder (HpackDecoder.java:330) -
Adding header to index [1] of dynamic table with name [user-agent] and
value [curl/7.61.1]
12:51:30,488 [exec-1] http2.HpackDecoder (HpackDecoder.java:443) -
Emitting header with name [accept] and value [*/*]
12:51:30,488 [exec-1] http2.Stream (Stream.java:291) - Connection [1],
Stream [1], HTTP header [accept], Value [*/*]
12:51:30,488 [exec-1] http2.HpackDecoder (HpackDecoder.java:330) -
Adding header to index [2] of dynamic table with name [accept] and value
[*/*]
12:51:30,488 [exec-1] http2.Http2Parser (Http2Parser.java:580) -
Connection [1], Stream [1], Swallowed [0] bytes
12:51:30,489 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:1520) - Connection [1], Stream [0], Frame type
[HEADERS] resulted in new overhead count of [-90]
12:51:30,489 [exec-1] http2.StreamStateMachine
(StreamStateMachine.java:115) - Connection [1], Stream [1], State
changed from [OPEN] to [HALF_CLOSED_REMOTE]
12:51:30,490 [exec-1] http2.Http2Parser (Http2Parser.java:669) -
Connection [1], Stream [0], Frame type [SETTINGS], Flags [1], Payload
size [0]
12:51:30,490 [exec-1] http2.Http2Parser (Http2Parser.java:669) -
Connection [1], Stream [0], Frame type [PING], Flags [1], Payload size [8]
12:51:30,490 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:2017) - Connection [1] Round trip time
measured as [8,209,582]ns
12:51:30,491 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:451) - Exit, Connection [1], SocketState
[ASYNC_IO]
12:51:30,491 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:266) - Connection [1], Connection preface
received from client
12:51:30,492 [exec-1] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:451) - Exit, Connection [1], SocketState
[ASYNC_IO]
12:51:30,492 [exec-1] http11.upgrade.UpgradeProcessorInternal
(AbstractProcessorLight.java:75) - Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@c0f9ad3:org.apache.tomcat.util.net.SecureNio2Channel@39a7a1e8:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/1.2.3.4:8244 remote=/1.2.3.1:58186]], Status in: [OPEN_READ], State out: [ASYNC_IO]
12:51:30,491 [exec-2] util.http.Parameters (Parameters.java:106) - Set
query string encoding to UTF-8
12:51:30,493 [exec-2] authenticator.AuthenticatorBase
(AuthenticatorBase.java:504) - Security checking request GET /qs/sleep.jsp
12:51:30,494 [exec-2] realm.RealmBase (RealmBase.java:555) - No
applicable constraints defined
12:51:30,494 [exec-2] authenticator.AuthenticatorBase
(AuthenticatorBase.java:540) - Not subject to any constraint
12:51:30,494 [exec-2] org.apache.catalina.core.StandardWrapper
(StandardWrapper.java:701) - Returning instance
12:51:30,494 [exec-2] servlet.JspServlet (JspServlet.java:318) -
JspEngine --> /sleep.jsp
12:51:30,494 [exec-2] servlet.JspServlet (JspServlet.java:319) -
ServletPath: /sleep.jsp
12:51:30,494 [exec-2] servlet.JspServlet (JspServlet.java:320) -
PathInfo: null
12:51:30,495 [exec-2] servlet.JspServlet (JspServlet.java:321) -
RealPath:
/opt/instances/tomcat101-10.1.4-nio2-timeout/webapps/qs/sleep.jsp
12:51:30,495 [exec-2] servlet.JspServlet (JspServlet.java:322) -
RequestURI: /qs/sleep.jsp
12:51:30,495 [exec-2] servlet.JspServlet (JspServlet.java:323) -
QueryString: null
12:51:40,493 [exec-3] http2.Http2Parser (Http2AsyncParser.java:325) -
Connection [1], Stream [0], Frame type [null], Error
java.net.SocketTimeoutException: null
at
org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.failed(SocketWrapperBase.java:1124) ~[tomcat-coyote.jar:10.1.4]
at
org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.failed(SocketWrapperBase.java:1066) ~[tomcat-coyote.jar:10.1.4]
at
org.apache.tomcat.util.net.SecureNio2Channel$2.failed(SecureNio2Channel.java:1158) ~[tomcat-coyote.jar:10.1.4]
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:129) ~[?:?]
at sun.nio.ch.Invoker$2.run(Invoker.java:219) ~[?:?]
at
sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) ~[?:?]
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-util.jar:10.1.4]
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-util.jar:10.1.4]
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:10.1.4]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
12:51:40,497 [exec-3] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:331) - Entry, Connection [1], SocketStatus
[ERROR]
12:51:40,497 [exec-3] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:202) - Connection [1], State [CONNECTED]
12:51:40,497 [exec-3] http2.Stream (Stream.java:190) - Connection [1],
Stream [1], Reset received due to [8]
12:51:40,498 [exec-3] http2.StreamStateMachine
(StreamStateMachine.java:115) - Connection [1], Stream [1], State
changed from [HALF_CLOSED_REMOTE] to [CLOSED_RST_RX]
12:51:40,498 [exec-3] http2.WindowAllocationManager
(WindowAllocationManager.java:179) - Connection [1], Stream [1], Waiting
type [0], Notify type [3]
12:51:40,498 [exec-3] http11.Http11Nio2Protocol
(AbstractProtocol.java:387) - Removed processor
[org.apache.coyote.http11.upgrade.UpgradeProcessorInternal@376048ac]
from waiting processors
12:51:40,499 [exec-3] util.threads.LimitLatch (LimitLatch.java:128) -
Counting down[https-jsse-nio2-8244-exec-6] latch=1
12:51:40,500 [exec-3] util.net.Nio2Endpoint (Nio2Endpoint.java:940) -
Calling
[org.apache.tomcat.util.net.Nio2Endpoint@2873d672].closeSocket([org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@c0f9ad3:org.apache.tomcat.util.net.SecureNio2Channel@39a7a1e8:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/1.2.3.4:8244 remote=/1.2.3.1:58186]])
12:51:40,503 [exec-3] http2.Http2UpgradeHandler
(Http2UpgradeHandler.java:451) - Exit, Connection [1], SocketState [CLOSED]
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
