HTTP Request stuck in Spring Boot / Tomcat Embed 9.0.35

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

HTTP Request stuck in Spring Boot / Tomcat Embed 9.0.35

Attila Tőkés
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.



 
Reply | Threaded
Open this post in threaded view
|

Re: HTTP Request stuck in Spring Boot / Tomcat Embed 9.0.35

markt
On 16/11/2020 13:41, Attila Tőkés wrote:

<snip/>

> 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?

In normal circumstances, no. In some error conditions, yes.

> Or does this looks like a bug in Tomcat?

No.

The most likely cause is the user agent signalling an incorrect content
length.

Unfortunately you removed all of the useful information from the debug
logs so it is impossible to provide a definitive answer.

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: HTTP Request stuck in Spring Boot / Tomcat Embed 9.0.35

Attila Tőkés
Hi Mark, The Content-Length is correctly set, and the request is valid. We already checked this. Sometimes we even have requests identical to the problematic one, correctly processed before / after the problem occurs. Thank, Attila  From: Mark Thomas <[hidden email]> Sent: Monday, November 16, 2020 3:56 PM To: [hidden email] <[hidden email]> Subject: Re: HTTP Request stuck in Spring Boot / Tomcat Embed 9.0.35   On 16/11/2020 13:41, Attila Tőkés wrote: <snip/> > 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? In normal circumstances, no. In some error conditions, yes. > Or does this looks like a bug in Tomcat? No. The most likely cause is the user agent signalling an incorrect content length. Unfortunately you removed all of the useful information from the debug logs so it is impossible to provide a definitive answer. Mark --------------------------------------------------------------------- To unsubscribe, e-mail: [hidden email] For additional commands, e-mail: [hidden email]