ci: "nightly" test failed when determining latest_edge_version

[trentm]

The "Edge Test / Node.js-17-nightly" test failed this morning in CI. This is a run of the test suite against the latest Node v17 nightly build from https://nodejs.org/download/nightly/

From https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/master/1033/pipeline/5528 .ci/scripts/test.sh -b "nightly" -t "" "17" failed (and then again on retry) with:

[2021-08-23T07:01:42.817Z] + .ci/scripts/test.sh -b nightly -t  17
[2021-08-23T07:01:42.817Z] Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
[2021-08-23T07:01:42.817Z] + [[ nightly != \r\e\l\e\a\s\e ]]
[2021-08-23T07:01:42.817Z] + [[ false != \t\r\u\e ]]
[2021-08-23T07:01:42.817Z] ++ curl -sS https://nodejs.org/download/nightly/index.tab
[2021-08-23T07:01:42.817Z] ++ awk '{print $1}'
[2021-08-23T07:01:42.817Z] ++ grep '^v17'
[2021-08-23T07:01:42.817Z] ++ head -1
[2021-08-23T07:01:42.817Z] + latest_edge_version=v17.0.0-nightly202108230073831482
script returned exit code 1

The relevant code location here is:

apm-agent-nodejs/.ci/scripts/test.sh

Lines 131 to 151 in 9b78622

	echo "Running Agent tests with node v$NODE_VERSION (BUILD_TYPE=$BUILD_TYPE, FORCE=$FORCE)"
	else
	echo "Running '$TAV_MODULE' TAV tests with node v$NODE_VERSION (BUILD_TYPE=$BUILD_TYPE, FORCE=$FORCE)"
	fi
	# Turn on xtrace output only after processing args.
	set -x
	# ---- For nightly and rc builds, determine if there is a point in testing.
	if [[ $BUILD_TYPE != "release" && $FORCE != "true" ]]; then
	# If there is no nightly/rc build for this version, then skip.
	#
	# Note: We are relying on new releases being added to the top of index.tab,
	# which currently seems to be the case.
	latest_edge_version=$(curl -sS ${NVM_NODEJS_ORG_MIRROR}/index.tab \
	| (grep "^v${NODE_VERSION}" || true) | awk '{print $1}' | head -1)
	if [[ -z "$latest_edge_version" ]]; then
	skip "No ${BUILD_TYPE} build of Node v${NODE_VERSION} was found. Skipping tests."
	fi

I don't understand what command failed there. This bash script is running with set -eo pipefail, so any failure in a pipeline will result in exit.

Running the sdtart of that script locally now, I get:

% .ci/scripts/test.sh -b nightly -t "" 17
Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
+ [[ nightly != \r\e\l\e\a\s\e ]]
+ [[ false != \t\r\u\e ]]
++ curl -sS https://nodejs.org/download/nightly/index.tab
++ grep '^v17'
++ awk '{print $1}'
++ head -1
+ latest_edge_version=v17.0.0-nightly202108230073831482
+ [[ -z v17.0.0-nightly202108230073831482 ]]
+ possible_release_version=v17.0.0
++ curl -sS https://nodejs.org/dist/index.tab
++ grep -E '^v17.0.0\>'
++ awk '{print $1}'
++ true
+ release_version=
+ [[ -n '' ]]
...

So the failure had to have been in:

  latest_edge_version=$(curl -sS ${NVM_NODEJS_ORG_MIRROR}/index.tab \
    | (grep "^v${NODE_VERSION}" || true) | awk '{print $1}' | head -1)

A possibly interesting datapoint is that this test run is happening just when the Node.js project is uploading this new nightly build. From https://nodejs.org/download/nightly/

v17.0.0-nightly202108230073831482/                 23-Aug-2021 07:00      

I have seen a failure in the "nightly" CI before that I chalked up to a failed download of the nightly build bits while it was being uploaded.

The best guess I have here is that the curl ... or head ... failed possibly related to the behaviour of that index.tab file being updated during our read. I'll keep this ticket open for now in the background to see if it happens persistently. If we determine this is related to attempting to download the nightly at the same time it is being uploaded, then we could consider moving this nightly timer back an hour -- which is controlled by either or both of these:

.ci/schedule-daily.groovy
35:    cron('H H(4-5) * * 1-5')

.ci/jobs/apm-agent-nodejs-schedule-daily.yml
27:    - timed: 'H H(4-5) * * 1-5'

[trentm]

