https://bz.apache.org/bugzilla/show_bug.cgi?id=66385
Bug ID: 66385
Summary: NIO2 with HTTP/2 wrong Timeout behaviour
Product: Tomcat 10
Version: 10.1.4
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: Connectors
Assignee: dev@tomcat.apache.org
Reporter: rainer.j...@kippdata.de
Target Milestone: ------
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
reply 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. Another possibility is, that it is the writeTimeout but that it
erroneously uses the value for the readTimeout.
Using trace logging and looking at the http2 log lines, all of those are the
same for NIO and for NIO2.
Here are the full logs for one failing request. The problem happens at the
SocketTimeout at 12:50:40.
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]
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
