Pg-promise: Abnormal client.end() with task and tx

[boromisp]

What happens:

If the connection to the database is lost while a transaction is in progress, the following error is displayed:

Abnormal client.end() call, due to invalid code or failed server connection.
    at BoundPool.Pool._destroy ([...]\test\node_modules\pg-pool\index.js:82:10)
    at Pool.destroy ([...]\test\node_modules\generic-pool\lib\generic-pool.js:193:17)
    at BoundPool.<anonymous> ([...]\test\node_modules\pg-pool\index.js:91:15)
    at Client.<anonymous> ([...]\test\node_modules\pg\lib\client.js:199:19)

and the transaction promise is rejected with the following error:

TypeError: Cannot read property 'client' of null
    at update ([...]\test\node_modules\pg-promise\lib\task.js:210:27)
    at callback.then.then.reason ([...]\test\node_modules\pg-promise\lib\task.js:248:21)

What I expected to happen:

Reject the tx (or task) with some kind of standard error type and message in case of unexpected disconnect(, without printing an additional error messages).

How to reproduce:

Start running the script below, and while it runs, stop, or restart the postgresql server.

'use strict';

const pgp = require('pg-promise')();

const cn = {
  user: 'postgres',
  host: '...',
  port: 5432,
  database: 'testdb'
};

pgp(cn).tx(function f() {
  return this.one('SELECT clock_timestamp()')
    .then(r => console.log('s', r), e => console.error('s', e))
    .then(() => new Promise(r => setTimeout(r, 1000)))
    .then(f.bind(this));
}).then(r => console.log('t', r), e => console.error('t', e));

If I use only a task, instead of a transaction, the error is similar:

Abnormal client.end() call, due to invalid code or failed server connection.
    at BoundPool.Pool._destroy ([...]\test\node_modules\pg-pool\index.js:82:10)
    at Pool.destroy ([...]\test\node_modules\generic-pool\lib\generic-pool.js:193:17)
    at BoundPool.<anonymous> ([...]\test\node_modules\pg-pool\index.js:91:15)
    at Client.<anonymous> ([...]\test\node_modules\pg\lib\client.js:199:19)

TypeError: Cannot read property 'client' of null
    at update ([...]\test\node_modules\pg-promise\lib\task.js:210:27)
    at callback.then.catch.error ([...]\test\node_modules\pg-promise\lib\task.js:291:13)

Proper error events should have been implemented in https://github.com/brianc/node-postgres/pull/1316 for similar use cases, maybe this is connected in some way.

System info

• Server:
  
  
  
  • Ubuntu 16.04 LTE (AWS EC2 eu-west-1)
  
  
  • Postgres 9.6.5
  
  
• Client:
  
  
  
  • Windows 10
  
  
  • node 8.5.0 (also tested on 7.7.4)
  
  
  • pg-promise 6.5.2
  
  

[vitaly-t]

The first message - Abnormal client.end() is spot on, it is there by design, and it is always displayed because the loss of connection is considered the most severe type of error in the library. And the other possible reason - invalid code should definitely be reported. Those two manifest themselves in the same way, unfortunately - client.end() is invoked directly, and no way of telling which one happened at that point.

The second one - TypeError: Cannot read property 'client' of null is due to uncertain state of the task/transaction in that case, and depends on what is happening inside those. Why that specific error happens in your case - I'm not sure, would need to debug it. But in general, as long as both reject, it is not a big issue, imo.

I will look at the second message later on and see if I can reproduce it.

[vitaly-t]

A new release v6.5.3 addresses the issue with the second error type, making it consistent with how query methods fail in case they are executed against a released connection, producing an error such as Error: Unexpected call outside of task/transaction.

This is the best the library can deduct for the situations when connection is lost while inside a task or transaction. It is impossible to detect it any better, as it is impossible to determine whether the disconnection occurred before or after running the last query within it, which makes it uncertain whether the task should be considered a success or failure.

At least the error that's reported is now consistent, and not something caused by the task engine internally as it was before.

As for the first error type, as I wrote earlier, it is there by design.

@boromisp Thank you for reporting the issue! I hope you will find the fix satisfying.