A re-run of the edge tests (https://apm-ci.elastic.co/job/apm-agent-nodejs/job/apm-agent-nodejs-mbp/job/master/1034/) failed in the same way:

[2021-08-23T16:45:51.626Z] + .ci/scripts/test.sh -b nightly -t  17
[2021-08-23T16:45:51.626Z] Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
[2021-08-23T16:45:51.626Z] + [[ nightly != \r\e\l\e\a\s\e ]]
[2021-08-23T16:45:51.626Z] + [[ false != \t\r\u\e ]]
[2021-08-23T16:45:51.626Z] ++ curl -sS https://nodejs.org/download/nightly/index.tab
[2021-08-23T16:45:51.626Z] ++ grep '^v17'
[2021-08-23T16:45:51.626Z] ++ awk '{print $1}'
[2021-08-23T16:45:51.626Z] ++ head -1
[2021-08-23T16:45:51.626Z] + latest_edge_version=v17.0.0-nightly202108230073831482
script returned exit code 1

This debunks the idea that it is related to timing of the build/test run while the Node.js project automation is uploading that nightly build.

[trentm]

From investigation on #2298, we are basically hitting this:

% curl -sS https://nodejs.org/download/rc/index.tab | head -1
version	date	files	npm	v8	uv	zlib	openssl	modules	lts	security
curl: (23) Failed writing body (0 != 1360)

I.e. the pipeline after curl ... is closing the read pipe before curl has a chance to read the full body, so it errors out. I don't understand why in CI we don't see that "Failed writing body" error message to stderr.

[trentm]

Sigh. After breaking this up into:

  curl -sS "${NVM_NODEJS_ORG_MIRROR}/index.tab" >$index_tab
  latest_edge_version=$(cat "$index_tab" \
    | (grep "^v${NODE_VERSION}" || true) | awk '{print $1}' | head -1

I now sometimes pass this and sometimes one of these two errors:

1. This can no longer be a curl failure.

[2021-08-23T21:02:07.540Z] + .ci/scripts/test.sh -b nightly -t  17
[2021-08-23T21:02:07.540Z] Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
[2021-08-23T21:02:07.540Z] .ci/scripts/test.sh:143: main(): [[ nightly != \r\e\l\e\a\s\e ]]
[2021-08-23T21:02:07.540Z] .ci/scripts/test.sh:143: main(): [[ false != \t\r\u\e ]]
[2021-08-23T21:02:07.540Z] .ci/scripts/test.sh:144: main(): index_tab=./index.tab.tmp
[2021-08-23T21:02:07.540Z] .ci/scripts/test.sh:150: main(): curl -sS https://nodejs.org/download/nightly/index.tab
[2021-08-23T21:02:07.540Z] ..ci/scripts/test.sh:152: main(): cat ./index.tab.tmp
[2021-08-23T21:02:07.540Z] ..ci/scripts/test.sh:152: main(): awk '{print $1}'
[2021-08-23T21:02:07.540Z] ..ci/scripts/test.sh:152: main(): head -1
[2021-08-23T21:02:07.540Z] ..ci/scripts/test.sh:152: main(): grep '^v17'
[2021-08-23T21:02:07.540Z] .ci/scripts/test.sh:152: main(): latest_edge_version=v17.0.0-nightly202108230073831482
script returned exit code 1

2. this is likely (lucky me?) some network or system (hopefully transient) error:

[2021-08-23T21:01:26.181Z] + .ci/scripts/test.sh -b nightly -t  17
[2021-08-23T21:01:26.181Z] Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
[2021-08-23T21:01:26.181Z] .ci/scripts/test.sh:143: main(): [[ nightly != \r\e\l\e\a\s\e ]]
[2021-08-23T21:01:26.181Z] .ci/scripts/test.sh:143: main(): [[ false != \t\r\u\e ]]
[2021-08-23T21:01:26.181Z] .ci/scripts/test.sh:144: main(): index_tab=./index.tab.tmp
[2021-08-23T21:01:26.181Z] .ci/scripts/test.sh:150: main(): curl -sS https://nodejs.org/download/nightly/index.tab
[2021-08-23T21:01:26.181Z] curl: (56) OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104
script returned exit code 56

[trentm]

(I'm ignoring the "SSL_ERROR_SYSCALL" error. It occurred once and I'm assuming a fluke for now.)

---

I can't currently explain the following. From experimentation on #2298 apparently:

1. This code -- curling to a file and cat | grep | awk | head -1'ing -- commonly (but not always) results in failures in CI:

curl -sS "${NVM_NODEJS_ORG_MIRROR}/index.tab" >$index_tab
latest_edge_version=$(cat "$index_tab" \
   | (grep "^v${NODE_VERSION}" || true) | awk '{print $1}' | head -1)

e.g. from https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/PR-2298/4/pipeline/298

[2021-08-23T21:39:28.218Z] + .ci/scripts/test.sh -b nightly -t  17
[2021-08-23T21:39:28.218Z] Running Agent tests with node v17 (BUILD_TYPE=nightly, FORCE=false)
[2021-08-23T21:39:28.218Z] .ci/scripts/test.sh:143: main(): [[ nightly != \r\e\l\e\a\s\e ]]
[2021-08-23T21:39:28.218Z] .ci/scripts/test.sh:143: main(): [[ false != \t\r\u\e ]]
[2021-08-23T21:39:28.218Z] .ci/scripts/test.sh:144: main(): index_tab=./index.tab.tmp
[2021-08-23T21:39:28.218Z] .ci/scripts/test.sh:150: main(): curl -sS https://nodejs.org/download/nightly/index.tab
[2021-08-23T21:39:28.218Z] ..ci/scripts/test.sh:152: main(): cat ./index.tab.tmp
[2021-08-23T21:39:28.218Z] ..ci/scripts/test.sh:152: main(): grep '^v17'
[2021-08-23T21:39:28.218Z] ..ci/scripts/test.sh:152: main(): awk '{print $1}'
[2021-08-23T21:39:28.218Z] ..ci/scripts/test.sh:152: main(): head -1
[2021-08-23T21:39:28.218Z] .ci/scripts/test.sh:152: main(): latest_edge_version=v17.0.0-nightly202108230073831482
script returned exit code 1

2. Where as this code -- curl | grep | awk to a bash var, echo "$the_var" | head -1ing that -- is fine:

index_tab_content=$(curl -sS "${NVM_NODEJS_ORG_MIRROR}/index.tab" | (grep "^v${NODE_VERSION}" || true) | awk '{print $1}')
latest_edge_version=$(echo "$index_tab_content" | head -1)

At least was fine with this build https://apm-ci.elastic.co/blue/organizations/jenkins/apm-agent-nodejs%2Fapm-agent-nodejs-mbp/detail/PR-2298/5/pipeline/

[trentm]

I'd initially attempt to avoid using the second style to avoid having large log output -- because we are using set -x, the full value of that bash var with the content is included in the log. Oh well. Working and a big log is better than not working at all.