Hi,
We are using Tomcat Embed 9.0.35 with Spring Boot 2.2.7 in a micro-service
running in a Kubernetes environment.
Occasionally, we observe some HTTP requests getting stuck and not being
processed. After 5 seconds, when the client side times out and tries to close
the connection to the server, the server suddenly starts processing the
problematic request, but usually fails as the connection is already closed.
In order investigate the issue, we enabled TCP dumps and DEBUG level logging on
the <org.apache.tomcat>, <org.apache.catalina> and <org.apache.coyote> packages.
The resulting logs revealed that the HTTP Request is actually fully read into a
Http11InputBuffer, but then the request is not being processed until the client
tries to close the connection.
Log:
2020-11-12 21:13:24,944 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11NioProtocol [DirectJDKLog.java:173] Processing socket
[org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=/<ip>:<port> remote=/<ip>:<port>]] with status [OPEN_READ]
2020-11-12 21:13:24,945 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11InputBuffer [DirectJDKLog.java:173] Received [POST <url> HTTP/1.1\
Authorization: Basic <Token>\
Accept: application/json, application/*+json\
<...headers...>\
<...body...>]
2020-11-12 21:13:24,945 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11NioProtocol [DirectJDKLog.java:173] Found processor [null] for
socket
[org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=/<ip>:<port> remote=/<ip>:<port>]]
2020-11-12 21:13:24,945 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11NioProtocol [DirectJDKLog.java:173] Popped processor
[org.apache.coyote.http11.Http11Processor@639be197] from cache
2020-11-12 21:13:24,945 DEBUG [http-nio-<port>-exec-14] o.a.t.u.n.NioEndpoint
[DirectJDKLog.java:173] Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3b5eaf8e:org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=/<ip>:<port> remote=/<ip>:<port>]], Read direct from socket: [581]
2020-11-12 21:13:24,945 DEBUG [http-nio-<port>-exec-14]
o.a.t.u.n.SocketWrapperBase [DirectJDKLog.java:173] Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3b5eaf8e:org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=/<ip>:<port> remote=/<ip>:<port>]], Read from buffer: [0]
<... 5 seconds gap, till the client times out and tries to close the
connection...>
2020-11-12 21:13:29,952 DEBUG [http-nio-<port>-exec-14]
o.a.c.a.AuthenticatorBase [DirectJDKLog.java:173] Not subject to any constraint
2020-11-12 21:13:29,952 DEBUG [http-nio-<port>-exec-14]
o.a.c.a.AuthenticatorBase [DirectJDKLog.java:173] Security checking request
POST <url>
2020-11-12 21:13:29,952 DEBUG [http-nio-<port>-exec-14] o.a.c.r.RealmBase
[DirectJDKLog.java:173] No applicable constraints defined
2020-11-12 21:13:29,952 DEBUG [http-nio-<port>-exec-14] o.a.c.v.RemoteIpValve
[DirectJDKLog.java:173] Incoming request <url> with originalRemoteAddr [<ip>],
originalRemoteHost=[<ip>], originalSecure=[false], originalScheme=[http],
originalServerName=[<host>], originalServerPort=[<port>] will be seen as
newRemoteAddr=[<ip>], newRemoteHost=[<ip>], newSecure=[false],
newScheme=[http], newServerName=[<host>], newServerPort=[<port>]
2020-11-12 21:13:29,954 DEBUG [http-nio-<port>-exec-14] o.a.t.u.h.Parameters
[DirectJDKLog.java:173] Set encoding to UTF-8
2020-11-12 21:13:29,954 DEBUG [http-nio-<port>-exec-14] o.a.t.u.h.Parameters
[DirectJDKLog.java:173] Start processing with input [<body>]
2020-11-12 21:13:29,955 DEBUG [http-nio-<port>-exec-14]
o.a.t.u.n.SocketWrapperBase [DirectJDKLog.java:173] Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3b5eaf8e:org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=<ip>/<ip>:<port> remote=/<ip>:<port>]], Read from buffer: [0]
2020-11-12 21:13:29,956 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11NioProtocol [DirectJDKLog.java:173] Pushed Processor
[org.apache.coyote.http11.Http11Processor@639be197]
2020-11-12 21:13:29,956 DEBUG [http-nio-<port>-exec-14] o.a.c.h.Http11Processor
[DirectJDKLog.java:173] Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3b5eaf8e:org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=<ip>/<ip>:<port> remote=/<ip>:<port>]], Status in: [OPEN_READ], State
out: [CLOSED]
"2020-11-12 21:13:29,956 DEBUG [http-nio-<port>-exec-14]
o.a.c.h.Http11Processor [DirectJDKLog.java:175] Error parsing HTTP request
header java.io.EOFException: null
at
org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1231)
at
org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1141)
at
org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:780)
at
org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:356)
at
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:260)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown
Source)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Unknown Source)"
2020-11-12 21:13:29,956 DEBUG [http-nio-<port>-exec-14] o.a.t.u.n.NioEndpoint
[DirectJDKLog.java:173] Calling
[org.apache.tomcat.util.net.NioEndpoint@25bca962].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3b5eaf8e:org.apache.tomcat.util.net.NioChannel@785aacda:java.nio.channels.SocketChannel[connected
local=<ip>/<ip>:<port> remote=/<ip>:<port>]])
2020-11-12 21:13:29,956 DEBUG [http-nio-<port>-exec-14] o.a.t.u.t.LimitLatch
[DirectJDKLog.java:173] Counting down[http-nio-<port>-exec-14] latch=99
(note: sensitive information was removed from the logs)
Do you think it could be expected behavior for a HTTP Request to not be
processed, even if it is fully read from the socket?
Or does this looks like a bug in Tomcat?
Tried to check the Tomcat source code, but did not managed yet to figure out
what happens.
Note:
The issue always happens on newly opened TCP connections, and we observed it on
multiple different hosts.
Thanks,
Attila T.
Share your
feedback with us
