Why node.couch.js Times Out After 60 Seconds

‹prev | My Chain | next›

I will figure this out.

I have traced down a node.couch.js issue to the listener's start method, which is called when the Listener object is instantiated. I had thought that the problem was timeout related because the node.js documentation states the default timeout to be 60 seconds—almost exactly when the node.couch.js script stops listening for changes.

Fiddling with the timeout value on the client, however, produced no change. So let's try a different approach. I add two more listeners to the changes listener, one for the end of the request, one for a timeout:

  var start = function () {
    c.h.setTimeout(2);
    var request = c.h.request("GET", c.url.pathname+'?'+querystring.stringify(options), {'accept':'application/json'});

    request.addListener('response', function(response) {
      response.addListener('data', changesHandler);
      response.addListener('end', function () {
 sys.puts("end");
      });
      response.addListener('timeout', function () {
 sys.puts("timeout");
      });
    });
    request.close();
  };

Running this, and waiting for a bit, I find:

cstrom@whitefall:~/repos/node.couch.js$ node ./changes/lib/service.js http://localhost:5984
end

Hrm...

So the "end" state is being reached and not "timeout". Again consulting the node.js documentation (which is excellent by the way), I see that the "end" listener fires when "the other end of the connection sends a FIN packet". Interesting, so it is CouchDB that is hanging up the connection, not the node.js script that is timing out.

I suspect that the problem might be related to the close() call in the start() method. To test this, I change close() to write():

  var start = function () {
    c.h.setTimeout(2);
    var request = c.h.request("GET", c.url.pathname+'?'+querystring.stringify(options), {'accept':'application/json'});

    request.addListener('response', function(response) {
      response.addListener('data', changesHandler);
      response.addListener('end', function () {
 sys.puts("end");
      });
      response.addListener('timeout', function () {
 sys.puts("timeout");
      });
    });
    request.write();
  };

So I re-run the script and wait:

cstrom@whitefall:~/repos/node.couch.js$ node ./changes/lib/service.js http://localhost:5984
end

That didn't help.

At this point I finally recall that I am working with HTTP (this is CouchDB, after all), not TCP. Writing to a connection with or without a close will produce a response. In other words, the close()/write() switch was useless.

HTTP 1.1 timeouts are governed by keepalive, which are configured on the server. Since I already know that the server is closing the request (based on the "end" event firing), I investigate configuring CouchDB's keepalive at which point I find the CouchDB keepalive documentation for... the changes API. It seems that one can pass a keepalive query parameter to the changes API, which defaults, not coincidentally, to 60 seconds.

Could this be culprit?

To verify, I update my start() method to request a keepalive of 5 seconds:

  var start = function () {
    var request = c.h.request("GET", c.url.pathname+'?'+querystring.stringify(options)+'&timeout=5000', {'accept':'application/json'});

    request.addListener('response', function(response) {
      response.addListener('data', changesHandler);
      response.addListener('end', function () {
 sys.puts("end");
      });
      response.addListener('timeout', function () {
 sys.puts("timeout");
      });
    });
    request.close();
  };

I run, wait 5 seconds and:

cstrom@whitefall:~/repos/node.couch.js$ node ./changes/lib/service.js http://localhost:5984
{"last_seq":77}
end

Finally, I have my answer. In retrospect, it is a pretty obvious answer, but sometimes that will happen.

I update my forked copy of node.couch.js to keepalive for 10 minutes (commit) and call it a night. With my current list of questions satisfied, I will likely move on to other node.js goodness tomorrow.

Update: seems a hearbeat also needs to be set (commit).

Day #67