Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Cause jest integration tests to play nicely with tinypg/pg.pool on connection errors #53

Closed
bickelj opened this issue Jul 21, 2022 · 5 comments
Closed

Cause jest integration tests to play nicely with tinypg/pg.pool on connection errors #53

bickelj opened this issue Jul 21, 2022 · 5 comments

Comments

@bickelj
Copy link
Contributor

bickelj commented Jul 21, 2022

Expected behavior:

An error (such as failure to connect) during an integration test causes that test to fail shortly after the error, whether that occurs in a before section of the test or the test itself.

Actual behavior:

Timeouts occur as well as "open handles potentially keeping Jest form exiting."

Example debug logs from a draft opportunities.int.test.ts:

$ npm run test:integration | node node_modules/pino-pretty/bin.js

> @pdc/service@0.0.0 test:integration
> jest --config=jest.config.int.js --detectOpenHandles --runInBand

[2022-07-21T17:23:59.145Z] DEBUG (88928 on local): About to set/call afterAll with a function that will close db.
    source: "test/integrationSuiteSetup"
[2022-07-21T17:23:59.152Z] DEBUG (88928 on local): Finished set/call afterAll with a function that will close db.
    source: "test/integrationSuiteSetup"
[2022-07-21T17:23:59.672Z] DEBUG (88928 on local): About to define function getCanonicalFields
    source: "handlers/canonicalFieldsHandlers"
[2022-07-21T17:23:59.675Z] DEBUG (88928 on local): About to define function getOpportunities
    source: "handlers/opportunitiesHandlers"
[2022-07-21T17:23:59.680Z] DEBUG (88928 on local): About to define the createSchema function
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.680Z] DEBUG (88928 on local): About to define the setSchema function
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.680Z] DEBUG (88928 on local): About to define the dropSchema function
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.680Z] DEBUG (88928 on local): About to define the prepareDatabaseForCurrentWorker function
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.680Z] DEBUG (88928 on local): About to define the cleanupDatabaseForCurrentWorker function
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.681Z] DEBUG (88928 on local): About to describe /opportunities
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.681Z] DEBUG (88928 on local): About to call/set beforeEach in /opportunities
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.681Z] DEBUG (88928 on local): About to call/set afterEach in /opportunities
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.681Z] DEBUG (88928 on local): About to describe / in /opportunities
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.682Z] DEBUG (88928 on local): Describing / in /opportunities called
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.686Z] DEBUG (88928 on local): beforeEach function in /opportunities called
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.686Z] DEBUG (88928 on local): beforeEach function in /opportunities: about to call prepareDatabaseForCurrentWorker
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:23:59.687Z] DEBUG (88928 on local): prepareDatabaseForCurrentWorker function was called
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.687Z] DEBUG (88928 on local): prepareDatabaseForCurrentWorker: about to await createSchema
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.688Z] DEBUG (88928 on local): createSchema function was called
    source: "test/harnessFunctions"
[2022-07-21T17:23:59.688Z] DEBUG (88928 on local): createSchema: about to await a query
    source: "test/harnessFunctions"
[2022-07-21T17:24:06.691Z] DEBUG (88928 on local): afterEach function in /opportunities called
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): afterEach function in /opportunities: about to call cleanupDatabaseForCurrentWorker
    source: ".__tests__/opportunities.int.test"
[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): cleanupDatabaseForCurrentWorker function was called
    source: "test/harnessFunctions"
[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): cleanupDatabaseForCurrentWorker: about to return await dropSchema
    source: "test/harnessFunctions"
[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): dropSchema function was called
    source: "test/harnessFunctions"
[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): dropSchema: about to await a query
    source: "test/harnessFunctions"
[2022-07-21T17:24:13.727Z] DEBUG (88928 on local): Function passed to afterAll was called.
    source: "test/integrationSuiteSetup"
