ncu-ci commit TypeError: Cannot read properties of null (reading '1')

[F3n67u]

Reproduce

$ ncu-ci commit 54550                      
--------------------------------------------------------------------------------
[1/1] Running COMMIT: 54550
--------------------------------------------------------------------------------
✔  Build data downloaded
⠏ Querying API for job/node-test-binary-windows-js-suites/RUN_SUBSET=2,nodes=win10-arm64-COMPILED_BY-vs2019-arm64/13778/TypeError: Cannot read properties of null (reading '1')
    at new JSTestFailure (file:///usr/local/lib/node_modules/node-core-utils/lib/ci/ci_failure_parser.js:78:62)
    at file:///usr/local/lib/node_modules/node-core-utils/lib/ci/ci_failure_parser.js:168:16
    at Array.map (<anonymous>)
    at filter (file:///usr/local/lib/node_modules/node-core-utils/lib/ci/ci_failure_parser.js:167:29)
    at CIFailureParser.parse (file:///usr/local/lib/node_modules/node-core-utils/lib/ci/ci_failure_parser.js:296:22)
    at TestRun.parseConsoleText (file:///usr/local/lib/node_modules/node-core-utils/lib/ci/build-types/job.js:93:26)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Promise.all (index 13)
    at async CommitBuild.getResults (file:///usr/local/lib/node_modules/node-core-utils/lib/ci/build-types/commit_build.js:106:25)
    at async JobCommand.drain (file:///usr/local/lib/node_modules/node-core-utils/bin/ncu-ci.js:352:7)

Expected behavior

No Error happened, could process job/node-test-commit/54550/ normally

Actual behavior

TypeError thrown

Additional Information

Refs: nodejs/reliability#316

Jenkins job URL:
https://ci.nodejs.org/job/node-test-commit-osx-arm/6298/
https://ci.nodejs.org/job/node-test-commit/54550/
https://ci.nodejs.org/job/node-test-pull-request/44957/

[aduh95]

The CI has been locked in preparation for the security release, I think the error is the expected behavior.

[richardlau]

This was occuring at the end of last week before the CI was locked down, see nodejs/reliability#316.

[F3n67u]

After some debugging, I found the following additional info, but still don't figure out why the test console text is not behaving as expected.

Problem Jenkins job URL: https://ci.nodejs.org/job/node-test-commit-osx-arm/6298/
from https://ci.nodejs.org/job/node-test-commit/54550/
from https://ci.nodejs.org/job/node-test-pull-request/44957/

Problem Console Text:
https://ci.nodejs.org/job/node-test-commit-osx-arm/nodes=osx11/6298/consoleText
https://ci.nodejs.org/job/node-test-commit-osx-arm/6298/nodes=osx11/consoleFull

Pr where the job trigger:
nodejs/node#43549

The console text which cause parse error:

outline = not ok 3 - sync fail todo # TODO
outline =   ---
outline =   duration_ms: 0.000040417
outline =   failureType: 'testCodeFailure'
outline =   error: 'thrown from sync fail todo'
outline =   code: 'ERR_TEST_FAILURE'
outline =   stack: |-
outline =     Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx-arm/nodes/osx11/test/message/test_runner_desctibe_it.js:17:9)
outline =     ItTest.runInAsyncScope (node:async_hooks:203:9)
outline =     ItTest.run (node:internal/test_runner/test:338:15)
outline =     Test.processPendingSubtests (node:internal/test_runner/test:158:27)
outline =     ItTest.postRun (node:internal/test_runner/test:390:19)
outline =     ItTest.run (node:internal/test_runner/test:352:10)
outline =     async Test.processPendingSubtests (node:internal/test_runner/test:158:7)
outline =   ...

More context:

length differs.
expect=512
actual=513
patterns:
pattern = ^TAP\ version\ 13$
pattern = ^\#\ Subtest:\ sync\ pass\ todo$
pattern = ^ok\ 1\ \-\ sync\ pass\ todo\ \#\ TODO$

<...omit rest pattern text>

outlines:
outline = TAP version 13
outline = # Subtest: sync pass todo
outline = ok 1 - sync pass todo # TODO
outline =   ---
outline =   duration_ms: 0.001743083
outline =   ...
outline = # Subtest: sync pass todo with message
outline = ok 2 - sync pass todo with message # TODO this is a passing todo
outline =   ---
outline =   duration_ms: 0.000014917
outline =   ...
outline = # Subtest: sync fail todo
outline = not ok 3 - sync fail todo # TODO
outline =   ---
outline =   duration_ms: 0.000040417
outline =   failureType: 'testCodeFailure'
outline =   error: 'thrown from sync fail todo'
outline =   code: 'ERR_TEST_FAILURE'
outline =   stack: |-
outline =     Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx-arm/nodes/osx11/test/message/test_runner_desctibe_it.js:17:9)
outline =     ItTest.runInAsyncScope (node:async_hooks:203:9)
outline =     ItTest.run (node:internal/test_runner/test:338:15)
outline =     Test.processPendingSubtests (node:internal/test_runner/test:158:27)
outline =     ItTest.postRun (node:internal/test_runner/test:390:19)
outline =     ItTest.run (node:internal/test_runner/test:352:10)
outline =     async Test.processPendingSubtests (node:internal/test_runner/test:158:7)
outline =   ...

<...omit rest outline text>

[F3n67u]

Problem points:

1. There is no severity attribute.
2. The weird outline = prefix.

@MoLow do you have any idea why?

[F3n67u]

pattern length and outline length differs.
pattern length is 512
outline length is 513

the diff is from last part.

pattern is:

pattern = ^\#\ tests\ 54$
pattern = ^\#\ pass\ 23$
pattern = ^\#\ fail\ 17$
pattern = ^\#\ skipped\ 9$
pattern = ^\#\ todo\ 5$
pattern = ^\#\ duration_ms\ .*$

outline is:

outline = # tests 54
outline = # pass 23
outline = # fail 17
outline = # cancelled 0
outline = # skipped 9
outline = # todo 5
outline = # duration_ms 4.798118667

the pattern has not cancelled but the outline has cancelled. this is why length differs print and cause the parse error.

[F3n67u]

I know what is the problem now:

1. test_runner_desctibe_it has a snapshot: test_runner_desctibe_it.out, but the actual output is not match the snapshot
2. the test_runner_desctibe_it fail and print a log that says the pattern and outline is not match
3. the outline is a test output, ncu-ci think it is a real test output and tries to parse it and resulting in a parse failure

[MoLow]

@F3n67u anything I can do to help?
I guess we can either change the output of tools/test.py in case of a output that contains tap
or we can change the code in this repo to accept the malformed output.
Il try playing around with both options

[MoLow]

Oh thanks for fixing it :)

[F3n67u]

@F3n67u anything I can do to help? I guess we can either change the output of tools/test.py in case of a output that contains tap or we can change the code in this repo to accept the malformed output. Il try playing around with both options

I figure out how to fix this problem. I made a pr to fix this.

[richardlau]

FWIW we may have a similar issue in https://github.com/nodejs/tap2junit when parsing failures from test_runner_desctibe_it, nodejs/node#43773

[MoLow]

Seems like the issue can be closed: nodejs/reliability#321