Kill queries after timeout for PostgreSQL

[veikovx]

This is for #707 .
Basically a copy of the mysql functionality implemented for PostgreSQL

[elhigu]

I will get back to this, when I have time to meditate on that implementation some time. Even that it is copied from mysql it doesn't automatically mean it is correct.

[kibertoad]

Should be updated to remove references to mariadb :)

[veikovx]

Thanks for the notification @kibertoad. I've merged the latest commits into my branch now.

Hoping @elhigu will have had some time to meditate over this :)

[elhigu]

I suppose this is good :) I couldn't spot anything wrong with it. I will still try this out locally to see how tests fail, when only test changes are applied, but cancel implementation is not there.

[elhigu]

Thanks for this. Code is good, but there should be link to documentation PR which adds information to docs that also postgresql now supports query canceling.

Also I would like to test that this won't leak pool connections... I added line comment about that.

[veikovx]

Associated documentation update:
knex/documentation#131

[elhigu]

Shouldn't this then be actually .finally() so that even if that release query rejects the connection will be released from pool?

[elhigu]

btw. that error case is really hard to test... without wrapping

this.query(conn, {
        method: 'raw',
        sql: 'SELECT pg_terminate_backend(?);',
        bindings: [connectionToKill.processID],
        options: {},
      })

part to a separate method, which can then be temporarily overridden to throw an error during tests.

[veikovx]

Yes it should be .finally(). Will fix. Do you suggest that I try to write a test for this case as well? I can agree that it would be quite a task.

[elhigu]

The test shouldn't be so hard to write if done in a way I mentioned. Yep test would be important to have, because someone might break this code afterwards otherwise.

[wpoch]

I'm porting this to a custom client I created in my source code in order to start using it and I have to wait until the this.releaseConnection(conn); promise resolves, otherwise, the next issued query will try to use the same conn DB connection and everything hangs.

[elhigu]

@wpoch that shouldn't be possible if releaseConnection is working correctly. But that sounds like good test case to have, in case if there is bug in knex involved.

[wpoch]

I finally implemented it this way:

    canCancelQuery: true,
    async cancelQuery(connectionToKill) {
      logger.info('Killing connection', { processID: connectionToKill.processID, __knexUid: connectionToKill.__knexUid, activeQueryText: connectionToKill.activeQuery.text });
      const connection = await this.acquireConnection();
      try {
        await this.query(connection, {
          method: 'raw',
          sql: 'SELECT pg_terminate_backend(?);',
          bindings: [connectionToKill.processID],
          options: {}
        });
        this.releaseConnection(connectionToKill);
      } finally {
        this.releaseConnection(connection);
      }
    }

These are my test cases, I would try to port them to the knex test suite if I have time in order to repro.

'use strict';

const should = require('should');
const uuid = require('node-uuid');
const injectorFactory = require('../../injector');

describe('Timeout PG Client', () => {
  const queryTimeout = 50;
  let knex;
  before(() => {
    const injector = injectorFactory({ database: { defaultQueryTimeout: queryTimeout } });
    knex = injector.get('db');
  });

  async function assertQueryIsIdle(query) {
    const { rows } = await knex.raw(`
      SELECT pid, now() - pg_stat_activity.query_start AS duration, query, state
      FROM pg_stat_activity
      WHERE state = 'active'
      AND query = ?;`,
      [query]
    );

    rows.length.should.be.equal(0);
  }

  describe('given a query that takes less', () => {
    describe('than the default timeout', () => {
      it('should complete and retrieve results', async () => {
        const result = await knex.raw(`SELECT 1 as result, pg_sleep(${ 1 / 1000})`);
        result.rows[0].result.should.be.equal(1);
      });
    });
    describe('than the specified timeout', () => {
      it('should complete and retrieve results', async () => {
        const result = await knex.raw(`SELECT 1 as result, pg_sleep(${ 1 / 1000})`)
          .timeout(queryTimeout, { cancel: true });
        result.rows[0].result.should.be.equal(1);
      });
    });
  });
  describe('given a query with an error', () => {
    it(`should throw the original error`, async () => {
      await knex.raw(`SELECT 1 as result FROM not_existing_table`)
        .should.be.rejectedWith('relation "not_existing_table" does not exist');
    });
  });
  describe('given a query that takes longer', () => {
    describe('than the default timeout', () => {
      it('should timeout and kill the underlying query', async () => {
        const sql = `SELECT 1 as result, pg_sleep(${(queryTimeout + 2) }), '${uuid.v4()}'`;
        await knex.raw(sql).should.be.rejectedWith(`Defined query timeout of ${queryTimeout}ms exceeded when running query.`);
        await assertQueryIsIdle(sql);
      });
    });
    describe('than the specified timeout', () => {
      describe('when the timeout is bigger than the default', () => {
        it('should timeout and kill the underlying query', async () => {
          const timeoutOverride = queryTimeout * 20;
          // Adding a generic UUID in order to not conflict with parallel runs
          const sql = `SELECT 1 as result, pg_sleep(${(timeoutOverride + 2)}), '${uuid.v4()}'`;
          await knex.raw(sql).timeout(timeoutOverride, { cancel: true }).should.be.rejectedWith(`Defined query timeout of ${timeoutOverride}ms exceeded when running query.`);
          await assertQueryIsIdle(sql);
        });
      });
      describe('when the timeout is smaller than the default', () => {
        it('should timeout and kill the underlying query', async () => {
          const timeoutOverride = queryTimeout / 2;
          const sql = `SELECT 1 as result, pg_sleep(${(timeoutOverride + 2) / 1000}), '${uuid.v4()}'`;
          await knex.raw(sql).timeout(timeoutOverride, { cancel: true }).should.be.rejectedWith(`Defined query timeout of ${timeoutOverride}ms exceeded when running query.`);
          await assertQueryIsIdle(sql);
        });
      });
    });
  });
});

I copied the implementation from this PR and the one from mysql and both hang on the assertQueryIsIdle method since they try to use the same DB connection that was being killed.
With my implementation, the assertQueryIsIdle method will use a different connection which is the same that's being used for executing the kill query.

[KristjanTammekivi]

What's the status on this? (aka bump)

[elhigu]

@KristjanTammekivi Last activity was when I hoped for having regression test for part which makes sure connection is released even if release fails #2636 (comment)

[kibertoad]

@veikovx There's a bunch of conflicts.

[veikovx]

Haven't found time to deal with this. Sorry about that.
@elhigu I made the separation and a test for it.
@wpoch I could not reproduce your issue. Latest test I added fails at first cancel query and then tries another query plus it's cancelling, which both succeed. With pool.max set to 2 this would mean that both cancelled and cancelling query are released. If you can reproduce it with a test that'd be great.

[esvinson]

Should this be using pg_cancel_backend instead of pg_terminate_backend? pg_terminate_backend is more heavy handed than necessary most of the time.

[elhigu]

Looking good, thanks!