Wednesday, April 7, 2010

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

No comments:

Post a Comment