unit test failure in test/unit/parser-tests.js for NodeJS 14, 16, 18 and 20 while working in 10 and 12

Description

ubuntu@ip-172-31-50-113:~/nodejs-driver$ ./node_modules/mocha/bin/mocha test/unit/parser-tests.js Parser #_transform() ✓ should read a READY opcode ✓ should read a AUTHENTICATE response ✓ should buffer a AUTHENTICATE response until complete ✓ should read a VOID result ✓ should read a VOID result with trace id ✓ should read a VOID result with trace id chunked ✓ should read a RESULT result with trace id chunked ✓ should read a VOID result with warnings and custom payload ✓ should read a SET_KEYSPACE result ✓ should read a PREPARE result ✓ should read a PREPARE V2 result ✓ should read a STATUS_CHANGE UP EVENT response ✓ should read a STATUS_CHANGE DOWN EVENT response ✓ should read a STATUS_CHANGE DOWN EVENT response chunked ✓ should read an ERROR response that includes warnings ✓ should read an UNAVAILABLE ✓ should read a READ_TIMEOUT with not enough received ✓ should read a READ_TIMEOUT with no data present ✓ should read a READ_TIMEOUT with repair timeout ✓ should read a READ_FAILURE ✓ should read a SIMPLE WRITE_TIMEOUT ✓ should read a BATCH_LOG WRITE_TIMEOUT ✓ should read a WRITE_FAILURE ✓ should read an UNPREPARED ✓ should read a FUNCTION_FAILURE ✓ should read an ALREADY_EXISTS for Table ✓ should read an ALREADY_EXISTS for Keyspace ✓ should read a buffer until there is enough data ✓ should emit empty result one column no rows ✓ should emit empty result two columns no rows ✓ should emit row when rows present ✓ should parse new_metadata_id in ROWS result ✓ should emit row with large row values (612ms) ✓ should read a AUTH_CHALLENGE response ✓ should buffer ERROR response until complete ✓ should not buffer RESULT ROWS response when byRow is enabled with multiple chunk lengths ✓ should emit rows chunked with chunk length of 1 (72ms) ✓ should emit rows chunked with chunk length of 3 ✓ should emit rows chunked with chunk length of 5 ✓ should emit rows chunked with chunk length of 13 with multiple chunk lengths piped 1) should emit rows chunked with chunk length of 1 2) should emit rows chunked with chunk length of 2 3) should emit rows chunked with chunk length of 7 4) should emit rows chunked with chunk length of 11 40 passing (1s) 4 failing 1) Parser #_transform() with multiple chunk lengths piped should emit rows chunked with chunk length of 1: Uncaught AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: assert.ok(byRowCompleted) at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:996:20 at process.processTicksAndRejections (node:internal/process/task_queues:77:11) 2) Parser #_transform() with multiple chunk lengths piped should emit rows chunked with chunk length of 2: Uncaught AssertionError [ERR_ASSERTION]: Result not found for index 2 at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:999:22 at Array.forEach (<anonymous>) at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:998:22 at process.processTicksAndRejections (node:internal/process/task_queues:77:11) 3) Parser #_transform() with multiple chunk lengths piped should emit rows chunked with chunk length of 7: Uncaught AssertionError [ERR_ASSERTION]: Result not found for index 2 at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:999:22 at Array.forEach (<anonymous>) at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:998:22 at process.processTicksAndRejections (node:internal/process/task_queues:77:11) 4) Parser #_transform() with multiple chunk lengths piped should emit rows chunked with chunk length of 11: Uncaught AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: assert.ok(byRowCompleted) at /home/ubuntu/nodejs-driver/test/unit/parser-tests.js:996:20 at process.processTicksAndRejections (node:internal/process/task_queues:77:11)

Environment

None

Pull Requests

None

Affects versions

None

Fix versions

Activity

Bret McGuire September 7, 2023 at 6:58 PM

Confirmed; it’s a weird synchronization case. I can make this test back by converting the process.nextTick() invocation to the following:

 

