Test /parallel/test-fs-stat-bigint fails 3 out of 100 times

[dominikeinkemmer]

Hey, I just ran the test suit and it seems that the tests for /parallel/test-fs-stat-bigint.js fail about 3 times in 100 runs. When running python2 tools/test.py --repeat=100 -J parallel/test-fs-stat-bigint the output is as follows:

=== release test-fs-stat-bigint ===                    
Path: parallel/test-fs-stat-bigint
(node:56622) ExperimentalWarning: The fs.promises API is experimental
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: atimeMs is not a safe integer, difference should < 1.
Number version 1543043785204.1536, BigInt version 1543043785197n
    at verifyStats (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:72:7)
    at fs.stat (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:109:7)
    at FSReqCallback.oncomplete (fs.js:162:5)
Command: out/Release/node /Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js
=== release test-fs-stat-bigint ===                    
Path: parallel/test-fs-stat-bigint
(node:56623) ExperimentalWarning: The fs.promises API is experimental
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: atimeMs is not a safe integer, difference should < 1.
Number version 1543043785206.173, BigInt version 1543043785199n
    at verifyStats (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:72:7)
    at fs.stat (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:109:7)
    at FSReqCallback.oncomplete (fs.js:162:5)
Command: out/Release/node /Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js
=== release test-fs-stat-bigint ===                    
Path: parallel/test-fs-stat-bigint
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: atimeMs is not a safe integer, difference should < 1.
Number version 1543043785397.4092, BigInt version 1543043785396n
    at verifyStats (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:72:7)
    at Object.<anonymous> (/Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js:84:3)
    at Module._compile (internal/modules/cjs/loader.js:722:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:733:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:775:12)
    at startup (internal/bootstrap/node.js:300:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:826:3)
Command: out/Release/node /Users/dominik.einkemmer/Documents/Nodefest/node/test/parallel/test-fs-stat-bigint.js
[00:02|% 100|+  97|-   3]: Done

My system spec:

• Macbook: MacBook Pro (13-inch, 2018)
• Operating system: MacOS Mojave v10.14.1
• Processor: 2.7 GHz Intel Core i7
• Memory: 16 GB 2133 MHz LPDDR3

[Trott]

See also: #24565

[Trott]

/ping @joyeecheung

[refack]

Possible fix/clarify - #23821

[bnoordhuis]

I haven't been able to reproduce but looking at the test and the output OP posted, I suspect there's something updating the atime between the two stat calls. The tests in test-fs-stat-bigint.js follow this pattern:

1. stat/fstat/lstat either synchronously or asynchronously with { bigint: true }, then
2. repeat the operation but this time without { bigint: true }

There's a time window between 1 and 2 where an external actor can update the atime. The three failures all have bigint atime < non-bigint atime, probably not a coincidence.

[bnoordhuis]

Failure on smartos:

13:01:01 not ok 649 parallel/test-fs-stat-bigint
13:01:01   ---
13:01:01   duration_ms: 0.727
13:01:01   severity: fail
13:01:01   exitcode: 1
13:01:01   stack: |-
13:01:01     assert.js:86
13:01:01       throw new AssertionError(obj);
13:01:01       ^
13:01:01     
13:01:01     AssertionError [ERR_ASSERTION]: 1543428061215n !== 1543428061216n
13:01:01     key=atimeMs, val=1543428061216
13:01:01         at verifyStats (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos16-64/test/parallel/test-fs-stat-bigint.js:66:14)
13:01:01         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos16-64/test/parallel/test-fs-stat-bigint.js:101:3)
13:01:01         at Module._compile (internal/modules/cjs/loader.js:722:30)
13:01:01         at Object.Module._extensions..js (internal/modules/cjs/loader.js:733:10)
13:01:01         at Module.load (internal/modules/cjs/loader.js:620:32)
13:01:01         at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
13:01:01         at Function.Module._load (internal/modules/cjs/loader.js:552:3)
13:01:01         at Function.Module.runMain (internal/modules/cjs/loader.js:775:12)
13:01:01         at startup (internal/bootstrap/node.js:300:19)
13:01:01         at bootstrapNodeJSCore (internal/bootstrap/node.js:826:3)

[joyeecheung]

Considering some of the tests there are synchronous and some of them are asynchronous, and it fails with python2 tools/test.py --repeat=100 -J parallel/test-fs-stat-bigint, and that the stat calls share one global AliasedBuffer to transport data from C++, it may help to either split this test, or use different AliasedBuffers in the implementation (it's not yet clear to me wether sharing the buffer in callback/synchronous APIs would actually introduce a bug, theoretically it shouldn't)

[bnoordhuis]

I don't think that's it. There's no sharing taking place, the typed array is passed from C++ to JS and immediately converted to a Stats object.

