In a certain case, the AJP write-timeout can be started before EAP starts processing the request. If the request takes longer than write-timeout, when EAP goes to send the response, a write-timeout will occur and the connection will be closed. In the case of Transfer-Encoding: chunked, this can cause the final chunk (the 0 chunk indicating no more data) to not be sent back to the client, causing decode issues.
Normal Case
In the "normal" case, httpd sends a REQ:POST request and the full body in the REQ:BODY to EAP, and EAP then processes the request. When the processing is finished, EAP sends the response back to http.
When EAP sends the first RSP:SEND_BODY_CHUNK, that starts the write-timeout timer (technically, it sets the expireTime in WriteTimeoutStreamSinkConduit to the current time + write-timeout). The default write-timeout is 90 seconds, so just sending the response does not really cause any issue.
httpd EAP
-------- --------------
REQ:POST ---->
REQ:BODY ---->
<process>
<---- RSP:SEND BODY CHUNK +--+
<---- RSP:SEND BODY CHUNK | write-timeout period
<---- RSP:END RESPONSE +--+
The first RSP:SEND_BODY_CHUNK contains the response, the second is the "terminating chunk", and RSP:END_RESPONSE signitifes the end of the transaction.
GET BODY CHUNK case
However, in the following case, httpd does not send the full body in the first REQ:BODY which causes EAP to send a RSP:GET_BODY_CHUNK request back to httpd. This unfortunately starts the write-timeout timer (again, expireTime is set to the current time + write-timeout). If the processing takes longer than the write-timeout period, when EAP goes to send the response, the first RSP:SEND_BODY_CHUNK causes a write-timeout, and the connection is closed without sending the terminating chunk or RSP:END_RESPONSE.
httpd EAP
-------- --------------
REQ:POST ---->
REQ:BODY ---->
<---- RSP:GET BODY CHUNK +--+
REQ:BODY ----> |
<process> | write-timeout period
<---- RSP:SEND BODY CHUNK +--+
<write-timeout, connection closed>
Here is an example showing when handleWriteTimeout() is called, and how expireTime gets set. I set the write-timeout to 2s (2000ms) for this test.
15:09:09,484 TRACE [io.undertow.request] (default I/O-4) Opened connection with /a.b.c.d:43078
15:09:09,485 DEBUG [io.undertow.request] (default I/O-4) Matched default handler path /polling
15:09:09,485 INFO [stdout] (default task-1) @@@@ Reading POST body (6366B)...
==> 15:09:09,485 INFO [stdout] (default task-1) @@@@ Read in 5327 bytes # POST body is split into multiple packets, so we only read the first 5327 bytes
15:09:09,485 INFO [stdout] (default task-1) Rule.execute called for WriteTimeoutStreamSinkConduit ENTER_0:0
15:09:09,485 INFO [stdout] (default task-1) WriteTimeoutStreamSinkConduit ENTER execute
15:09:09,486 INFO [stdout] (default task-1) -------------- [ io.undertow.conduits.WriteTimeoutStreamSinkConduit@7586a4b8 ] io.undertow.conduits.WriteTimeoutStreamSinkConduit#handleWriteTimeout(long) void invoked.
==> 15:09:09,486 INFO [stdout] (default task-1) expireTime = -1 # expireTime is originally unset.
# EAP sends RSP:GET_BODY_CHUNK which calls handleWriteTimeout() which will set expireTime to the current time + write-timeout (2s) or 15:09:11.
15:09:09,486 INFO [stdout] (default task-1)
15:09:09,486 INFO [stdout] (default task-1) Rule.execute called for WriteTimeoutStreamSinkConduit EXIT_2:0
15:09:09,486 INFO [stdout] (default task-1) WriteTimeoutStreamSinkConduit EXIT execute
15:09:09,486 INFO [stdout] (default task-1) -------------- [ io.undertow.conduits.WriteTimeoutStreamSinkConduit@7586a4b8 ] io.undertow.conduits.WriteTimeoutStreamSinkConduit#handleWriteTimeout(long) void finished.
15:09:09,486 INFO [stdout] (default task-1)
==> 15:09:09,486 INFO [stdout] (default task-1) @@@@ Read in 6366 bytes # read in the rest of the POST body
<"process" the request and make sure it takes longer than write-timeout (2s)>
15:09:14,487 TRACE [io.undertow.server.HttpServerExchange] (default task-1) Starting to write response for HttpServerExchange{ POST /polling}
15:09:14,488 INFO [stdout] (default task-1) Rule.execute called for WriteTimeoutStreamSinkConduit ENTER_0:0
15:09:14,488 INFO [stdout] (default task-1) WriteTimeoutStreamSinkConduit ENTER execute
15:09:14,488 INFO [stdout] (default task-1) -------------- [ io.undertow.conduits.WriteTimeoutStreamSinkConduit@7586a4b8 ] io.undertow.conduits.WriteTimeoutStreamSinkConduit#handleWriteTimeout(long) void invoked.
==> 15:09:14,489 INFO [stdout] (default task-1) expireTime = 1739945351486 # expireTime is set to 15:09:11 (15:09:09 + 2s), so EAP thinks a write-timeout has occured
15:09:14,489 INFO [stdout] (default task-1)
15:09:14,491 TRACE [io.undertow.server.channel.ajp.response] (default task-1) suspend
15:09:14,492 INFO [stdout] (default task-1) Rule.execute called for WriteTimeoutStreamSinkConduit THROW_1:0
15:09:14,492 INFO [stdout] (default task-1) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
15:09:14,493 INFO [stdout] (default task-1) calling installed(WriteTimeoutStreamSinkConduit THROW) for helper classorg.jboss.byteman.rule.helper.Helper
15:09:14,493 INFO [stdout] (default task-1) Installed rule using default helper : WriteTimeoutStreamSinkConduit THROW
15:09:14,493 INFO [stdout] (default task-1) WriteTimeoutStreamSinkConduit THROW execute
==> 15:09:14,493 INFO [stdout] (default task-1) -------------- [ io.undertow.conduits.WriteTimeoutStreamSinkConduit@7586a4b8 ] io.undertow.conduits.WriteTimeoutStreamSinkConduit#handleWriteTimeout(long) void threw an exception java.nio.channels.ClosedChannelException
15:09:14,494 INFO [stdout] (default task-1) # handleWriteTimeout() throws a ClosedChannelException which causes the connection to close
- is blocked by
-
JBEAP-30492 (8.1.z) AJP write-timeout can be calculated incorrectly, leading to erroneous write-timeout
-
- New
-
-
-
- New
-
-
UNDERTOW-2575 Flush on WriteTimeout to adhere to proper protocol handling if needs be
-
- Resolved
-
- is cloned by
-
-
- Pull Request Sent
-
- is duplicated by
-
-
- New
-