Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-20814

[GSS](7.3.z) UNDERTOW-1856 - Undertow read-timeout can cause closing a connection for long running request even if the request processing is not reading any request data

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 7.3.9.CR1, 7.3.9.GA
    • 7.3.4.GA
    • Undertow
    • None
    • False
    • False
    • +
    • Undefined
    • Hide

      Use ajp-listener instead of http-listener.
      Because AjpReadListener executes the call to channel.suspendReads() (= ReadTimeoutStreamSourceConduit.suspendReads()) that can cancel the read-timeout expiration at here.

      Show
      Use ajp-listener instead of http-listener. Because AjpReadListener executes the call to channel.suspendReads() (= ReadTimeoutStreamSourceConduit.suspendReads()) that can cancel the read-timeout expiration at here .
    • Hide

      1. Configure read-timeout on http-lister in undertow subsystem. For example:

              <subsystem xmlns="urn:jboss:domain:undertow:10.0" ...>
            ...(snip)...
            <server name="default-server">
                <http-listener name="default" read-timeout="10000" socket-binding="http" redirect-socket="https" enable-http2="true" record-request-start-time="true"/>
                <https-listener name="https" socket-binding="https" security-realm="ApplicationRealm" enable-http2="true"/>
                <host name="default-host" alias="localhost">
                    <location name="/" handler="welcome-content"/>
                    <http-invoker security-realm="ApplicationRealm"/>
                    <access-log pattern="%h %l %u %t &quot;%r&quot; %s %b %I %S &quot;%{i,User-Agent}&quot; %T"/>
                    <filter-ref name="dump-request-filter"/>
                </host>
            </server>
            ...(snip)...
            <handlers>
                <file name="welcome-content" path="${jboss.home.dir}/welcome-content"/>
            </handlers>
            <filters>
                <expression-filter name="dump-request-filter" expression="dump-request"/>
            </filters>
        </subsystem>

      2. Deploy a war that contains the following sleep.jsp which invokes a longer Thread.sleep() than read-timeout:

      <%
