"azure-functions.test.js" test failure: `Syntax error: "(" unexpected`

[trentm]

Recently, there has been a new failure in the azure-functions test:

node_tests_1     | running test: cd . && node --unhandled-rejections=strict test/instrumentation/azure-functions/azure-functions.test.js > test_output/test-instrumentation-azure-functions-azure-functions.test.js.tap 2&>1
node_tests_1     |
node_tests_1     | TAP version 13
node_tests_1     | # SKIP setup: npm ci (in /app/test/instrumentation/azure-functions/fixtures/AJsAzureFnApp)
node_tests_1     | # azure functions
node_tests_1     | # setup
node_tests_1     | # mock APM apmServerUrl: http://localhost:43399
node_tests_1     | # setup: "func start" for AJsAzureFnApp fixture
node_tests_1     | # ["func start" stderr] /app/test/instrumentation/azure-functions/fixtures/AJsAzureFnApp/node_modules/azure-functions-core-tools/bin/func: 1: Syntax error: "(" unexpected
node_tests_1     | not ok 1 "func start" failed early: code=2
node_tests_1     |   ---
node_tests_1     |     operator: fail
node_tests_1     |     at: ChildProcess.onEarlyClose (/app/test/instrumentation/azure-functions/azure-functions.test.js:484:9)
node_tests_1     |     stack: |-
node_tests_1     |       Error: "func start" failed early: code=2
node_tests_1     |           at Test.assert [as _assert] (/app/node_modules/tape/lib/test.js:312:48)
node_tests_1     |           at Test.bound [as _assert] (/app/node_modules/tape/lib/test.js:95:17)
node_tests_1     |           at Test.fail (/app/node_modules/tape/lib/test.js:406:7)
node_tests_1     |           at Test.bound [as fail] (/app/node_modules/tape/lib/test.js:95:17)
node_tests_1     |           at ChildProcess.onEarlyClose (/app/test/instrumentation/azure-functions/azure-functions.test.js:484:9)
node_tests_1     |           at ChildProcess.emit (node:events:513:28)
node_tests_1     |           at maybeClose (node:internal/child_process:1091:16)
node_tests_1     |           at ChildProcess._handle.onexit (node:internal/child_process:302:5)
node_tests_1     |   ...
node_tests_1     | # make requests
node_tests_1     | ok 2 there is no fnAppProc # SKIP
node_tests_1     | # check all APM events
node_tests_1     | ok 3 there is no fnAppProc # SKIP
node_tests_1     | # teardown
node_tests_1     |
node_tests_1     | 1..3
node_tests_1     | # tests 3
node_tests_1     | # pass  2
node_tests_1     | # fail  1
node_tests_1     |
node_tests_1     |
node_tests_1     | /app/test/test.js:224
node_tests_1     |     if (err) throw err
node_tests_1     |              ^
node_tests_1     |
node_tests_1     | Error: non-zero error code
node_tests_1     |     at WriteStream.onClose (/app/test/test.js:86:25)
node_tests_1     |     at WriteStream.emit (node:events:513:28)
node_tests_1     |     at emitCloseNT (node:internal/streams/destroy:132:10)
node_tests_1     |     at process.processTicksAndRejections (node:internal/process/task_queues:81:21) {
node_tests_1     |   code: 'ENONZERO',
node_tests_1     |   exitCode: 1
node_tests_1     | }

This started happening yesterday on the #3274 PR, e.g. https://github.com/elastic/apm-agent-nodejs/actions/runs/4753789197/jobs/8450388109

It is reproducible in a docker test run via: .ci/scripts/test.sh -b release 18. I'm not yet sure if it is related to Node v18... or perhaps a particular version of node v18. The main relevant error output is:

node_tests_1     | # ["func start" stderr] /app/test/instrumentation/azure-functions/fixtures/AJsAzureFnApp/node_modules/azure-functions-core-tools/bin/func: 1: Syntax error: "(" unexpected
node_tests_1     | not ok 1 "func start" failed early: code=2

[trentm]

This is due to Azure/azure-functions-core-tools#3335

azure-functions-core-tools (used by "test/instrumentation/azure-functions/fixtures/AJsAzureFnApp" for testing) includes a post-install script, that downloads and installs some binaries. Presumably those binaries are node-version dependent, because the binaries work when installed for node 16.x, but are corrupt when installed for node 18.x or 20.x.

By "corrupt" I mean it won't execute:

root@2b4ffd338a55:/app# ./node_modules/.bin/func
/app/node_modules/azure-functions-core-tools/bin/func: 2: Syntax error: Unterminated quoted string

workaround

As a workaround for now, I'll skip AF testing for those node versions.

[trentm]

The issue in azure-functions-core-tools is fixed, but we need to wait for a release after
'4.0.5095': '2023-03-27T15:24:07.673Z'

