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

[GSS](8.0.z) UNDERTOW-2228 - Undertow write-timeout can cause a truncate response for request coming through keep-alive connection

XMLWordPrintable

    • False
    • None
    • False
    • Hide

      1. Configure write-timeout on http-lister (and ajp-listener) in undertow subsystem. For example:

              <subsystem xmlns="urn:jboss:domain:undertow:12.0" ...>
            ...(snip)...
            <server name="default-server">
                <http-listener name="default" socket-binding="http" redirect-socket="https" enable-http2="true" record-request-start-time="true" write-timeout="5000" />
                <ajp-listener name="ajp" socket-binding="ajp" record-request-start-time="true" write-timeout="5000"/>
                <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 %T"/>
                </host>
            </server>
            ...(snip)...
        </subsystem>

      2. Deploy a war that contains the following example.jsp which write larger response than the default buffer size (16KB) and emulate long request processing with Thread.sleep():

      <%
System.out.println("example.jsp - start");
// int size = 8 * 1024; // 8KB
int size = 16 * 1024; // 16KB - default buffer size

char[] buffer = new char[size];
for (int i = 0; i < size; i++) {
    buffer[i] = 'X';
}

try {
    // emulate long request processing
    System.out.println("sleep 10 seconds");
    Thread.sleep(10*1000L);
} catch (Exception ignore) {}

out.print("start");
// out.flush();
out.write(buffer);
out.print("end");
System.out.println("example.jsp - end");
%>

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

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

      This request can be processed successfully and the response contains all content ("start" + 16KB size of "X" + "end")

      4. Use the following curl command to send two requests (1st one for the welcome content and 2nd one for example.jsp), so the 2nd request for example.jsp will be sent through the same keep-alive 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/example.jsp

      Then, you will see that the curl command shows "curl: (18) transfer closed with outstanding read data remaining" on the 2nd request for example.jsp. And the response is truncated in the middle of 16KB size of "X", so you do not see the last "end" in the response. If you enable (uncomment) "out.flush()" in the above example.jsp, the response is truncated before 16KB size of "X", so you see only the first "start" in the response.

      —

      Another easy step to reproduce with web browser. This reproducer does not need "Thread.sleep()" in the application.

      1. Deploy a war that contains the following example2.jsp which write larger response than the default buffer size (16KB):

      <%
System.out.println("example.jsp - start");
// int size = 8 * 1024; // 8KB
int size = 16 * 1024; // 16KB - default buffer size

char[] buffer = new char[size];
for (int i = 0; i < size; i++) {
    buffer[i] = 'X';
}

