Node.js Timeout

‹prev | My Chain | next›

Picking back up with node.couch.js node.js library, there is one mystery that I have yet to solve: why the changes stop coming though after about 60 seconds and end with a "last_seq":

cstrom@whitefall:~/repos/node.couch.js/changes$ node ./lib/service.js http://localhost:5984
{"seq":73,"id":"2002-08-26-grilled_chicken","changes":[{"rev":"23-737b0bac46bbb1b07a0af879d42eaded"}]}
{"last_seq":73}

In the code, there is a 60 second setInterval:

          setInterval(function ()  {
     alldbs(couchdbUrl.port, couchdbUrl.hostname, pathname, function(dbs) {
              var newdbs = [];
       dbs.forEach( function(db) {
  if (!deligation.changes[db]) { newdbs.push(db); }
              });
              attachAllDbs(newdbs);
     });
          }, 60 * 1000);

If I change that to 2 seconds, that produces requests to all_dbs every 2 seconds:

[Thu, 08 Apr 2010 02:14:24 GMT] [debug] [<0.5434.0>] 'GET' /_all_dbs {1,1}
Headers: [{'Connection',"close"}]

[Thu, 08 Apr 2010 02:14:24 GMT] [debug] [<0.5434.0>] OAuth Params: []

[Thu, 08 Apr 2010 02:14:24 GMT] [info] [<0.5434.0>] 127.0.0.1 - - 'GET' /_all_dbs 200

[Thu, 08 Apr 2010 02:14:26 GMT] [debug] [<0.5437.0>] 'GET' /_all_dbs {1,1}
Headers: [{'Connection',"close"}]

[Thu, 08 Apr 2010 02:14:26 GMT] [debug] [<0.5437.0>] OAuth Params: []

[Thu, 08 Apr 2010 02:14:26 GMT] [info] [<0.5437.0>] 127.0.0.1 - - 'GET' /_all_dbs 200

But I still end up with a last_seq after 60 seconds:

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

Eventually, however, I do get yet another "last_seq" dumped and see this in the log:

[Thu, 08 Apr 2010 02:14:27 GMT] [info] [<0.5342.0>] 127.0.0.1 - - 'GET' /seed/_changes?feed=continuous&since=75 200

[Thu, 08 Apr 2010 02:14:27 GMT] [info] [<<0.5343.0>] 127.0.0.1 - - 'GET' /test/_changes?feed=continuous&since=138 200

[Thu, 08 Apr 2010 02:14:27 GMT] [info] [<0.5345.0>] 127.0.0.1 - - 'GET' /eee/_changes?feed=continuous&since=6133 200

On a hunch, well process of elimination really, I identify the Listener.start function as a possible culprit:

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

I suspect that the output is coming from the changesHandler, which was uploaded to a design document in the CouchDB database to print out any changes. Why this is firing off after 60 seconds, I do not know. To test my theory, I no longer pass the changesHandler directly in the addListener, but wrap it in an anonymous function that prints an I-am-here statement:

  var start = function () {
    var request = c.h.request("GET", c.url.pathname+'?'+querystring.stringify(options), {'accept':'application/json'});
    request.addListener('response', function(response) {
      response.addListener('data', function (data) {
 sys.puts("here");
 changesHandler(data);
      });
    });
    request.close();
  };

Running the code now, I find:

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



here
{"last_seq":75}
here
here
here
here
here

Yup, it's getting called right before becoming non-responsive. At this point, I begin to suspect that node.js has some sort of default timeout set on HTTP connections. Checking the documentation, I find:

connection.setTimeout(timeout)
Sets the connection to timeout after timeout milliseconds of inactivity on the connection. By default all tcp.Connection objects have a timeout of 60 seconds (60000 ms).

If timeout is 0, then the idle timeout is disabled.

Ah ha! That seems very likely to be the source of my consternation. I will follow up with that a bit more tomorrow.

Day #66