FWIW, I can reproduce when I run while true; do cat test/.tmp*/* > /dev/null; done in another terminal (but check with mount that the fs isn't mounted with noatime.)

[Trott]

Another failure on SmartOS, seems off-by-one as in @bnoordhuis's example posted above. Is that a bug in the result or should the test actually permit off-by-one in the timestamp? (Seems like a bug but maybe there's a subtlety I'm missing. I haven't looked closely at all.)

https://ci.nodejs.org/job/node-test-commit-smartos/22861/nodes=smartos16-64/console

test-joyent-smartos16-x64-1

00:12:30 not ok 691 parallel/test-fs-stat-bigint
00:12:30   ---
00:12:30   duration_ms: 0.535
00:12:30   severity: fail
00:12:30   exitcode: 1
00:12:30   stack: |-
00:12:30     (node:636936) ExperimentalWarning: The fs.promises API is experimental
00:12:30     assert.js:86
00:12:30       throw new AssertionError(obj);
00:12:30       ^
00:12:30     
00:12:30     AssertionError [ERR_ASSERTION]: 1546243950493n !== 1546243950494n
00:12:30     key=atimeMs, val=1546243950494
00:12:30         at verifyStats (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos16-64/test/parallel/test-fs-stat-bigint.js:66:14)
00:12:30         at fs.stat (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos16-64/test/parallel/test-fs-stat-bigint.js:109:7)
00:12:30         at FSReqCallback.oncomplete (fs.js:160:5)
00:12:30   ...

@nodejs/platform-smartos @nodejs/fs

[Trott]

Failure on debian9-64:

https://ci.nodejs.org/job/node-test-commit-linux/24665/nodes=debian9-64/console

test-softlayer-debian9-x64-1

00:05:02 not ok 593 parallel/test-fs-stat-bigint
00:05:02   ---
00:05:02   duration_ms: 0.141
00:05:02   severity: fail
00:05:02   exitcode: 1
00:05:02   stack: |-
00:05:02     assert.js:86
00:05:02       throw new AssertionError(obj);
00:05:02       ^
00:05:02     
00:05:02     AssertionError [ERR_ASSERTION]: 1547539502126n !== 1547539502127n
00:05:02     key=atimeMs, val=1547539502127
00:05:02         at verifyStats (/home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/parallel/test-fs-stat-bigint.js:66:14)
00:05:02         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/parallel/test-fs-stat-bigint.js:93:3)
00:05:02         at Module._compile (internal/modules/cjs/loader.js:722:30)
00:05:02         at Object.Module._extensions..js (internal/modules/cjs/loader.js:733:10)
00:05:02         at Module.load (internal/modules/cjs/loader.js:621:32)
00:05:02         at tryModuleLoad (internal/modules/cjs/loader.js:564:12)
00:05:02         at Function.Module._load (internal/modules/cjs/loader.js:556:3)
00:05:02         at Function.Module.runMain (internal/modules/cjs/loader.js:775:12)
00:05:02         at executeUserCode (internal/bootstrap/node.js:433:15)
00:05:02         at startExecution (internal/bootstrap/node.js:370:3)
00:05:02   ...

[refack]

OS - Windows
Worker - https://ci.nodejs.org/computer/test-azure_msft-win2016-x64-2/
Link - https://ci.nodejs.org/job/node-test-binary-windows/23418/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=1/

AssertionError [ERR_ASSERTION]: 1548817600661n !== 1548817600662n
key=atimeMs, val=1548817600662
    at verifyStats (c:\workspace\node-test-binary-windows\test\parallel\test-fs-stat-bigint.js:66:14)
    at c:\workspace\node-test-binary-windows\test\parallel\test-fs-stat-bigint.js:140:3

This is the test code:

node/test/parallel/test-fs-stat-bigint.js

Lines 136 to 141 in 5e1d446

	(async function() {
	const filename = getFilename();
	const bigintStats = await promiseFs.stat(filename, { bigint: true });
	const numStats = await promiseFs.stat(filename);
	verifyStats(bigintStats, numStats);
	})();

...

node/test/parallel/test-fs-stat-bigint.js

Line 22 in 5e1d446

function verifyStats(bigintStats, numStats) {

...

node/test/parallel/test-fs-stat-bigint.js

Lines 65 to 70 in 5e1d446

	} else if (Number.isSafeInteger(val)) {
	assert.strictEqual(
	bigintStats[key], BigInt(val),
	`${inspect(bigintStats[key])} !== ${inspect(BigInt(val))}\n` +
	`key=${key}, val=${val}`
	);

So bigintStats is calculated first, before numStats

Is the "atime is changed between the calls" hypothesis is correct, flipping L138 and L139 should flip the sides on the inequality. I'm testing that now.

[refack]

AssertionError [ERR_ASSERTION]: 1548858177822n !== 1548858177823n
key=atimeMs, val=1548858177823
    at verifyStats (D:\code\node\test\parallel\test-fs-stat-bigint.js:66:14)
    at D:\code\node\test\parallel\test-fs-stat-bigint.js:140:3
Command: D:\code\node\Release\node.exe D:\code\node\test\parallel\test-fs-stat-bigint.js
[00:21|% 100|+  99|-   1]: Done

numStats is still > bigintStats, even when numStats is calculated first, so this might indicate numerical instability.