You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Rainer Jung <ra...@kippdata.de> on 2022/12/09 15:15:19 UTC
NIO2 with HTTP/2 wrong Timeout behaviour?
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)?
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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: NIO2 with HTTP/2 wrong Timeout behaviour?
Posted by Mark Thomas <ma...@apache.org>.
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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org