pg.on('error') does not remove client idle timers

[troyk]

I'm listening to pg.on('error') and terminate the clients server process (to simulate restarting the server). The error fires and the client passed to the error has an empty queryQueue.

A few moments after the error, the following process level error is thrown:

timers.js:96
            if (!process.listeners('uncaughtException').length) throw e;
                                                                      ^
Error: This socket is closed.
    at Socket._write (net.js:453:28)
    at Socket.write (net.js:446:15)
    at [object Object]._send (/Users/troy/Projects/blit.js/node_modules/pg/lib/connection.js:102:24)
    at [object Object].end (/Users/troy/Projects/blit.js/node_modules/pg/lib/connection.js:206:8)
    at [object Object].end (/Users/troy/Projects/blit.js/node_modules/pg/lib/client.js:211:19)
    at Object.destroy (/Users/troy/Projects/blit.js/node_modules/pg/lib/index.js:76:14)
    at Object.destroy (/Users/troy/Projects/blit.js/node_modules/pg/node_modules/generic-pool/lib/generic-pool.js:123:13)
    at Object.removeIdle [as _onTimeout] (/Users/troy/Projects/blit.js/node_modules/pg/node_modules/generic-pool/lib/generic-pool.js:148:12)
    at Timer.ontimeout (timers.js:94:19)

[brianc]

Could you attach example code on how to reproduce?

[troyk]

Sorry about that, should of done that already as it pointed out a specific nature of the bug. Notice in the code below that I have commented out the query "SELECT pg_terminate_backend((SELECT pg_backend_pid()))" as it seems the bug will not reproduce when an error is fired on a client query (I even tried using nested pg.connect to kill the process from another connection).

To get the bug, the error has to be caused from outside the pg/node scope, thus the call to exec. It takes about 30 seconds for the error to fire, I think that's the default idle timeout.

I am using pg 0.6.18 and postgres 9.1.3

var connStr = "tcp://troy@localhost/template1",
    exec    = require('child_process').exec
pg.connect(connStr,function(err,client){
  //client.query("SELECT pg_terminate_backend((SELECT pg_backend_pid()))",function(err,result){
  client.query("SELECT pg_backend_pid()",function(err,result){
    var pid = result.rows[0].pg_backend_pid;
    console.log('terminating: ', pid);
    exec('psql -c "select pg_terminate_backend('+pid+')" template1',
      function (error, stdout, stderr) {
        console.log('stdout: ' + stdout);
        console.log('stderr: ' + stderr);
        if (error !== null) {
          console.log('exec error: ' + error);
        }
        console.log('\u001b[31mwaiting for error (about 30 secs), note pg_terminate_backend should === t\u001b[0m');
    });
  });
});
pg.on('error',function(err,client){
  console.log('pg::error',{err:err, client:client});
});

setTimeout(function(){
  console.log('done');
},60*1000*5);

Here is the console from the above code:

terminating:  96065
pg::error { err: 
   { [error: terminating connection due to administrator command]
     length: 109,
     name: 'error',
     severity: 'FATAL',
     code: '57P01',
     detail: undefined,
     hint: undefined,
     position: undefined,
     internalPosition: undefined,
     internalQuery: undefined,
     where: undefined,
     file: 'postgres.c',
     line: '2894',
     routine: 'ProcessInterrupts' },
  client: 
   { user: 'troy',
     database: 'template1',
     port: 5432,
     host: 'localhost',
     connection: 
      { stream: [Object],
        lastBuffer: <Buffer 54 00 00 00 27 00 01 70 67 5f 62 61 63 6b 65 6e 64 5f 70 69 64 00 00 00 00 00 00 00 00 00 00 17 00 04 ff ff ff ff 00 00 44 00 00 00 0f 00 01 00 00 00 05 ...>,
        lastOffset: 76,
        buffer: <Buffer 45 00 00 00 6d 53 46 41 54 41 4c 00 43 35 37 50 30 31 00 4d 74 65 72 6d 69 6e 61 74 69 6e 67 20 63 6f 6e 6e 65 63 74 69 6f 6e 20 64 75 65 20 74 6f 20 61 ...>,
        offset: 110,
        encoding: 'utf8',
        parsedStatements: {},
        writer: [Object],
        _events: [Object] },
     queryQueue: [],
     password: null,
     binary: false,
     encoding: 'utf8',
     processID: 96065,
     secretKey: 1349540892,
     _events: { drain: [Function], error: [Function] },
     activeQuery: null,
     readyForQuery: true,
     hasExecuted: true } }
stdout:  pg_terminate_backend 
----------------------
 t
(1 row)


stderr: 
waiting for error (about 30 secs), note pg_terminate_backend should === t

timers.js:96
            if (!process.listeners('uncaughtException').length) throw e;
                                                                      ^
Error: This socket is closed.
    at Socket._write (net.js:453:28)
    at Socket.write (net.js:446:15)
    at [object Object]._send (/Users/troy/Projects/blit.js/node_modules/pg/lib/connection.js:102:24)
    at [object Object].end (/Users/troy/Projects/blit.js/node_modules/pg/lib/connection.js:206:8)
    at [object Object].end (/Users/troy/Projects/blit.js/node_modules/pg/lib/client.js:211:19)
    at Object.destroy (/Users/troy/Projects/blit.js/node_modules/pg/lib/index.js:76:14)
    at Object.destroy (/Users/troy/Projects/blit.js/node_modules/pg/node_modules/generic-pool/lib/generic-pool.js:123:13)
    at Object.removeIdle [as _onTimeout] (/Users/troy/Projects/blit.js/node_modules/pg/node_modules/generic-pool/lib/generic-pool.js:148:12)
    at Timer.ontimeout (timers.js:94:19)

[brianc]

Thank you for the detailed bug report. I'll publish a new version to npm tonight.

[troyk]

Wow, thanks for fixing this so fast!

[brianc]

👍

Thanks for the detailed bug report.