You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
Investigate flaky test-fs-stat-bigint on macos M1 #45612
the result of this operations fail inconsistently, exceeding the allowableDelta : msFromNum - Number(msFromBigIntNs) <= allowableDelta msFromNum - Number(msFromBigInt) <= allowableDelta 49.189697265625 <= 49
I was able to reproduce the error in about 1% of local runs. With the change in #45925 it appeared to become less flaky locally but really difficult to say for sure.
@jasnell just checked out #45925 locally and tried running the same thing, it's much less recurrent to get a failure now but it still does fail from time to time 😞
grr, ok. hmm... the only thing I can think of is artificially setting the allowableDelta higher. What I did notice is that it would fail when the delta was either 0 or 1.
I guess this is particularly on M1, since no one complains the CI for this test?
I noticed this on local m1 env as well. The flakiness rate is pretty high, that I can even manually reproduce it by repeatedly running the test (and hence not related to parallel FWIW).
I just wanted to chip in mentioning that I also experienced the flakiness on my Mac machine, I've also opened #58043 to address this flakiness (before @RaisinTen made me notice this issue)
I can confirm that on my machine a large enough allowable delta does seem to fix the issue
Quick update on this, I've written a small script that reproduces the flakiness for statSync (+ adjustments to make it more convenient to use with fs_usage):
script
constfs=require("node:fs");constpath=require("node:path");constassert=require("node:assert");const{ setTimeout }=require("node:timers/promises");fs.rmSync("./tmp",{force: true,recursive: true});console.log(`\x1b[32m This process' PID is: ${process.pid} (run: sudo fs_usage -w -f pathname ${process.pid} > fs_usage-logs.txt) \x1b[0m`);(async()=>{awaitsetTimeout(15_000);// a timeout so that fs_usage can be calledfs.mkdirSync("./tmp");constattempts=100_000;constexitOnFail=true;for(leti=0;i<attempts;i++){constfilename=path.resolve(`./tmp/test_${i}`);console.log(`\x1b[35m file = ${filename} \x1b[0m`);try{fs.writeFileSync(filename,"test");conststartTime=process.hrtime.bigint();constbigintStats=fs.statSync(filename,{bigint: true});constnumStats=fs.statSync(filename);constendTime=process.hrtime.bigint();constallowableDelta=Math.ceil(Number(endTime-startTime)/1e6);constkey="atimeMs";constmsFromBigInt=bigintStats[key];constmsFromNum=numStats[key];assert(msFromNum-Number(msFromBigInt)<=allowableDelta,`Number version ${key} = ${msFromNum}, `+`BigInt version ${key} = ${msFromBigInt}n, `+`Delta = ${msFromNum-Number(msFromBigInt)}n, `+`Allowable delta = ${allowableDelta}`);}catch(e){if(einstanceofassert.AssertionError){console.error(e);}if(exitOnFail){throwe;}}}})();
I've run it and saved the output to a fs_usage-logs.txt file (using the command the scripts logs), unfortunately this does not seem to yield any useful information, I'm including below the last few logs present in the file (where the test_16768 file is the one that caused the assertion fail while the rest did not)
the only noticeable difference is that the two stat calls on test_16768 are further apart then those of other files, and by quickly scanning all the logs that seems to apply to all the other stats too, when they are too much far apart the assertion fails otherwise it succeeds (I guess that the question now is, why they get further apart and if something else is accessing the file during that time)
Do you have the start time, end time and atime values for the success and fail cases? That should help in understanding which one of the atime values is going out of the expected start time ... end time window and by how much.
No I didn't have the values, however I re-run the script and got new logs with the times as well 🙂👍
Updated script
constfs=require("node:fs");constpath=require("node:path");constassert=require("node:assert");const{ setTimeout }=require("node:timers/promises");fs.rmSync("./tmp",{force: true,recursive: true});console.error(`\x1b[32m This process' PID is: ${process.pid} (run: sudo fs_usage -w -f pathname ${process.pid} > fs_usage-logs.txt) \x1b[0m`);(async()=>{awaitsetTimeout(15_000);// a timeout so that fs_usage can be calledfs.mkdirSync("./tmp");constattempts=100_000;constexitOnFail=true;for(leti=0;i<attempts;i++){constfilename=path.resolve(`./tmp/test_${i}`);console.error(`\x1b[35m processing ${filename} \x1b[0m`);try{fs.writeFileSync(filename,"test");conststartTime=process.hrtime.bigint();constbigintStats=fs.statSync(filename,{bigint: true});constnumStats=fs.statSync(filename);constendTime=process.hrtime.bigint();constallowableDelta=Math.ceil(Number(endTime-startTime)/1e6);constkey="atimeMs";constmsFromBigInt=bigintStats[key];constmsFromNum=numStats[key];console.log(` file: ${filename} startTime: ${startTime} endTime: ${endTime} allowableDelta: ${allowableDelta} delta: ${msFromNum-Number(msFromBigInt)} bigintStats[${key}]: ${bigintStats[key]} numStats[${key}]: ${numStats[key]} `);assert(msFromNum-Number(msFromBigInt)<=allowableDelta,`Number version ${key} = ${msFromNum}, `+`BigInt version ${key} = ${msFromBigInt}n, `+`Delta = ${msFromNum-Number(msFromBigInt)}n, `+`Allowable delta = ${allowableDelta}`);fs.rmSync(filename);// remove the file if no flake occurred}catch(e){if(einstanceofassert.AssertionError){console.error(e);}if(exitOnFail){throwe;}}}})();
Last portion of script output
Note: the assertion failed for test_17635 and succeeded for all the other files
Now, you can check with dtruss (you would need to temporarily disable SIP for this) too to verify if mknod, utimes or read is being called which might change the atime value.
Sorry I can't do that as I am using my company's mac and can't really disable SIP on it 😓
Since the start time and end times are measured from the process start time and the times on the stat objects are measured from the system time, it is hard to understand how these are relating to one another. It would help if we can see the numbers relative to the same reference like epoch or system time. Let's also log:
the birthtime, ctime and mtime values which should be exactly the same for both stat objects but should give us more info of the timing of the file events
hrtimes before and after the writeFileSync calls to understand the time it takes to create the file
This should help us confirm if both the atimes are more than the birthtime and find out a reliable upper limit for the permissible atime differences.
it is hard to understand how these are relating to one another. It would help if we can see the numbers relative to the same reference like epoch or system time
Could you clarify what you mean? would just using new Date().getTime() instead of process.hrtime to get the start and end times work for you?
For the failed case:
a. atimeNs on first stat: ...49759597
b. atimeMs on first stat: ...49
c. atimeMs on second stat: ...51.1516
We see a 0.759597ms difference between the atimeMs and atimeNs values on the first bigint stat object because the atimeMs value is calculated by doing integer division with kNsPerMsBigInt which is 10n ** 6n:
The accurate difference between atime on the second stat object (c) and the first stat object (a) is ...51.1516 ms - ...49.759597 ms = 1.392 ms. This is within the allowed delta without ceil = 13834850.787250 ms - 13834849.353916 ms = 1.433334ms. It only goes out of range when you compare the atime on the second stat object (c) with the floored atime on the first object (b), which is ...51.1516 ms - ...49 ms = 2.152 ms.
All the (birth|m|c)time values are exactly the same, except for the flooring differences discussed above.
As you pointed out, there is a 2ms gap before and after the first stat call for the failing case but it is 0ms for all the other cases. The new atime after this stat call looks similar to the timestamp after this stat call completed. I would not blame the stat for the atime update because you can still run the stat call on the same file on the REPL after wide intervals and it would not update the atime. Also, correlation does not imply causation. So this part is still an unsolved mystery.
My suggestions:
For 1 and 2, we can modify the calculation to account for the flooring difference.
For 3, the test can be modified to just allow the flooring difference for (birth|m|c)time values, i.e., no additional delta needed.
The atime flake is still expected because of the unsolved mystery, so the delta is still needed for this but I didn't expect the mtime to change at all.
Apparently, you don't need to write an Endpoint Security client yourself because I found out about eslogger which should already exist on your system. You can try to run that in parallel (your terminal would need full disk access):
$ sudo eslogger access create open close stat utimes write | jq -r '"\(.process.executable.path) -> \(.event)"' | grep path-of-the-file
and it would print info about what process is performing the syscalls and a JSON with event info about the syscall along with the file stat data. This should show which process is responsible for suddenly modifying these times.
This issue has been marked as stale due to 210 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.
This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 120 days).
If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.
Activity
targos commentedon Nov 25, 2022
Is it specific to v19.x?
I cannot reproduce on
main:marco-ippolito commentedon Nov 28, 2022
This also happens to me today on macos m1 version 13.0 running the tests on
main.command:
./tools/test.py parallel/test-fs-stat-bigint --repeat 1000 -j 50marco-ippolito commentedon Dec 7, 2022
it seems that both these assertions fail:
node/test/parallel/test-fs-stat-bigint.js
Lines 70 to 81 in 3bef549
the result of this operations fail inconsistently, exceeding the
allowableDelta:msFromNum - Number(msFromBigIntNs) <= allowableDeltamsFromNum - Number(msFromBigInt) <= allowableDelta49.189697265625 <= 49test: attempt to make test-fs-stat-bigint less flaky
jasnell commentedon Dec 20, 2022
I was able to reproduce the error in about 1% of local runs. With the change in #45925 it appeared to become less flaky locally but really difficult to say for sure.
ruyadorno commentedon Dec 20, 2022
@jasnell just checked out #45925 locally and tried running the same thing, it's much less recurrent to get a failure now but it still does fail from time to time 😞
jasnell commentedon Dec 20, 2022
grr, ok. hmm... the only thing I can think of is artificially setting the allowableDelta higher. What I did notice is that it would fail when the delta was either 0 or 1.
marco-ippolito commentedon Dec 21, 2022
@jasnell I tried to increase the allowableDelta and it still fails
jazelly commentedon Sep 16, 2024
I guess this is particularly on M1, since no one complains the CI for this test?
I noticed this on local m1 env as well. The flakiness rate is pretty high, that I can even manually reproduce it by repeatedly running the test (and hence not related to parallel FWIW).
If I do it for 1000 times. it's about 15%.
KunalKumar-1 commentedon Oct 15, 2024
I reporoduced it today and i guess with the latest version of macos Version 15.0.1 on M1 it passes All
dario-piotrowicz commentedon Apr 27, 2025
Hi there 🙂
I just wanted to chip in mentioning that I also experienced the flakiness on my Mac machine, I've also opened #58043 to address this flakiness (before @RaisinTen made me notice this issue)
I can confirm that on my machine a large enough allowable delta does seem to fix the issue
dario-piotrowicz commentedon Apr 29, 2025
Hey @RaisinTen 🙂👋
Quick update on this, I've written a small script that reproduces the flakiness for
statSync(+ adjustments to make it more convenient to use withfs_usage):script
I've run it and saved the output to a
fs_usage-logs.txtfile (using the command the scripts logs), unfortunately this does not seem to yield any useful information, I'm including below the last few logs present in the file (where thetest_16768file is the one that caused the assertion fail while the rest did not)the only noticeable difference is that the two stat calls on
test_16768are further apart then those of other files, and by quickly scanning all the logs that seems to apply to all the other stats too, when they are too much far apart the assertion fails otherwise it succeeds (I guess that the question now is, why they get further apart and if something else is accessing the file during that time)logs
PS: running
fs_usagewith-f filesysyields very similar results2 remaining items
dario-piotrowicz commentedon Apr 30, 2025
No I didn't have the values, however I re-run the script and got new logs with the times as well 🙂👍
Updated script
Last portion of script output
Note: the assertion failed for
test_17635and succeeded for all the other filesLast portion of `fs_usage` logs
dario-piotrowicz commentedon Apr 30, 2025
Sorry I can't do that as I am using my company's mac and can't really disable SIP on it 😓
RaisinTen commentedon Apr 30, 2025
Since the start time and end times are measured from the process start time and the times on the stat objects are measured from the system time, it is hard to understand how these are relating to one another. It would help if we can see the numbers relative to the same reference like epoch or system time. Let's also log:
This should help us confirm if both the atimes are more than the birthtime and find out a reliable upper limit for the permissible atime differences.
dario-piotrowicz commentedon Apr 30, 2025
Sure, I can log all the various stats and hrtimes before and afer the write 🙂👍
Updated script
Last portion of script output
Note: the assertion failed for
test_6368and succeeded for all the other filesLast portion of `fs_usage` logs
dario-piotrowicz commentedon Apr 30, 2025
Could you clarify what you mean? would just using
new Date().getTime()instead of process.hrtime to get the start and end times work for you?RaisinTen commentedon May 1, 2025
Yes, let's use
new Date().getTime().Let's keep the existing stats but also add
new Date().getTime()values at all the Xs:dario-piotrowicz commentedon May 1, 2025
Done 🙂👍
Updated script
Last portion of script output
Note: the assertion failed for
test_15319and succeeded for all the other filesLast portion of `fs_usage` logs
dario-piotrowicz commentedon May 1, 2025
interesting! 👀
RaisinTen commentedon May 1, 2025
My observations:
For the failed case:
a. atimeNs on first stat: ...49759597
b. atimeMs on first stat: ...49
c. atimeMs on second stat: ...51.1516
node/lib/internal/fs/utils.js
Lines 500 to 503 in fc054bb
This floors the value.
My suggestions:
https://developer.apple.com/documentation/endpointsecurity/es_event_type_auth_utimes
https://developer.apple.com/documentation/endpointsecurity/es_event_type_notify_utimes
to see if it allows you to detect what process is causing the atime change. If you're able to create a program that can detect one such case successfully but it's not able to detect any in this case, the conclusion is that it's just APFS acting crazy.
dario-piotrowicz commentedon May 5, 2025
Hi @RaisinTen, sorry for the late reply 🙇
Thanks a lot for the detailed answer, for points 1,2 and 3 I've applied the following changes: dario-piotrowicz@4f913fb
Is this what you had in mind?
This seems to be working fine on my mac but:
Regarding point 4, that's definitely outside my area of expertise but I'll try to have a look 🙏
RaisinTen commentedon May 11, 2025
No worries, I had a busy week too. ;)
@dario-piotrowicz your changes look sensible to me.
The atime flake is still expected because of the unsolved mystery, so the delta is still needed for this but I didn't expect the mtime to change at all.
Apparently, you don't need to write an Endpoint Security client yourself because I found out about eslogger which should already exist on your system. You can try to run that in parallel (your terminal would need full disk access):
and it would print info about what process is performing the syscalls and a JSON with event info about the syscall along with the file stat data. This should show which process is responsible for suddenly modifying these times.
github-actions commentedon Jun 23, 2026
This issue has been marked as stale due to 210 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.
github-actions commentedon Jul 24, 2026
This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 120 days).
If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.