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 🎉 :