[trentm]

note to self: enode9

[trentm]

There is a new release yesterday that should resolve this:

% npm info azure-functions-core-tools time
...
  '4.0.5095': '2023-03-27T15:24:07.673Z',
  '4.0.5148': '2023-05-01T20:51:53.554Z'
}

However, .ci/scripts/test.sh -b release 18 still fails for me:

% .ci/scripts/test.sh -b release 18
...
node_tests_1  | running test: cd . && node --unhandled-rejections=strict test/instrumentation/azure-functions/azure-functions.test.js > test_output/test-instrumentation-azure-functions-azure-functions.test.js.tap 2&>1
node_tests_1  |
node_tests_1  | TAP version 13
node_tests_1  | # SKIP setup: npm ci (in /app/test/instrumentation/azure-functions/fixtures/AJsAzureFnApp)
node_tests_1  | # azure functions
node_tests_1  | # setup
node_tests_1  | # mock APM apmServerUrl: http://localhost:44707
node_tests_1  | # setup: "func start" for AJsAzureFnApp fixture
node_tests_1  | # ["func start" stderr] /app/test/instrumentation/azure-functions/fixtures/AJsAzureFnApp/node_modules/azure-functions-core-tools/bin/func: 2: Syntax error: Unterminated quoted string
node_tests_1  | not ok 1 "func start" failed early: code=2
node_tests_1  |   ---
node_tests_1  |     operator: fail
node_tests_1  |     at: ChildProcess.onEarlyClose (/app/test/instrumentation/azure-functions/azure-functions.test.js:484:9)
node_tests_1  |     stack: |-
node_tests_1  |       Error: "func start" failed early: code=2
node_tests_1  |           at Test.assert [as _assert] (/app/node_modules/tape/lib/test.js:312:48)
node_tests_1  |           at Test.bound [as _assert] (/app/node_modules/tape/lib/test.js:95:17)
node_tests_1  |           at Test.fail (/app/node_modules/tape/lib/test.js:406:7)
node_tests_1  |           at Test.bound [as fail] (/app/node_modules/tape/lib/test.js:95:17)
node_tests_1  |           at ChildProcess.onEarlyClose (/app/test/instrumentation/azure-functions/azure-functions.test.js:484:9)
node_tests_1  |           at ChildProcess.emit (node:events:513:28)
node_tests_1  |           at maybeClose (node:internal/child_process:1091:16)
node_tests_1  |           at ChildProcess._handle.onexit (node:internal/child_process:302:5)
node_tests_1  |   ...
node_tests_1  | # make requests
node_tests_1  | ok 2 there is no fnAppProc # SKIP
node_tests_1  | # check all APM events
node_tests_1  | ok 3 there is no fnAppProc # SKIP
node_tests_1  | # teardown
node_tests_1  |
node_tests_1  | 1..3
node_tests_1  | # tests 3
node_tests_1  | # pass  2
node_tests_1  | # fail  1
node_tests_1  |
node_tests_1  |
node_tests_1  | /app/test/test.js:227
node_tests_1  |     if (err) throw err
node_tests_1  |              ^
node_tests_1  |
node_tests_1  | Error: non-zero error code
node_tests_1  |     at WriteStream.onClose (/app/test/test.js:86:25)
node_tests_1  |     at WriteStream.emit (node:events:513:28)
node_tests_1  |     at emitCloseNT (node:internal/streams/destroy:132:10)
node_tests_1  |     at process.processTicksAndRejections (node:internal/process/task_queues:81:21) {
node_tests_1  |   code: 'ENONZERO',
node_tests_1  |   exitCode: 1
node_tests_1  | }
node_tests_1  |
node_tests_1  | Node.js v18.16.0
...
docker_node_tests_1 exited with code 1
Aborting on container exit...
1

So I'm not sure what is going on there.

[trentm]

The repro I had on the source issue no longer reproduces so I think the root issue is fixed:

...

root@919fe8daffef:/app# ./node_modules/.bin/func
Azure Functions Core Tools
Core Tools Version:       4.0.5148 Commit hash: N/A  (64-bit)
Function Runtime Version: 4.17.3.20392
...

root@919fe8daffef:/app# file ./node_modules/azure-functions-core-tools/bin/func
./node_modules/azure-functions-core-tools/bin/func: ELF 64-bit LSB shared object, x86-64, version 1 (GNU/Linux), dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2, BuildID[sha1]=9235fcd6f9a2c78e1633b322390bc73968b03b91, for GNU/Linux 2.6.32, stripped

... I needed to update "test/instrumentation/azure-functions/fixtures/AJsAzureFnApp/package-lock.json" to the new azure-functions-core-tools@4.0.5148. I've done this in #3307