FAIL src/__tests__/opportunities.int.test.ts (24.406 s)
  ● /opportunities › / › should return HTTP Status Code 200 OK

    SASL: SCRAM-SERVER-FIRST-MESSAGE: client password must be a string

      at Object.continueSession (node_modules/pg/lib/sasl.js:24:11)
      at Client._handleAuthSASLContinue (node_modules/pg/lib/client.js:257:10)
      at node_modules/pg/lib/connection.js:114:12
      at Parser.parse (node_modules/pg-protocol/src/parser.ts:104:9)
      at Socket.<anonymous> (node_modules/pg-protocol/src/index.ts:7:48)

  ● /opportunities › / › should return HTTP Status Code 200 OK

    thrown: "Exceeded timeout of 7000 ms for a hook.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

      15 |
      16 |   logger.debug('About to call/set beforeEach in /opportunities');
    > 17 |   beforeEach(() => {
         |   ^
      18 |     logger.debug('beforeEach function in /opportunities called');
      19 |     if (!pool) {
      20 |       throw new Error("No pool connection!");

      at src/__tests__/opportunities.int.test.ts:17:3
      at Object.<anonymous> (src/__tests__/opportunities.int.test.ts:14:1)

  ● /opportunities › / › should return HTTP Status Code 200 OK

    SASL: SCRAM-SERVER-FIRST-MESSAGE: client password must be a string

      at Object.continueSession (node_modules/pg/lib/sasl.js:24:11)
      at Client._handleAuthSASLContinue (node_modules/pg/lib/client.js:257:10)
      at node_modules/pg/lib/connection.js:114:12
      at Parser.parse (node_modules/pg-protocol/src/parser.ts:104:9)
      at Socket.<anonymous> (node_modules/pg-protocol/src/index.ts:7:48)

  ● /opportunities › / › should return HTTP Status Code 200 OK

    thrown: "Exceeded timeout of 7000 ms for a hook.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

      25 |
      26 |   logger.debug('About to call/set afterEach in /opportunities');
    > 27 |   afterEach(() => {
         |   ^
      28 |     logger.debug('afterEach function in /opportunities called');
      29 |     if (!pool) {
      30 |       throw new Error("No pool connection!");

      at src/__tests__/opportunities.int.test.ts:27:3
      at Object.<anonymous> (src/__tests__/opportunities.int.test.ts:14:1)


  ● Test suite failed to run

    thrown: "Exceeded timeout of 7000 ms for a hook.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

       9 |
      10 | logger.debug('About to set/call afterAll with a function that will close db.');
    > 11 | afterAll(async () => {
         | ^
      12 |   logger.debug('Function passed to afterAll was called.');
      13 |   if (db.pool)
      14 |   {

      at Object.<anonymous> (src/test/integrationSuiteSetup.ts:11:1)

[2022-07-21T17:24:21.077Z] DEBUG (88928 on local): About to set/call afterAll with a function that will close db.
    source: "test/integrationSuiteSetup"
[2022-07-21T17:24:21.078Z] DEBUG (88928 on local): Finished set/call afterAll with a function that will close db.
    source: "test/integrationSuiteSetup"

The key spot seems to be this:

[2022-07-21T17:24:06.693Z] DEBUG (88928 on local): dropSchema: about to await a query
    source: "test/harnessFunctions"
[2022-07-21T17:24:13.727Z] DEBUG (88928 on local): Function passed to afterAll was called.
    source: "test/integrationSuiteSetup"

The seven second hang occurs there, and there is no mention of the dropSchema finishing that query, nor is there any error logged, here is the relevant code from harnessFunctions:

logger.debug('About to define the createSchema function');
const createSchema = async (schemaName: string): Promise<void> => {
  logger.debug('createSchema function was called');
  if (!db.pool) {
    const message = "createSchema: NO POOL PRESENT!";
    logger.warn(message);
    throw new Error(message);
  }
  try {
    logger.debug('createSchema: about to await a query');
    await db.query(`CREATE SCHEMA IF NOT EXISTS ${schemaName};`);
    logger.debug('createSchema: finished await for a query');
  }
  catch (error: any) {
    logger.warn(error);
    throw error;
  }
};

I would expect to see a warn mesage or the error itself long before a timeout here.

Here is the beforeEach call in opportunities.int.test:

logger.debug('About to describe /opportunities');
describe('/opportunities', () => {

  logger.debug('About to call/set beforeEach in /opportunities');
  beforeEach(() => {
    logger.debug('beforeEach function in /opportunities called');
    if (!pool) {
      throw new Error("No pool connection!");
    }
    logger.debug('beforeEach function in /opportunities: about to call prepareDatabaseForCurrentWorker');
    return prepareDatabaseForCurrentWorker();
  });
@bickelj bickelj mentioned this issue Jul 21, 2022
Closed
@bickelj
Copy link
Contributor Author

bickelj commented Jul 25, 2022

It may actually be a supertest issue, not so much tinypg nor jest or pg.pool:
ladjs/supertest#520

@bickelj
Copy link
Contributor Author

bickelj commented Jul 25, 2022

One thing that seemed to help a bit was putting client.release(); in a finally block in database/migrate.ts

@bickelj
Copy link
Contributor Author

bickelj commented Jul 25, 2022

Explicitly getting a client and doing client.release() in a finally block in the test/harnessFunctions.ts functions seems to help as well.

@bickelj
Copy link
Contributor Author

bickelj commented Jul 25, 2022

Jest still thinks we are leaking memory, though:

    Your test suite is leaking memory. Please ensure all references are cleaned.

    There is a number of things that can leak memory:
      - Async operations that have not finished (e.g. fs.readFile).
      - Timers not properly mocked (e.g. setInterval, setTimeout).
      - Keeping references to the global scope.

      at onResult (node_modules/@jest/core/build/TestScheduler.js:188:18)
      at node_modules/@jest/core/build/TestScheduler.js:300:17
      at node_modules/emittery/index.js:311:13
          at Array.map (<anonymous>)
      at Emittery.emit (node_modules/emittery/index.js:309:23)```

bickelj added a commit that referenced this issue Jul 25, 2022
@bickelj
Release the db client on migrate every time
370bcc1 
This seems to help integration tests finish properly when there are
failures related to database setup or tear-down.

Issue #53  Cause jest integration tests to play nicely with tinypg
@bickelj bickelj mentioned this issue Jul 25, 2022
Merged
@bickelj
Copy link
Contributor Author

bickelj commented Jul 26, 2022

There might be other issues but the main issue as described in the original post above is resolved for now.

@bickelj bickelj closed this as completed Jul 26, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@bickelj