Lisk-sdk: Jest Integration tests are failing randomly

[yatki]

Expected behavior

Integration tests should run without a problem.

Actual behavior

Jest integration tests are randomly failing due to database connection failure. It might be related to database connection pool sizes of the PgHelper class.

Example output:

[2019-09-30T12:54:30.100Z] Summary of all failing tests
[2019-09-30T12:54:30.100Z] FAIL framework/test/jest/integration/specs/modules/chain/components/storage/entities/round_delegates/get_active_delegates_for_round.spec.js (18.802s)
[2019-09-30T12:54:30.100Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round) › should return list of round delegates
[2019-09-30T12:54:30.100Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round) › should return list of round delegates
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     error: relation "round_delegates" does not exist
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseE (node_modules/pg/lib/connection.js:554:11)
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseMessage (node_modules/pg/lib/connection.js:379:19)
[2019-09-30T12:54:30.101Z]       at Socket.<anonymous> (node_modules/pg/lib/connection.js:119:22)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round) › should return list of round delegates
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     error: relation "round_delegates" does not exist
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseE (node_modules/pg/lib/connection.js:554:11)
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseMessage (node_modules/pg/lib/connection.js:379:19)
[2019-09-30T12:54:30.101Z]       at Socket.<anonymous> (node_modules/pg/lib/connection.js:119:22)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round: nonExistingRound) › should return an empty array
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round: nonExistingRound) › should return an empty array
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     error: relation "round_delegates" does not exist
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseE (node_modules/pg/lib/connection.js:554:11)
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseMessage (node_modules/pg/lib/connection.js:379:19)
[2019-09-30T12:54:30.101Z]       at Socket.<anonymous> (node_modules/pg/lib/connection.js:119:22)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.RoundDelegates.getActiveDelegatesForRound › Given arguments = (round: nonExistingRound) › should return an empty array
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     error: relation "round_delegates" does not exist
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseE (node_modules/pg/lib/connection.js:554:11)
[2019-09-30T12:54:30.101Z]       at Connection.Object.<anonymous>.Connection.parseMessage (node_modules/pg/lib/connection.js:379:19)
[2019-09-30T12:54:30.101Z]       at Socket.<anonymous> (node_modules/pg/lib/connection.js:119:22)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z] FAIL framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/update.spec.js (18.969s)
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.update › update(filter = {publicKey: account.publicKey}, data = {rewards, fees, balance}, tx = tx) › should update rewards, fees and balance fields for each given account
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.update › update(filter = {publicKey: account.publicKey}, data = {rewards, fees, balance}, tx = tx) › should update rewards, fees and balance fields for each given account
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     TypeError: Cannot read property 'entities' of undefined
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       68 |           // Act
[2019-09-30T12:54:30.101Z]       69 |           await db.tx(async tx => {
[2019-09-30T12:54:30.101Z]     > 70 |                await storage.entities.Account.update(
[2019-09-30T12:54:30.101Z]          |                             ^
[2019-09-30T12:54:30.101Z]       71 |                   {
[2019-09-30T12:54:30.101Z]       72 |                       publicKey: account.publicKey,
[2019-09-30T12:54:30.101Z]       73 |                   },
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Task.entities (framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/update.spec.js:70:19)
[2019-09-30T12:54:30.101Z]       at callback (node_modules/pg-promise/lib/task.js:201:21)
[2019-09-30T12:54:30.101Z]       at begin.then (node_modules/pg-promise/lib/task.js:261:25)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z] FAIL framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/decrease_field_by.spec.js (18.491s)
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey}, "producedBlocks", "1", tx) › should decrease "producedBlocks" property of each given account by "1"
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey}, "producedBlocks", "1", tx) › should decrease "producedBlocks" property of each given account by "1"
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     TypeError: Cannot read property 'entities' of undefined
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       66 |           // Act
[2019-09-30T12:54:30.101Z]       67 |           await db.tx(async tx => {
[2019-09-30T12:54:30.101Z]     > 68 |                await storage.entities.Account.decreaseFieldBy(
[2019-09-30T12:54:30.101Z]          |                             ^
[2019-09-30T12:54:30.101Z]       69 |                   {
[2019-09-30T12:54:30.101Z]       70 |                       publicKey: account.publicKey,
[2019-09-30T12:54:30.101Z]       71 |                   },
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Task.entities (framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/decrease_field_by.spec.js:68:19)
[2019-09-30T12:54:30.101Z]       at callback (node_modules/pg-promise/lib/task.js:201:21)
[2019-09-30T12:54:30.101Z]       at begin.then (node_modules/pg-promise/lib/task.js:261:25)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey_in: []}, "missedBlocks", "1", tx) › should decrease "missedBlocks" property of each account by 1
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey_in: []}, "missedBlocks", "1", tx) › should decrease "missedBlocks" property of each account by 1
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     TypeError: Cannot read property 'entities' of undefined
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       114 |          // Act
[2019-09-30T12:54:30.101Z]       115 |          await db.tx(async tx => {
[2019-09-30T12:54:30.101Z]     > 116 |               await storage.entities.Account.decreaseFieldBy(
[2019-09-30T12:54:30.101Z]           |                            ^
[2019-09-30T12:54:30.101Z]       117 |                  {
[2019-09-30T12:54:30.101Z]       118 |                      publicKey_in: [account.publicKey, account2.publicKey],
[2019-09-30T12:54:30.101Z]       119 |                  },
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at Task.entities (framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/decrease_field_by.spec.js:116:19)
[2019-09-30T12:54:30.101Z]       at callback (node_modules/pg-promise/lib/task.js:201:21)
[2019-09-30T12:54:30.101Z]       at begin.then (node_modules/pg-promise/lib/task.js:261:25)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey}, "voteWeight", "Number", tx) › should decrease "voteWeight" property of each given account by given value
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.101Z]       at mapper (node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2019-09-30T12:54:30.101Z] 
[2019-09-30T12:54:30.102Z]   ● storage.entities.Account.decreaseFieldBy › Given arguments ({publicKey}, "voteWeight", "Number", tx) › should decrease "voteWeight" property of each given account by given value
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z]     TypeError: Cannot read property 'entities' of undefined
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z]       156 |          // Act
[2019-09-30T12:54:30.102Z]       157 |          await db.tx(async tx => {
[2019-09-30T12:54:30.102Z]     > 158 |               await storage.entities.Account.decreaseFieldBy(
[2019-09-30T12:54:30.102Z]           |                            ^
[2019-09-30T12:54:30.102Z]       159 |                  {
[2019-09-30T12:54:30.102Z]       160 |                      publicKey: account.publicKey,
[2019-09-30T12:54:30.102Z]       161 |                  },
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z]       at Task.entities (framework/test/jest/integration/specs/modules/chain/components/storage/entities/account/decrease_field_by.spec.js:158:19)
[2019-09-30T12:54:30.102Z]       at callback (node_modules/pg-promise/lib/task.js:201:21)
[2019-09-30T12:54:30.102Z]       at begin.then (node_modules/pg-promise/lib/task.js:261:25)
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z] Test Suites: 3 failed, 1 skipped, 61 passed, 64 of 65 total
[2019-09-30T12:54:30.102Z] Tests:       6 failed, 1 skipped, 597 todo, 70 passed, 674 total
[2019-09-30T12:54:30.102Z] Snapshots:   0 total
[2019-09-30T12:54:30.102Z] Time:        23.553s
[2019-09-30T12:54:30.102Z] Ran all test suites.
[2019-09-30T12:54:30.102Z] npm ERR! code ELIFECYCLE
[2019-09-30T12:54:30.102Z] npm ERR! errno 1
[2019-09-30T12:54:30.102Z] npm ERR! [email protected] jest:integration: `jest --config=./test/jest/integration/jest.config.js`
[2019-09-30T12:54:30.102Z] npm ERR! Exit status 1
[2019-09-30T12:54:30.102Z] npm ERR! 
[2019-09-30T12:54:30.102Z] npm ERR! Failed at the [email protected] jest:integration script.
[2019-09-30T12:54:30.102Z] npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
[2019-09-30T12:54:30.102Z] 
[2019-09-30T12:54:30.102Z] npm ERR! A complete log of this run can be found in:
[2019-09-30T12:54:30.102Z] npm ERR!     /home/lisk/.npm/_logs/2019-09-30T12_54_29_930Z-debug.log
script returned exit code 1

Steps to reproduce

npm run jest:integration (However, since it fails randomly it's hard to reproduce)

Which version(s) does this affect? (Environment, OS, etc...)

3.0

[yatki]

I tried to solve the issue with #4344. However, the problem still occurs. We are going to tackle with this issue later since it's not blocking anything.

[pablitovicente]

@yatki are there any details you can share about it? It's true that does not block development but it does randomly produce failed builds which cause noise in other PRs.

Maybe with details about your findings in #4344 someone else can look into it.

[yatki]

Yes, so some of the details I can share:

• I could only reproduce the issue on Jenkins. It never failed the same way on my local pc. But please try to reproduce this locally as well, maybe it's a db configuration issue.
• I'm suspecting from connection pool size. Because incrementing min connection value and max connection value increases the rate of failures.
• The order of test execution is not related to the problem.
• Each test suite is executed in a separate node by Jenkins and there is a database instance in every node which has MAX 500 connection limit. So there is no way to allocate that amount of connection with the current number of tests.

So far these are the meaningful details that I can share. Please feel free to ask if you have any other questions.