Connection pool broken in Node 0.5.6?

[chowey]

This problem only came up with Node 0.5.6. I send a request to a postgresql database, wait a minute, and then send another request. It breaks.

Try the following code:

var pg = require('pg'),
    util = require('util');
var connectstring = 'pg://postgres:1234@127.0.0.1/postgres';

function getTheTime() {
  pg.connect(connectstring, function (err, client) {
    client.query('SELECT now() as when', function (err, result) {
      util.log('The postres time is: ' + result.rows[0].when);
    });
  });
}

getTheTime();
setTimeout(getTheTime, 60 * 1000);

The first getTheTime works fine, and the second getTheTime throws the following error:

node.js:203
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
Error: read UNKNOWN
    at errnoException (net_uv.js:557:11)
    at TCP.onread (net_uv.js:326:20)

I am running Node 0.5.6 on Windows. It only happens with a delay between the two requests. Sending requests repeatedly works fine. Therefore, some new feature in Node 0.5.6 must be dropping the connection?

[brianc]

I can take a look at this tomorrow, but in general 0.5.x is mega-buggy and windows support isn't really heavily tested yet. I don't plan on investing a large amount of time into windows support until we get closer to a 0.6.0 release candidate. At that point I will be fully committed to bringing the highest quality windows-node-postgres support out you can get. :) (also, pull requests are major appreciated)

[chowey]

The problem specifically occurs when the generic-pool timeout occurs, connection.end() is called, which calls connection._send(x058).

Note also that connection.end is defined twice:

89   var termBuffer = new Buffer([0x58, 0, 0, 0, 4]);
90   p.end = function() {
91     var wrote = this.stream.write(termBuffer);
92   };
...
183  p.end = function() {
184    //0x58 = 'X'
185    this.writer.add(emptyBuffer);
186    this._send(0x58);
187  };

The connection.end() on lines 90-92 is never called, so it could be removed as a cosmetic point.

[marcelklehr]

This error occured to me (also on windows), when a tcp socket in node between node A and node B was closed simply using socket.end on node B. Node B stopped and printed the above error...

[brianc]

@marcelklehr could you gist an example? You're saying this is outside of node-postgres and related to the windows/libuv node growing pains?

[marcelklehr]

http://gist.github.com/1280896

[chowey]

I actually tried my own code again with node v0.5.9, and things seem to be working again.

Obviously was a node issue, sorry to have put it here.

[chowey]

Erm, still getting the error though for my production code. Will see if I can isolate it further.

[chowey]

The errors still occur but I can safely ignore them:

process.on('uncaughtException', function (err) {
  console.log('Caught exception: ' + err);
});

It seems that postgresql drops the TCP connection in an unfriendly way when the pg module ends the connection (writes 0x58). This pops an error in Node as @marcelklehr says. Can we get a nice TCP disconnection from postgresql?

[brianc]

So this only happens for you on windows? Can you tell me your operating system, postgres version, and version of node? I appreciate you helping narrow down the problem. Does your original example code in this issue still reproduce the bug? I need the simplest piece of code that can possibly reproduce the bug...I'll take a look at it some time this week.

[chowey]

My original example code still reproduces the bug.

If I remember correctly, back in the Node v0.5.6 days, when I ignored the error using the process.on('uncaughtException', ...) trick, pg became useless (unable to open new connections). I am not totally certain about this though.

Anyway, now in the Node v0.5.9 days, when I ignore the error as above, pg can still open new connections. So it is not 'broken' per-say, it just throws an error 30 seconds after a connection is used (when generic-pool closes it).

Per @marcelklehr's gist (which I tried too), Node now throws an error any time a TCP socket exits unexpectedly (such as by throwing an error, or by closing a terminal window). This may or may not be considered a bug in Node, because it may or may not be considered expected behavior.

Presumably, when we send 0x58 to postgresql to end the connection, postgresql just drops it and doesn't exit cleanly. I am not sure what Node considers a "clean" close (maybe expecting the FIN packet?) but there you have it. pg now throws an error 30 seconds after any connection is used.

I am using Windows 7 32-bit, Node v0.5.9, and postgresql v8.4.

[chowey]

Bug is gone with latest version of node (0.5.10) and pg (0.6.4).