process.nextTick(() => { setTimeout(() => { assert.ok(byRowCompleted); //assert result expected.forEach(function (expectedItem, index) { assert.ok(result[index], 'Result not found for index ' + index); assert.strictEqual(result[index].length, expectedItem.rowLength); assert.strictEqual(result[index][0].keys().length, expectedItem.columnLength); }); done(); },1000);

 

This gives the callback chain time to complete before evaluating the conditions.

 

This isn’t a reliable overall fix, however, so it’s still worth doing a bit of digging to see if we can come up with something better.

Wei Deng September 7, 2023 at 5:11 PM
Edited

Here is the relevant segment from nodejs 14 changelog:

2022-05-04, Version 14.19.2 'Fermium' (LTS), @BethGriggs prepared by @juanarbol

Notable Changes

doc:

  • New release key for Bryan English

Learn more at: https://github.com/nodejs/node/pull/42102 Contributed by Bryan English (@bengl)

npm:

  • Upgrade npm to v6.14.17.

Learn more at: https://github.com/nodejs/node/pull/42900 Contributed by Ruy Adorno (@ruyadorno)

V8:

  • V8 had a stack overflow issue affecting the vm module, cherry-picking cc9a8a37445e from V8 solves this issue.

Learn more at: https://github.com/nodejs/node/pull/41826 Contributed by Gus Caplan (@devsnek)

  • Using getHeapSnapshot() was causing a Node.js crash due a V8 issue, this is fixed by backporting 367b0c1e7a32 from V8.

Learn more at: https://github.com/nodejs/node/pull/42637 Contributed by Chengzhong Wu (@legendecas)

Commits

  • [c73ac527d6] - build: set DESTCPU correctly for 'make binary' on Apple Silicon (Chris Heisterkamp) #40147

  • [dcaed6db24] - build: use ccache in make-v8.sh on ppc64le and s390x (Richard Lau) #42204

  • [4203d132b1] - child_process: queue pending messages (Erick Wendel) #41221

  • [a3ebdbfe8f] - deps: upgrade npm to 6.14.17 (Ruy Adorno) #42900

  • [39e44f8382] - deps: V8: cherry-pick cc9a8a37445e (Gus Caplan) #41826

  • [b52a268b6f] - deps: V8: cherry-pick 367b0c1e7a32 (legendecas) #42637

  • [77ba012065] - doc: fix documentation of FileHandle.prototype.appendFile (Antoine du Hamel) #42588

  • [3d3d7ed1b7] - doc: specify flag needed for JSON and Wasm modules (Rich Trott) #42736

  • [542d812c93] - doc: use http://openpgp.org for keyserver examples (Nick Schonning) #39227

  • [7f2825b1a9] - doc: add release key for Bryan English (Bryan English) #42102

  • [75302d3dce] - fs: fix write methods param validation and docs (Livia Medeiros) #41677

  • [d4171e0eac] - stream: resume stream on drain (Robert Nagy) #41848

  • [de474c8b6f] - worker: do not send message if port is closing (Rich Trott) #42357

Wei Deng September 7, 2023 at 4:50 PM

Actually I was able to narrow the behavior change further down to some changes between 14.19.1 and 14.19.2, so we just need to examine the changelog in 14.19.2.

Wei Deng September 7, 2023 at 4:31 PM

Should we analyze the changelog between NodeJS 12 and 14 as that’s where the behavior of these tests changed?

Bret McGuire September 7, 2023 at 4:10 PM
Edited

Looked into this some last night. Pretty sure what’s going on here is a basic concurrency issue; the string of queued up callbacks setup by the parser.on('readable',fn) aren’t completing before the fn passed into process.nextTick() is invoked. Since the nextTick() fn is running while backing state is being updated several tests connected to that backing state behave in unpleasant ways. I’ve seen a couple examples in testing:

 

  • Keys in the backing object aren’t available at the time they’re requested because the underlying callbacks that populate them haven’t run yet.

  • The byRowCompleted flag (true on the last bit of chunked data) is set to true as expected but is promptly set to undefined when chunks from subsequent indexes are processed. The ‘assert.ok(byRowCompleted)’ op happens after this reset of byRowCompleted.

 

I’m not sure when this behaviour changed but it seems pretty clear that the test as written has some synchronization problems for current nodejs versions.

Fixed

Details

Assignee

Reporter

Priority

Created August 31, 2023 at 5:12 AM
Updated September 14, 2023 at 4:54 AM
Resolved September 14, 2023 at 4:54 AM

Flag notifications