out.println("start");
// out.flush();
out.write(buffer);
out.println();
out.println("end");
System.out.println("example.jsp - end");
%>

      2. Access example2.jsp with web browser 

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

      This request can be processed successfully and the response contains all content ("start" + 16KB size of "X" + "end")

      3. Wait for several seconds like 10 seconds which is longer than configure write-timeout (5000 = 5 seconds in this case) and is shorter than the default no-request-timeout (60000 = 60 seconds)

      4. Reload the previews page to access the same example2.jsp again through the same keep-alive connection.

      You will see the response is truncated in the middle of 16KB size of "X", so you do not see the last "end" in the response. If you enable (uncomment) "out.flush()" in the above jsp, the response is truncated before 16KB size of "X", so you see only the first "start" in the response.

      Show
      1. Configure write-timeout on http-lister (and ajp-listener) in undertow subsystem. For example: <subsystem xmlns= "urn:jboss:domain:undertow:12.0" ...> ...(snip)... <server name= " default -server" > <http-listener name= " default " socket-binding= "http" redirect-socket= "https" enable-http2= " true " record-request-start-time= " true " write-timeout= "5000" /> <ajp-listener name= "ajp" socket-binding= "ajp" record-request-start-time= " true " write-timeout= "5000" /> <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 %T" /> </host> </server> ...(snip)... </subsystem> 2. Deploy a war that contains the following example.jsp which write larger response than the default buffer size (16KB) and emulate long request processing with Thread.sleep(): <% System .out.println( "example.jsp - start" ); // int size = 8 * 1024; // 8KB int size = 16 * 1024; // 16KB - default buffer size char [] buffer = new char [size]; for ( int i = 0; i < size; i++) { buffer[i] = 'X' ; } try { // emulate long request processing System .out.println( "sleep 10 seconds" ); Thread .sleep(10*1000L); } catch (Exception ignore) {} out.print( "start" ); // out.flush(); out.write(buffer); out.print( "end" ); System .out.println( "example.jsp - end" ); %> 3. Use the following curl command to send a single request to example.jsp $ curl -v http: //127.0.0.1:8080/example/example.jsp This request can be processed successfully and the response contains all content ("start" + 16KB size of "X" + "end") 4. Use the following curl command to send two requests (1st one for the welcome content and 2nd one for example.jsp), so the 2nd request for example.jsp will be sent through the same keep-alive 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/example.jsp Then, you will see that the curl command shows "curl: (18) transfer closed with outstanding read data remaining" on the 2nd request for example.jsp. And the response is truncated in the middle of 16KB size of "X", so you do not see the last "end" in the response. If you enable (uncomment) "out.flush()" in the above example.jsp, the response is truncated before 16KB size of "X", so you see only the first "start" in the response. — Another easy step to reproduce with web browser. This reproducer does not need "Thread.sleep()" in the application. 1. Deploy a war that contains the following example2.jsp which write larger response than the default buffer size (16KB): <% System .out.println( "example.jsp - start" ); // int size = 8 * 1024; // 8KB int size = 16 * 1024; // 16KB - default buffer size char [] buffer = new char [size]; for ( int i = 0; i < size; i++) { buffer[i] = 'X' ; } out.println( "start" ); // out.flush(); out.write(buffer); out.println(); out.println( "end" ); System .out.println( "example.jsp - end" ); %> 2. Access example2.jsp with web browser $ curl -v http: //127.0.0.1:8080/example/example.jsp This request can be processed successfully and the response contains all content ("start" + 16KB size of "X" + "end") 3. Wait for several seconds like 10 seconds which is longer than configure write-timeout (5000 = 5 seconds in this case) and is shorter than the default no-request-timeout (60000 = 60 seconds) 4. Reload the previews page to access the same example2.jsp again through the same keep-alive connection. You will see the response is truncated in the middle of 16KB size of "X", so you do not see the last "end" in the response. If you enable (uncomment) "out.flush()" in the above jsp, the response is truncated before 16KB size of "X", so you see only the first "start" in the response.

      Truncate reponse can happen unexpectedly for request comming through keep-alive connection due to the force connection closure by the write-timeout setting. This is similar to JBEAP-20814 that happened with read-timeout setting. (Note that JBEAP-20814 does not happened for ajp-listener but only for http-listener. However, this issue happens on both http-listener and ajp-listener.)

      If I understand correctly, the current write-timeout setting works like the following:

      • WriteTimeoutStreamSinkConduit#handleWriteTimeout() checks if currentTime exceeds expireTime of the write-timeout and bump the expireTime if it's not expired.
      • The WriteTimeoutStreamSinkConduit#handleWriteTimeout() check is triggered after the write() operation. So, the expiration basically happens when the duration takes longer than write-timeout between the multiple write() operations.

      However, the problem is the expireTime in WriteTimeoutStreamSinkConduit never resets to -1 even after completing an exchange (request/response) or before starting an new exchange (request/response). So, the write-timeout can be easily expired for requests that come through the same keep-alive connections.

      Also, the write() operation happens actually when flushing content to the response. So, it appears that the WriteTimeoutStreamSinkConduit#handleWriteTimeout() check happens after either of the following:

      • after writing out all response content when the response content size is smaller than the default buffer size (16KB)
      • after writing each response buffer (16KB) when the response content size is larger than the default buffer size (16KB)
      • after an application invokes response flush() of ServletOutputStream (or Servlet Writer) explicitly

      So, if the response content size is smaller than the default buffer size (16KB) and an application does not invoke response flush, the check happens after writing all content of the response. So, the problem is not revealed luckily in this scenario.
      However, if the response content size is larger than the default buffer size (16KB) or an application invokes response flush() in pieces explicitly, this response truncate issue happens after writing the first buffer.

              thofman Tomas Hofman
              pberan@redhat.com Petr Beran
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: