Investigate test-fs-readfile-tostring-fail failures on FreeBSD

[richardlau]

Test

test-fs-readfile-tostring-fail

Platform

FreeBSD

Console output

13:11:17 not ok 3306 pummel/test-fs-readfile-tostring-fail
13:11:17 ---
13:11:17 duration_ms: 34.407
13:11:17 severity: fail
13:11:17 exitcode: 7
13:11:17 stack: |-
13:11:17 /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/pummel/test-fs-readfile-tostring-fail.js:69
13:11:17 throw err;
13:11:17 ^
13:11:17 
13:11:17 AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
13:11:17 
13:11:17 assert.ok(err instanceof Error)
13:11:17 
13:11:17 at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/pummel/test-fs-readfile-tostring-fail.js:36:12
13:11:17 at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/common/index.js:438:15
13:11:17 at FSReqCallback.readFileAfterClose [as oncomplete] (node:internal/fs/read_file_context:68:3) {
13:11:17 generatedMessage: true,
13:11:17 code: 'ERR_ASSERTION',
13:11:17 actual: false,
13:11:17 expected: true,
13:11:17 operator: '=='
13:11:17 }
13:11:17 
13:11:17 Node.js v19.0.0-pre
13:11:17 ...

Build links

• https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/44929/
• https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/44926/
• https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/44924/

Additional information

This appears to be happening consistently on test-digitalocean-freebsd12-x64-2. I haven't seen it happen yet on test-digitalocean-freebsd12-x64-1 -- according to https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/buildTimeTrend recent runs on test-digitalocean-freebsd12-x64-1 are green/yellow:

FWIW I rebooted test-digitalocean-freebsd12-x64-2 about an hour ago but that hasn't fixed the problem.

[richardlau]

FWIW It looks like this first appeared in https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/44906/ which was 21 hours ago. The next job, https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd12-x64/44907/ ran and passed on test-digitalocean-freebsd12-x64-2 but then all subsequent runs on test-digitalocean-freebsd12-x64-2 have failed this test. So this could be a very recent regression (but then I can't explain why it's not showing up on test-digitalocean-freebsd12-x64-1).

[bnoordhuis]

Just hit this. On the face of it, the failure looks impossible (reading a string bigger than V8 allows) so there's probably something else going on.

I don't know how easy it is to run a single pummel test but it'd be interesting to see what this prints:

diff --git a/test/pummel/test-fs-readfile-tostring-fail.js b/test/pummel/test-fs-readfile-tostring-fail.js
index 1a1e7d62175..e49ec2d880e 100644
--- a/test/pummel/test-fs-readfile-tostring-fail.js
+++ b/test/pummel/test-fs-readfile-tostring-fail.js
@@ -33,6 +33,7 @@ for (let i = 0; i < 201; i++) {
 stream.end();
 stream.on('finish', common.mustCall(function() {
 fs.readFile(file, 'utf8', common.mustCall(function(err, buf) {
+ console.log(buf?.length, err, buf);
 assert.ok(err instanceof Error);
 if (err.message !== 'Array buffer allocation failed') {
 const stringLengthHex = kStringMaxLength.toString(16);

[richardlau]

@bnoordhuis I left out printing buf as it's a lot of a's.

$ ./node test/pummel/test-fs-readfile-tostring-fail.js
207880192 null
/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/pummel/test-fs-readfile-tostring-fail.js:70
 throw err;
 ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

 assert.ok(err instanceof Error)

 at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/pummel/test-fs-readfile-tostring-fail.js:37:12
 at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/common/index.js:438:15
 at FSReqCallback.readFileAfterClose [as oncomplete] (node:internal/fs/read_file_context:68:3) {
 generatedMessage: true,
 code: 'ERR_ASSERTION',
 actual: false,
 expected: true,
 operator: '=='
}

Node.js v19.0.0-pre

I think we're running out of disk space and the file written is smaller than expected? Shouldn't we expect the writable to emit an error in that case?

$ df -h .
Filesystem Size Used Avail Capacity Mounted on
zroot/usr/home 32G 32G 289M 99% /usr/home

[richardlau]

I've opened #43850 -- the test is failing because there is not enough disk space on the machine to write the temporary file but for whatever reason we don't get any errors about that emitted on the WriteStream which means we end up with a more cryptic, unexpected test failure. The actual fix for this issue is sorting out the free disk space but the test can be improved in indicating what went wrong.

[richardlau]

Well here's where all the space has gone -- the .ccache directory (note it's far larger than the "max cache size"):

[iojs@test-digitalocean-freebsd12-x64-2 ~]$ ccache -s
cache directory /home/iojs/.ccache
primary config /home/iojs/.ccache/ccache.conf
secondary config (readonly) /usr/local/etc/ccache.conf
stats updated Fri Jul 15 18:18:35 2022
cache hit (direct) 9472203
cache hit (preprocessed) 114687
cache miss 138906
cache hit rate 98.57 %
called for link 314366
called for preprocessing 16005
compile failed 9
ccache internal error 83949
preprocessor error 7
cache file missing 510
bad compiler arguments 5
autoconf compile/link 103
no input file 5350
cleanups performed 14
files in cache 378613
cache size 1.6 GB
max cache size 5.0 GB
[iojs@test-digitalocean-freebsd12-x64-2 ~]$ du -hs /home/iojs/.ccache/
 26G /home/iojs/.ccache/
[iojs@test-digitalocean-freebsd12-x64-2 ~]$

[richardlau]

Running a cleanup (ccache -c).

[richardlau]

[iojs@test-digitalocean-freebsd12-x64-2 ~]$ ccache -c
Cleaned cache
[iojs@test-digitalocean-freebsd12-x64-2 ~]$ du -hs /home/iojs/.ccache/
4.7G /home/iojs/.ccache/
[iojs@test-digitalocean-freebsd12-x64-2 ~]$ ccache -s
cache directory /home/iojs/.ccache
primary config /home/iojs/.ccache/ccache.conf
secondary config (readonly) /usr/local/etc/ccache.conf
stats updated Fri Jul 15 21:12:31 2022
cache hit (direct) 9475977
cache hit (preprocessed) 114687
cache miss 138909
cache hit rate 98.57 %
called for link 314484
called for preprocessing 16011
compile failed 9
ccache internal error 83981
preprocessor error 7
cache file missing 510
bad compiler arguments 5
autoconf compile/link 103
no input file 5352
cleanups performed 32
files in cache 91923
cache size 5.0 GB
max cache size 5.0 GB
[iojs@test-digitalocean-freebsd12-x64-2 ~]$ df -h .
Filesystem Size Used Avail Capacity Mounted on
zroot/usr/home 32G 10G 21G 33% /usr/home
[iojs@test-digitalocean-freebsd12-x64-2 ~]$

[richardlau]

Two most recent builds (after the ccache clean up) on test-digitalocean-freebsd12-x64-2 have passed 🎉 :