Bug 62614 - Async servlet over HTTP/2 WriteListener does not work because onWritePossible is never called back again
Summary: Async servlet over HTTP/2 WriteListener does not work because onWritePossible...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Servlet (show other bugs)
Version: 9.0.10
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-08-10 00:16 UTC by Dapeng Zhang
Modified: 2018-08-11 15:59 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dapeng Zhang 2018-08-10 00:16:39 UTC
Steps to reproduce:

1. Enable HTTP/2 for Tomcat
<Connector port="8080" protocol="HTTP/1.1">
    <UpgradeProtocol className="org.apache.coyote.http2.Http2Protocol"/>
</Connector>

2. Deploy the following Servlet

@WebServlet(urlPatterns = {"/asyncwrite"}, asyncSupported = true)
public class AsyncWrite extends HttpServlet {
  @Override
  protected void doGet(HttpServletRequest request, HttpServletResponse response)
      throws IOException {
    final AsyncContext asyncContext = request.startAsync();

    response.setStatus(HttpServletResponse.SC_OK);
    response.setContentType("application/binary");

    final ServletOutputStream output = response.getOutputStream();
    output.setWriteListener(new WriteListener() {
      int i;
      byte[] bytes = new byte[0x10000];

      @Override
      public void onWritePossible() throws IOException {
        i++;
        System.out.println("onWritePossible called " + i + " times");

        if (i > 3) {
          System.out.println("complete");
          asyncContext.complete();
          return;
        }

        while(output.isReady()) {
          output.write(bytes);
        }

        System.out.println("output.isReady() = " + false);
      }

      @Override
      public void onError(Throwable t) {
        t.printStackTrace();
      }
    });
  }
}

3. Make sure the curl command supports HTTP/2
$ curl --version
curl 7.60.0
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

4. Run the following curl command over HTTP/1.1
$ curl "http://127.0.0.1:8080/asyncwrite" -v --output - -w 'received %{size_download} bytes\n'

No error happens. Check "logs/catalina.out" we can see

onWritePossible called 1 times
output.isReady() = false
onWritePossible called 2 times
output.isReady() = false
onWritePossible called 3 times
output.isReady() = false
onWritePossible called 4 times
complete

5. Run the following curl command over HTTP/2
$ curl  --http2 --http2-prior-knowledge  "http://127.0.0.1:8080/asyncwrite" -v --output - -w 'received %{size_download} bytes\n' 

The client hangs. Check "logs/catalina.out" we can only see
 
onWritePossible called 1 times

Actually output.write(bytes) is hanging.
Comment 1 Mark Thomas 2018-08-10 13:35:18 UTC
There is no Tomcat bug here.

The test case makes the (invalid) assumption that the network buffers will fill up and isReady() will return false. They don't.

Essentially the code enters an infinite loop here:

while(output.isReady()) {
    output.write(bytes);
}

There are multiple ways you van observe this:
- enable debug logging for the HTTP/2 (conf/logging.propeties)
- watch network traffic with Wireshark or similar
- debug Tomcat
Comment 2 Dapeng Zhang 2018-08-10 15:43:52 UTC
My fault again, sorry about that.
Comment 3 Dapeng Zhang 2018-08-10 16:08:23 UTC
Update:

I couldn't produce the bug with the "curl --output -" command because the output stream is always ready and enters an infinite loop, my bad; However, I can produce it using nghttp (see https://github.com/http2/http2-spec/wiki/Tools) client command, and this does not make it enter infinite loop.

I added more debug info in the code to make sure we can see if it's looping or not:

      @Override
      public void onWritePossible() throws IOException {
        i++;
        System.out.println("onWritePossible called " + i + " times");

        if (i > 3) {
          System.out.println("complete");
          asyncContext.complete();
          return;
        }

        int j = 0;
        while(output.isReady()) {
          System.out.println("start write j = " + j);
          output.write(bytes);
          System.out.println("write complete j = " + j);
          j++;
        }

        System.out.println("output.isReady() = " + false);
      }

Deploy it to Tomcat and call the nghttp client command
$ nghttp "http://127.0.0.1:8080/asyncwrite" -v

It hangs. Check "logs/catalina.out", onWritePossible called only 1 time, and never called back again and clearly it's not in an infinite loop this time.

onWritePossible called 1 times
start write j = 0
write complete j = 0
start write j = 1
write complete j = 1
output.isReady() = false

I also tried the same nghttp client to Jetty and Undertow, the onWritePossible callback can be called 4 times and finish.
Comment 4 Mark Thomas 2018-08-11 15:59:54 UTC
Fixed in:
- trunk for 9.0.11 onwards
- 8.5.x for 8.5.33 onwards

Whoops. Processing of an increase in window size from 0 to >0 was only triggering a write for blocking I/O. The notification for non-blocking was missing. I've added it and the test passes now.

Thanks for the report.