[ci] Dockerhub tests fail inconsistently

Acceptance criteria

[x] tests that run locally successfully should not fail in dockerhub runner

Tasks

[x] find the reason
[x] find solution
[x] implement solution

Analysis

When removing most of the tests some are still passing (even those dependent on hasura and test_table) - https://hub.docker.com/repository/registry-1.docker.io/datopian/data-api/builds/43d760a1-f0fd-4df9-a7bb-6e73cd52d594

Locally tests fail sometimes too - hasura does not start immediately, we are using wait-for-it.sh script to wait for hasura, but probably need to wait for a specific hasura endpoint: - https://hasura.io/docs/1.0/graphql/core/api-reference/health.html#api-spec

Was able to recreate 4 passing, 4 failing scenario locally with this command:

docker-compose -f docker-compose.test.yml -p datopian-data-api-test up --exit-code-from sut --renew-anon-volumes --build

Added a custom wait-for-hasura.sh, and now it consistently fails with 1 test both locally with .test.yaml and in dockerhub:

7 passing (491ms)
1 failing
1) datastore_search endpoint
respond with default number of rows when requesting by resource_id on a table with more than the default rows:
Error: done() invoked with non-Error: response length is not correct
at Test.<anonymous> (test/integration/datastore_search.js:49:18)
at Test.assert (node_modules/supertest/lib/test.js:181:6)
at Server.localAssert (node_modules/supertest/lib/test.js:131:12)
at emitCloseNT (net.js:1654:8)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
Removing bgtvjjfaugjk7lo2pguilop_sut_1 ...
[1A[2K Removing bgtvjjfaugjk7lo2pguilop_sut_1 ... [32mdone[0m [1BGoing to remove bgtvjjfaugjk7lo2pguilop_sut_1
executing docker-compose.test.yml (1)

Also there is a warning in hasura logs:

graphql-engine_1  | {"timestamp":"2020-09-24T11:10:06.000+0000","level":"info","type":"startup","detail":{"kind":"migrations-startup","info":"failed waiting for 9691, try increasing HASURA_GRAPHQL_MIGRATIONS_SERVER_TIMEOUT (default: 30)"}}

The reason for the last test not passing was we missed a new env variable in the docker-compose.test.yml

Inbox

E.g. tests on this PR https://github.com/datopian/data-api/pull/13 different test runs have different number of tests running successfully:

7 pass, 1 fail: https://hub.docker.com/repository/registry-1.docker.io/datopian/data-api/builds/e2a3e474-28ec-4676-b2a7-bdfccda94b38

$ mocha -r dotenv/config --recursive
data-api
[0mGET /non_existing_page [33m404 [0m4.528 ms - 10[0m
✓ should return 404 for non existing page (46ms)
GraphQL endpoint
[0mPOST /v1/graphql [32m200 [0m26.038 ms - -[0m
✓ returns graphql schema
datastore_search endpoint
[0mGET /v1/datastore_search?resource_id=test_table [32m200 [0m24.567 ms - 1621[0m
✓ returns 200 in a basic case
[0mGET /v1/datastore_search/help [32m200 [0m0.523 ms - 1001[0m
✓ returns help page in a basic case
[0mGET /v1/datastore_search [36m303 [0m1.612 ms - 51[0m
✓ redirects to help if no resource_id
[0mGET /v1/datastore_search?resource_id=test_table [32m200 [0m21.563 ms - 1621[0m
1) respond with default number of rows when requesting by resource_id on a table with more than the default rows
q parameter
[0mGET /v1/datastore_search?resource_id=test_table&q=%7B%22time_column%22:%222020-09-09%2000:00:00%22,%22text_column%22:%2211111111111111111111111111111111%22,%22float_column%22:0.1111111111111111,%22int_column%22:111111%7D [32m200 [0m336.367 ms - 349[0m
✓ filters resultset by values equal when passing {"columnname": "value"} (341ms)
graphqlQueryBuilder
function buildParametrableQuery
✓ builds a result query with all possible query params
7 passing (506ms)
1 failing
1) datastore_search endpoint
respond with default number of rows when requesting by resource_id on a table with more than the default rows:
Error: done() invoked with non-Error: response length is not correct
at Test.<anonymous> (test/integration/datastore_search.js:49:18)
at Test.assert (node_modules/supertest/lib/test.js:181:6)
at Server.localAssert (node_modules/supertest/lib/test.js:131:12)
at emitCloseNT (net.js:1654:8)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
Removing btmikobceywrqqzjbm4tmsr_sut_1 ...
[1A[2K Removing btmikobceywrqqzjbm4tmsr_sut_1 ... [32mdone[0m [1BGoing to remove btmikobceywrqqzjbm4tmsr_sut_1
executing docker-compose.test.yml (1)

4 pass, 4 fail: https://hub.docker.com/repository/registry-1.docker.io/datopian/data-api/builds/fcffe6c5-34c0-465a-b550-40618954a9b9

$ mocha -r dotenv/config --recursive
data-api
[0mGET /non_existing_page [33m404 [0m6.106 ms - 10[0m
✓ should return 404 for non existing page (52ms)
GraphQL endpoint
[0mPOST /v1/graphql [31m500 [0m21.010 ms - 10[0m
1) returns graphql schema
datastore_search endpoint
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
2) returns 200 in a basic case
[0mGET /v1/datastore_search/help [32m200 [0m0.706 ms - 1001[0m
✓ returns help page in a basic case
[0mGET /v1/datastore_search [36m303 [0m1.554 ms - 51[0m
✓ redirects to help if no resource_id
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
3) respond with default number of rows when requesting by resource_id on a table with more than the default rows
q parameter
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
FetchError: request to http://graphql-engine:8080/v1/graphql failed, reason: connect ECONNREFUSED 172.18.0.3:8080
at ClientRequest.<anonymous> (/usr/src/app/node_modules/node-fetch/lib/index.js:1461:11)
at ClientRequest.emit (events.js:315:20)
at Socket.socketErrorListener (_http_client.js:426:9)
at Socket.emit (events.js:315:20)
at emitErrorNT (internal/streams/destroy.js:92:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
at processTicksAndRejections (internal/process/task_queues.js:84:21) {
type: 'system',
errno: 'ECONNREFUSED',
code: 'ECONNREFUSED'
}
4) filters resultset by values equal when passing {"columnname": "value"}
graphqlQueryBuilder
function buildParametrableQuery
✓ builds a result query with all possible query params
4 passing (6s)
4 failing
1) GraphQL endpoint
returns graphql schema:
Error: expected 200 "OK", got 500 "Internal Server Error"
at Test._assertStatus (node_modules/supertest/lib/test.js:268:12)
at Test._assertFunction (node_modules/supertest/lib/test.js:283:11)
at Test.assert (node_modules/supertest/lib/test.js:173:18)
at Server.localAssert (node_modules/supertest/lib/test.js:131:12)
at emitCloseNT (net.js:1654:8)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
2) datastore_search endpoint
returns 200 in a basic case:
Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/usr/src/app/test/integration/datastore_search.js)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)
3) datastore_search endpoint
respond with default number of rows when requesting by resource_id on a table with more than the default rows:
Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/usr/src/app/test/integration/datastore_search.js)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)
4) datastore_search endpoint
q parameter
filters resultset by values equal when passing {"columnname": "value"}:
Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/usr/src/app/test/integration/datastore_search.js)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)
[0mGET /v1/datastore_search?resource_id=test_table [0m- [0m- ms - -[0m
[0mGET /v1/datastore_search?resource_id=test_table [0m- [0m- ms - -[0m
/usr/src/app/node_modules/mocha/lib/runner.js:906
throw err;
^
TypeError: Cannot read property 'body' of undefined
at Test.<anonymous> (/usr/src/app/test/integration/datastore_search.js:73:38)
at Test.assert (/usr/src/app/node_modules/supertest/lib/test.js:181:6)
at Server.localAssert (/usr/src/app/node_modules/supertest/lib/test.js:131:12)
at Object.onceWrapper (events.js:421:28)
at Server.emit (events.js:315:20)
at emitCloseNT (net.js:1654:8)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
error Command failed with exit code 7.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
Removing ba5dxw7nygi4fcxpe47x5cd_sut_1 ...
[1A[2K Removing ba5dxw7nygi4fcxpe47x5cd_sut_1 ... [32mdone[0m [1BGoing to remove ba5dxw7nygi4fcxpe47x5cd_sut_1
executing docker-compose.test.yml (7)

Where as locally all 8 tests pass:

evgeniyavakarina (feature/datastore_search-v1.1 *) data-api $ yarn test
yarn run v1.22.4
$ mocha -r dotenv/config --recursive

  data-api
GET /non_existing_page 404 3.065 ms - 10
    ✓ should return 404 for non existing page

  GraphQL endpoint
POST /v1/graphql 200 50.605 ms - -
    ✓ returns graphql schema (56ms)

  datastore_search endpoint
GET /v1/datastore_search?resource_id=test_table 200 36.800 ms - 14329
    ✓ returns 200 in a basic case (40ms)
GET /v1/datastore_search/help 200 0.498 ms - 1001
    ✓ returns help page in a basic case
GET /v1/datastore_search 303 1.009 ms - 51
    ✓ redirects to help if no resource_id
GET /v1/datastore_search?resource_id=test_table 200 56.574 ms - 14329
    ✓ respond with default number of rows when requesting by resource_id on a table with more than the default rows (63ms)
    q parameter
GET /v1/datastore_search?resource_id=test_table&q=%7B%22time_column%22:%222020-09-09%2000:00:00%22,%22text_column%22:%2211111111111111111111111111111111%22,%22float_column%22:0.1111111111111111,%22int_column%22:111111%7D 200 161.018 ms - 349
      ✓ filters resultset by values equal when passing {"columnname": "value"} (165ms)

  graphqlQueryBuilder
    function buildParametrableQuery
      ✓ builds a result query with all possible query params

  8 passing (380ms)

✨  Done in 2.31s.

datopian / data-api