test-fs-utimes failing locally

[targos]

• Version: master, v15.x
• Platform: Linux 4.18.0-240.1.1.el8_3.x86_64 #1 SMP Thu Nov 19 17:20:08 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: fs

What steps will reproduce the bug?

Run node test/parallel/test-fs-utimes.js

How often does it reproduce? Is there a required condition?

Every time

What is the expected behavior?

The test should pass

What do you see instead?

$ node test/parallel/test-fs-utimes.js 
node:assert:119
 throw new AssertionError(obj);
 ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ 2147483647
- 2147483648
 ^
 at Object.<anonymous> (/home/mzasso/git/nodejs/node/test/parallel/test-fs-utimes.js:169:10)
 at Module._compile (node:internal/modules/cjs/loader:1108:14)
 at Object.Module._extensions..js (node:internal/modules/cjs/loader:1137:10)
 at Module.load (node:internal/modules/cjs/loader:973:32)
 at Function.Module._load (node:internal/modules/cjs/loader:813:14)
 at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)
 at node:internal/main/run_main_module:17:47{
 generatedMessage: true,
 code: 'ERR_ASSERTION',
 actual: 2147483647,
 expected: 2147483648,
 operator: 'strictEqual'
}

Additional information

I recently updated to CentOS Stream, but I don't remember if it was already failing before that.

[richardlau]

FWIW I saw the same failure on RHEL 8. I don't see it on Fedora 33.

[ntedgi]

@targos i would like to take this opportunity

[targos]

Sure, feel free to take it!

[ntedgi]

hi @targos i installed cantos streams 4.18.0-193.14.2.el8_2.x86_64 #1 SMP Sun Jul 26 03:54:29 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
and can't reproduce the bug i test master and v15.x branches
and i also cant manage to boot load the same kernel you describe here
this is the next version available x86_64 4.18.0-257.el8

any ideas how to proceed?

[mhdawson]

Failed in CI as well: https://ci.nodejs.org/job/node-test-binary-arm-12+/lastCompletedBuild/RUN_SUBSET=0,label=pi2-docker/testReport/(root)/test/parallel_test_fs_utimes/ although with different error:

ode:assert:399
 throw err;
 ^

AssertionError [ERR_ASSERTION]: FAILED: expect_errno [Arguments]{
 '0': 'futimesSync',
 '1': 22,
 '2': AssertionError [ERR_ASSERTION]: FAILED: expect_ok [Arguments]{
 '0': 'futimesSync',
 '1': 22,
 '2': undefined,
 '3': '123456',
 '4': -1
 }
 check_mtime: 2.3949999809265137
 at expect_ok (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:64:3)
 at syncTests (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:142:7)
 at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:120:11
 at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:377:15
 at FSReqCallback.oncomplete (node:fs:184:23){
 generatedMessage: false,
 code: 'ERR_ASSERTION',
 actual: undefined,
 expected: true,
 operator: '=='
 },
 '3': 'ENOSYS'
}
 at expect_errno (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:56:3)
 at syncTests (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:144:7)
 at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:120:11
 at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:377:15
 at FSReqCallback.oncomplete (node:fs:184:23){
 generatedMessage: false,
 code: 'ERR_ASSERTION',
 actual: false,
 expected: true,
 operator: '=='
}

[Trott]

CI failure again:

https://ci.nodejs.org/job/node-test-binary-arm-12+/9681/RUN_SUBSET=3,label=pi2-docker/console

00:39:33 not ok 229 parallel/test-fs-utimes
00:39:33 ---
00:39:33 duration_ms: 4.757
00:39:33 severity: fail
00:39:33 exitcode: 1
00:39:33 stack: |-
00:39:33 node:assert:402
00:39:33 throw err;
00:39:33 ^
00:39:33 
00:39:33 AssertionError [ERR_ASSERTION]: FAILED: expect_ok [Arguments]{
00:39:33 '0': 'futimes',
00:39:33 '1': 22,
00:39:33 '2': null,
00:39:33 '3': '123456',
00:39:33 '4': -1
00:39:33 }
00:39:33 check_mtime: 2.0460000038146973
00:39:33 at expect_ok (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:64:3)
00:39:33 at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-fs-utimes.js:118:11
00:39:33 at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:376:15
00:39:33 at FSReqCallback.oncomplete (node:fs:190:23){
00:39:33 generatedMessage: false,
00:39:33 code: 'ERR_ASSERTION',
00:39:33 actual: null,
00:39:33 expected: true,
00:39:33 operator: '=='
00:39:33 }
00:39:33 ...

[Trott]

@targos Does this still fail for you every time locally? If so, I might open a different issue for the CI failures as they seem to be different and trying to resolve both in one place may be confusing.

[targos]

Yes, it still fails everytime locally. I agree that the CI failures seem to be different.

[Trott]

I've opened #37692 for the CI failures and hidden the comments here (by @mhdawson and me) about them.

[mhdawson]

@targos I see the same failure on my local RHEL boxes. I'd done some investigation and even opened a Bugzilla to get help. I was particularly confused why our CENTOS system in the CI were fine, while my local instances failed.

The answer was that not all file systems support Y2K38 (ie they will roll over versus being able to handle times beyond that point). Therefore,the test will fail if the file system used for the system does not support Y2K38 and that includes xfs which is the default for some RHEL/CENTOS installs.

A quick google does not show an easy way to test what type the file system is, so I did not have a good idea of how to fix the test and then it got lost in my backlog.

Don't have any ideas on how to address at this point, other than excluding the test which I'm not sure is the right answer.

[Trott]

The answer was that not all file systems support Y2K38 (ie they will roll over versus being able to handle times beyond that point). Therefore,the test will fail if the file system used for the system does not support Y2K38 and that includes xfs which is the default for some RHEL/CENTOS installs.

If that's the explanation, it's surprising that it's always off-by-one and not something bigger?

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ 2147483647
- 2147483648

But if that's the explanation and this is not a bug (off by one second?), we can perhaps permit the off-by-one value as valid. That may also mean that perhaps we can add back in a bunch of the platforms that we skip:

// Test Y2K38 for all platforms [except 'arm', 'OpenBSD', 'SunOS' and 'IBMi']
if (!process.arch.includes('arm') &&
 !common.isOpenBSD && !common.isSunOS && !common.isIBMi) {