[vitaly-t]

Release 6.5.4 is a further improvement on this.

@boromisp any feedback?

[boromisp]

Thanks for your quick response!
I haven't looked at 6.5.4 yet, but the changes in 6.5.3 addressed my original concern.

When I started testing 6.5.3, found a case, where a transaction rejection got lost with nodejs native Promise.

If during a transaction (db.tx(...)) the connection breaks while a query is being executed (eg. SELECT pg_sleep(15)), the inner promise gets rejected correctly, but when the execution reaches the error handler of the db.tx, and it tries to rollback the change, the promise returned from query never resolves.

The stack trace of the query in question:

Trace: return
    at $p ([...]\test\node_modules\pg-promise\lib\query.js:229:17)
    at Promise (<anonymous>)
    at promise ([...]\test\node_modules\pg-promise\lib\promise.js:23:20)
    at Task.$query ([...]\test\node_modules\pg-promise\lib\query.js:129:12)
    at Task.<anonymous> ([...]\test\node_modules\pg-promise\lib\query.js:235:23)
    at Task.query ([...]\test\node_modules\pg-promise\lib\task.js:106:36)
    at Task.obj.none ([...]\test\node_modules\pg-promise\lib\database.js:473:30)
    at exec ([...]\test\node_modules\pg-promise\lib\task.js:301:22)
    at rollback ([...]\test\node_modules\pg-promise\lib\task.js:292:16)
    at callback.then.reason ([...]\test\node_modules\pg-promise\lib\task.js:241:32)

The test code:

pgp(cn).tx(t => t.any('SELECT pg_sleep(15)')
    .catch(e => {
      console.error('inside', e);   // error: terminating connection due to administrator command
      throw e;
    }))
  .then(r => console.log('outside', r))  // never reaches neither this line
  .catch(e => console.error('outside', e))  // nor this one
  .then(() => console.log('tx finished'));   // nor this one

Interestingly, when using bluebird as promiseLib, I got the expected 'Error: Unexpected call outside of transaction' error on the outside.

Update
It is probably some kind of timing issue, because with native Promise at this line: https://github.com/vitaly-t/pg-promise/blob/ede77b39c2d7cb1951cee72775cc6f5fa61071c9/lib/task.js#L101 ctx.db is still not null.

Update 2
I experimented a bit with travis, if you want to, you can restart postgres during tests like this:

const { exec } = require('child_process');

exec('sudo service postgresql restart', function (err, stdout, stderr) {
  if (err) {
    console.error(err); // node couldn't execute the command
    return;
  }

  // the *entire* stdout and stderr (buffered)
  console.log(`stdout: ${stdout}`);
  console.log(`stderr: ${stderr}`);
});

[vitaly-t]

I was able to reproduce the problem, and I have found the cause, which is with the driver - node-postgres.

[vitaly-t]

Here I have reported the issue: https://github.com/brianc/node-postgres/issues/1454

[vitaly-t]

Reopening as an existing issue, although it seems to be only relevant to transactions, but not tasks.

[vitaly-t]

@boromisp congrats, mate! you've raised a deado! 💀🤣

...a very old issue that got 3 dupes at this point.

[vitaly-t]

After reviewing the issue, I've decided to close it, at least for now, for the following reasons:

• The main issue that was reported here was fixed and re-released
• The secondary issue here is strictly a bug in the node-postgres dependency, which was reported, and is unknown how long it is gonna take BrianC to fix, as it was reported in duplicated or directly related issues a number of times.

The bottom line is, there is nothing actionable for this module at this point. When the driver resolves the issue, it will be automatically resolved for pg-promise.

[vitaly-t]

Re-opening the issue, to start working on a work-around, since there is still no solution to this on the driver side. Removed label low frequency, since the issue also manifests itself when dealing with a slow network.

[vitaly-t]

I'm looking for some feedback, of whether this PR solves the issue, as a work-around: https://github.com/vitaly-t/pg-promise/pull/456

@boromisp @Raphyyy

[vitaly-t]

Release 7.5.4 should fix the secondary issue that was reported in the beginning.