trentm
commented
2 years ago tl;dr: I think this is better explained as "unexpected hangs/pauses in CI runner VMs".
The 1h36m hang in the above log looks like a test hang on its own, however looking at some surrounding tests makes it feel like something else is going on.
- I cannot repro the hang when running locally:
[14:42:28 trentm@pink:~/el/apm-agent-nodejs (git:main)]
% time .ci/scripts/test.sh -b "release" -t "apollo-server-express" "8"
...
node_tests_1 |
node_tests_1 | -- required packages ["graphql@^0.12.0","apollo-server-express@2.9.16"]
node_tests_1 | -- installing ["graphql@^0.12.0","apollo-server-express@2.9.16"]
node_tests_1 | -- running test "node test/instrumentation/modules/apollo-server-express.test.js" with apollo-server-express
node_tests_1 | -- ok
docker_node_tests_1 exited with code 0
Aborting on container exit...
.ci/scripts/test.sh:268: NODE_VERSION=8
.ci/scripts/test.sh:268: docker-compose --no-ansi --log-level ERROR -f .ci/docker/docker-compose-node-test.yml down -v --remove-orphans
--no-ansi option is deprecated and will be removed in future versions. Use `--ansi never` instead.
Removing docker_node_tests_1 ...
Removing docker_node_tests_1 ... done
.ci/scripts/test.sh -b "release" -t "apollo-server-express" "8" 2.94s user 0.68s system 0% cpu 36:52.35 total-
I cannot repro the hang in the Node v8 + apollo-server-express step in CI: https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/main/96/pipeline/526 completed. However there is a different step in this build 96 that is hanging: the
.ci/scripts/test.sh -b "release" -t "bluebird" "12"step: https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/main/96/pipeline/458 -
Our "TAV Test" stage is the longest. It typically and reliably has been taking slightly over 1h to complete. However, starting some time after Mar 23rd, that time started getting unexpectedly longer. A screenshot of the current https://apm-ci.elastic.co/job/apm-agent-nodejs/job/apm-agent-nodejs-mbp/job/main/
The preceding build 94 actually passed (because the full build run completed in 2 hr 53 min, slightly under the 3h timeout set on the build), but took an abnormally long time. Using the dev util script to list the slowest Jenkins build steps it was the jade TAV test with Node v12 that took an abnormally long time (6104897ms = ~101 minutes):
% ./dev-utils/jenkins-build-slow-steps.sh https://apm-ci.elastic.co/job/apm-agent-nodejs/job/apm-agent-nodejs-mbp/job/main/94/ | tail
1311604 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "knex" "14"
1323594 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "pg" "12"
1327722 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "apollo-server-express" "8"
1330001 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "knex" "10"
1441287 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "graphql" "14"
1465226 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "graphql" "12"
1519466 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "knex" "12"
1836015 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "apollo-server-express" "12"
1901324 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "apollo-server-express" "14"
6104897 FINISHED SUCCESS .ci/scripts/test.sh -b "release" -t "jade" "12"From the log for that build step, there was an unexplained 1h40m pause during its npm install:
...
[2022-03-25T06:39:19.419Z] node_tests_1 | npm WARN deprecated resolve-url@0.2.1: https://github.com/lydell/resolve-url#deprecated
[2022-03-25T06:39:19.419Z] node_tests_1 | npm WARN deprecated source-map-url@0.4.1: See https://github.com/lydell/source-map-url#deprecated
[2022-03-25T06:39:19.419Z] node_tests_1 | npm WARN deprecated urix@0.1.0: Please see https://github.com/lydell/urix#deprecated
[2022-03-25T08:20:15.644Z] node_tests_1 |
[2022-03-25T08:20:15.645Z] node_tests_1 | > dtrace-provider@0.8.8 install /app/node_modules/dtrace-provider
[2022-03-25T08:20:15.645Z] node_tests_1 | > node-gyp rebuild || node suppress-error.js
...
cachedout
v1v
We detected what appears to be a hang in the test suite when running
.ci/scripts/test.sh -b "release" -t "apollo-server-express" "8":https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/main/95/pipeline/1406
Relevant log entries: