Nginx timeout incorrectly invoking `done`

I’ve stumbled across a situation where needle doesn’t seem to be triggering an error event where I would expect to see one.

Description

I have a web application that slowly streams back text to the client and I have Nginx sitting out in front of my web app. I have configured Nginx to have a proxy_read_timeout directive of some number (let’s say 5 seconds).

proxy_read_timeout

Defines a timeout for reading a response from the proxied server. The timeout is set only between two successive read operations, not for the transmission of the whole response. If the proxied server does not transmit anything within this time, the connection is closed.

http://nginx.org/en/docs/http/ngx_http_proxy_module.html#proxy_read_timeout

As long as I stream out data from my web app with a delay of less than 5 seconds between each chunk of data, everything works fine.

But, if I have my backend sleep for 6 seconds during the call, Nginx will kill the socket after 5 seconds of waiting (again, this is what it is supposed to do).

When this happens, needle fires the 'done' event and is passes in a null/undefined err object. Thus, to my code, it looks like everything about the request completed successfully. However, it obviously did not. Needle didn’t timeout, but Ngnix did.

Other Clients

When I hit this endpoint in other clients, I do get some sort of error returned.

cUrl

cUrl (with trace-ascii)

~/dev
❯ curl http://localhost:2020/printing/streaming-test\?w\=6 --trace-ascii -
== Info:   Trying ::1...
== Info: TCP_NODELAY set
== Info: Connection failed
== Info: connect to ::1 port 2020 failed: Connection refused
== Info:   Trying 127.0.0.1...
== Info: TCP_NODELAY set
== Info: Connected to localhost (127.0.0.1) port 2020 (#0)
=> Send header, 105 bytes (0x69)
0000: GET /printing/streaming-test?w=6 HTTP/1.1
002b: Host: localhost:2020
0041: User-Agent: curl/7.64.1
005a: Accept: */*
0067: 
<= Recv header, 17 bytes (0x11)
0000: HTTP/1.1 200 OK
<= Recv header, 22 bytes (0x16)
0000: Server: nginx/1.17.9
<= Recv header, 37 bytes (0x25)
0000: Date: Fri, 06 Mar 2020 16:24:35 GMT
<= Recv header, 28 bytes (0x1c)
0000: Transfer-Encoding: chunked
<= Recv header, 24 bytes (0x18)
0000: Connection: keep-alive
<= Recv header, 2 bytes (0x2)
0000: 
<= Recv data, 17 bytes (0x11)
0000: c
0003: Hello there.
Hello there
== Info: transfer closed with outstanding read data remaining
== Info: Closing connection 0
curl: (18) transfer closed with outstanding read data remaining

Paw

Related GitHub Issues

GitHub suggested a couple of other tickets I should look at, specifically https://github.com/tomas/needle/issues/84 and https://github.com/tomas/needle/issues/125. Both of these seemed like different issues to me. I have my needle timeouts configured how I’d like, I’m not trying to change when needle times out, I want it to be able to recognize when Nginx does.

Reproduction

Here’s the needle code I’m using.

var needle = require('needle');

var stream = needle.get(' http://localhost:2020/printing/streaming-test?w=6');

// print out the data as it is streamed back from the server
stream.on('readable', function() {
  while (data = this.read()) {
    console.log(data.toString());
  }
});

// look for timeouts
stream.on('timeout', function() {
  console.log('timeout!');
});

// look for errors
stream.on('err', function() {
  console.log('error!');
});

stream.on('done', function(err) {
  // if our request had an error, our 'done' event will tell us.
  if (err) {
    console.log('All done with error: ' + err);
  } 
  else {
    console.log('All done!');
  }
});

Here is my backend web app (yeah, I know Java isn’t cool anymore).

public class StreamingTestServlet extends HttpServlet {

    @Override
    protected void doGet(@NotNull final HttpServletRequest request, @NotNull final HttpServletResponse response) throws IOException {
        // this is necessary to turn off proxy and ssl buffering in Nginx and
        // have the data sent directly back to the client with no waiting
        response.setHeader("X-Accel-Buffering", "no");

        final PrintWriter pw = response.getWriter();

        // the client can pass in how many iterations to run through
        // defaults to 10
        final String iterationParam = request.getParameter("i");
        int iterations;
        try {
            iterations = Integer.parseInt(iterationParam, 10);
        } catch (Exception e) {
            iterations = 10;
        }

        pw.println("Hello there");
        pw.flush();

        // the client can pass in a value to sleep for, good for forcing Nginx to timeout
        // defaults to no sleeping
        if (request.getParameter("w") != null) {
            try {
                Thread.sleep(Integer.parseInt(request.getParameter("w"), 10) * 1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }

        for (int i = 1; i <= iterations; i++) {
            pw.println(i);
            pw.flush();
            sleep(1);
        }

        pw.println("Goodbye");
    }

    private void sleep(final long seconds) {
        try {
            Thread.sleep(seconds * 1000);
        } catch (Exception ignored) { }
    }
}

And finally, here’s the relevant chunks of my Nginx config.

location /printing {
  proxy_pass http://printing_backend;
  proxy_http_version 1.1;
  proxy_read_timeout 5s;
}

upstream printing_backend {
  server 127.0.0.1:8080; # this is where Tomcat is running my Java code
  keepalive 64;
}

When I run this myself, here is the output:

No timeout event, no err event, not even an error object in the done event.

I would ideally be able to trap this case and handle it accordingly (e.g., telling the user the request failed instead of telling that it was successful).

Hopefully all this makes sense, I tried to find a resource online where I could mock up this server-side behavior and use RunKit or something to provide a reproducible case, but I wasn’t able to find something I thought would mock this exact backend situation. If you need help getting something together to see this in action, let me know, I can see if I can pull something together.

Thanks!

tomas / needle