System.out.println("start");
Thread.sleep(11000L);
System.out.println("end");
out.println("sleep.jsp");
%>

      3. Use the following curl command to send a single request to sleep.jsp

      $ curl -v http://127.0.0.1:8080/example/sleep.jsp

      This request can be processed successfully and access-log entry will be like the following:

      localhost - - [18/Jan/2021:13:58:36 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 11 default task-2 lzwPlREuRnQZt_-jQMY_RbIIlvsx_D04j3HhpfRV "curl/7.29.0" 11.008

      4. Use the following curl command to send two requests (1st one for the welcome content and 2nd one for sleep.jsp), so the 2nd request for sleep.jsp will be sent through the same KeepAlived connection. (Please make sure that execute the following command in one line.)

      $ curl -v http://127.0.0.1:8080 http://127.0.0.1:8080/example/sleep.jsp

      Then, you will see that the curl command shows "Connection died, retrying a fresh connect" on the 2nd request for sleep.jsp. The retried request can be successful, but the initial attempt of sleep.jsp fails. (Note: the retrying request itself is up to the client's behavior. So, the retry may not happen with a different client (e.g. wget) or a different version.)

      And you will see the following access-log entries. Notice that the 2nd request for sleep.jsp is logged as returned as "200 OK" from I/O thread. 

      localhost - - [18/Jan/2021:14:02:54 +0900] "GET / HTTP/1.1" 200 1531 default task-2 - "curl/7.29.0" 0.005
localhost - - [18/Jan/2021:14:03:04 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 - default I/O-4 5jFVDw8qdTLfxAeJ9yZPiM-mP-tTXU9PaNt5B4aS "curl/7.29.0" 10.010
localhost - - [18/Jan/2021:14:03:15 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 11 default task-1 Md0RG_zyRk5Qq7PKk08L0lH1sgTngglo6xXO9mVn "curl/7.29.0" 11.006
      Show
      1. Configure read-timeout on http-lister in undertow subsystem. For example: <subsystem xmlns= "urn:jboss:domain:undertow:10.0" ...> ...(snip)... <server name= " default -server" > <http-listener name= " default " read-timeout= "10000" socket-binding= "http" redirect-socket= "https" enable-http2= " true " record-request-start-time= " true " /> <https-listener name= "https" socket-binding= "https" security-realm= "ApplicationRealm" enable-http2= " true " /> <host name= " default -host" alias= "localhost" > <location name= "/" handler= "welcome-content" /> <http-invoker security-realm= "ApplicationRealm" /> <access-log pattern= "%h %l %u %t &quot;%r&quot; %s %b %I %S &quot;%{i,User-Agent}&quot; %T" /> <filter-ref name= "dump-request-filter" /> </host> </server> ...(snip)... <handlers> <file name= "welcome-content" path= "${jboss.home.dir}/welcome-content" /> </handlers> <filters> <expression-filter name= "dump-request-filter" expression= "dump-request" /> </filters> </subsystem> 2. Deploy a war that contains the following sleep.jsp which invokes a longer Thread.sleep() than read-timeout: <% System .out.println( "start" ); Thread .sleep(11000L); System .out.println( "end" ); out.println( "sleep.jsp" ); %> 3. Use the following curl command to send a single request to sleep.jsp $ curl -v http: //127.0.0.1:8080/example/sleep.jsp This request can be processed successfully and access-log entry will be like the following: localhost - - [18/Jan/2021:13:58:36 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 11 default task-2 lzwPlREuRnQZt_-jQMY_RbIIlvsx_D04j3HhpfRV "curl/7.29.0" 11.008 4. Use the following curl command to send two requests (1st one for the welcome content and 2nd one for sleep.jsp), so the 2nd request for sleep.jsp will be sent through the same KeepAlived connection. (Please make sure that execute the following command in one line.) $ curl -v http: //127.0.0.1:8080 http://127.0.0.1:8080/example/sleep.jsp Then, you will see that the curl command shows "Connection died, retrying a fresh connect" on the 2nd request for sleep.jsp. The retried request can be successful, but the initial attempt of sleep.jsp fails. (Note: the retrying request itself is up to the client's behavior. So, the retry may not happen with a different client (e.g. wget) or a different version.) And you will see the following access-log entries. Notice that the 2nd request for sleep.jsp is logged as returned as "200 OK" from I/O thread. localhost - - [18/Jan/2021:14:02:54 +0900] "GET / HTTP/1.1" 200 1531 default task-2 - "curl/7.29.0" 0.005 localhost - - [18/Jan/2021:14:03:04 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 - default I/O-4 5jFVDw8qdTLfxAeJ9yZPiM-mP-tTXU9PaNt5B4aS "curl/7.29.0" 10.010 localhost - - [18/Jan/2021:14:03:15 +0900] "GET /example/sleep.jsp HTTP/1.1" 200 11 default task-1 Md0RG_zyRk5Qq7PKk08L0lH1sgTngglo6xXO9mVn "curl/7.29.0" 11.006

      Undertow read-timeout can cause closing a connection for a long-running request even if the request processing is not reading any request data.

      This issue can happen notably and easily. However, this can rarely happen with a normal request. (For example, when channel.read(buffer) returns 0 and HttpReadListener.handleFailedRead() triggers ReadTimeoutStreamSourceConduit through channel.resumeReads().)

      As per Flavia's analysis, it appears that HttpReadListener is skipping the call to channel.suspendReads() (= ReadTimeoutStreamSourceConduit.suspendReads()) that would cancel the read-timeout expiration.

      —

      The following is a detailed scenario of when the issue happens with the KeepAlive connection.

      When read-timeout is configured on Undertow http-listener, ReadTimeoutStreamSourceConduit's timeoutCommand is registered to executeAfter on an I/O thread for KeepAlive connection at HttpReadListener.exchangeComplete().

      In the next request which comes through the KeepAlive connection, expireTime will be updated when reading data from the channel. However, timeoutCommand is still registered, so it can be invoked in the middle of the long-running request processing that is not reading any request data.

      read-timeout should only affect the request processing which is reading request data that takes longer time than the specified value.

      In addition, the access-log will log the request returned as "200 OK" from I/O thread in such a case. That is not correct.

              flaviarnn Flavia Rainone
              rhn-support-mmiura Masafumi Miura
              Votes:
              0 Vote for this issue
              Watchers:
              15 Start watching this issue

                Created:
                Updated:
                Resolved: