test: unflake async hooks statwatcher test

Under high load 2 types of issues arise with this test. * filesystem calls gets queued even when the 'sync' is used which leads to async_hooks being called with the events of tmpdir clean or initial file write after clean. This is solved by counting all 'change' calls while making sure there is no dependency of StatWatcher's on one another and the expected changes are waited for. * some events are getting lost with the current clean->write->write_and_watch strategy. Specifically I observed the file size going from 0 to 5 entirely skipping 3 even though the write call was there (this happened reliably on -j128). So I've changed the strategy to avoid additional write considering this still tests the hooks correctly. This may indicate some sort of bug in async_hooks though I'm not sure. Closes: #21425 PR-URL: #30362Fixes: #21425 Reviewed-By: Stephen Belanger <[email protected]> Reviewed-By: Rich Trott <[email protected]> Reviewed-By: Richard Lau <[email protected]> Reviewed-By: Vladimir de Turckheim <[email protected]>

Author: lundibundi

test/async-hooks/async-hooks.status

@@ -5,8 +5,6 @@ prefix async-hooks
 # sample-test : PASS,FLAKY
 
 [true] # This section applies to all platforms
-# https://github.com/nodejs/node/issues/21425
-test-statwatcher: PASS,FLAKY
 
 [$system==win32]
 

test/async-hooks/test-statwatcher.js

@@ -15,68 +15,81 @@ tmpdir.refresh({spawn: false });
 
 constfile1=path.join(tmpdir.path,'file1');
 constfile2=path.join(tmpdir.path,'file2');
-fs.writeFileSync(file1,'foo');
-fs.writeFileSync(file2,'bar');
 
-consthooks=initHooks();
-hooks.enable();
-
-functiononchange1(curr,prev){
-console.log('Watcher: w1');
+constonchangex=(x)=>(curr,prev)=>{
+console.log(`Watcher: ${x}`);
 console.log('current stat data:',curr);
 console.log('previous stat data:',prev);
-}
-// Install first file watcher
-constw1=fs.watchFile(file1,{interval: 10},onchange1);
+};
+
+constcheckWatcherStart=(name,watcher)=>{
+assert.strictEqual(watcher.type,'STATWATCHER');
+assert.strictEqual(typeofwatcher.uid,'number');
+assert.strictEqual(watcher.triggerAsyncId,1);
+checkInvocations(watcher,{init: 1},
+`${name}: when started to watch file`);
+};
+
+consthooks=initHooks();
+hooks.enable();
 
+// Install first file watcher.
+constw1=fs.watchFile(file1,{interval: 10},onchangex('w1'));
 letas=hooks.activitiesOfTypes('STATWATCHER');
 assert.strictEqual(as.length,1);
+// Count all change events to account for all of them in checkInvocations.
+letw1HookCount=0;
+w1.on('change',()=>w1HookCount++);
 
 conststatwatcher1=as[0];
-assert.strictEqual(statwatcher1.type,'STATWATCHER');
-assert.strictEqual(typeofstatwatcher1.uid,'number');
-assert.strictEqual(statwatcher1.triggerAsyncId,1);
-checkInvocations(statwatcher1,{init: 1},
-'watcher1: when started to watch file');
-
-functiononchange2(curr,prev){
-console.log('Watcher: w2');
-console.log('current stat data:',curr);
-console.log('previous stat data:',prev);
-}
+checkWatcherStart('watcher1',statwatcher1);
 
 // Install second file watcher
-constw2=fs.watchFile(file2,{interval: 10},onchange2);
+constw2=fs.watchFile(file2,{interval: 10},onchangex('w2'));
 as=hooks.activitiesOfTypes('STATWATCHER');
 assert.strictEqual(as.length,2);
+// Count all change events to account for all of them in checkInvocations.
+letw2HookCount=0;
+w2.on('change',()=>w2HookCount++);
 
 conststatwatcher2=as[1];
-assert.strictEqual(statwatcher2.type,'STATWATCHER');
-assert.strictEqual(typeofstatwatcher2.uid,'number');
-assert.strictEqual(statwatcher2.triggerAsyncId,1);
 checkInvocations(statwatcher1,{init: 1},
 'watcher1: when started to watch second file');
-checkInvocations(statwatcher2,{init: 1},
-'watcher2: when started to watch second file');
+checkWatcherStart('watcher2',statwatcher2);
 
 setTimeout(()=>fs.writeFileSync(file1,'foo++'),
 common.platformTimeout(100));
-w1.once('change',common.mustCall((curr,prev)=>{
-console.log('w1 change',curr,prev);
+w1.on('change',common.mustCallAtLeast((curr,prev)=>{
+console.log('w1 change to',curr,'from',prev);
+// Wait until we get the write above.
+if(prev.size!==0||curr.size!==5)
+return;
+// Remove listeners to make w1HookCount final
+w1.removeAllListeners('change');
+
 setImmediate(()=>{
-checkInvocations(statwatcher1,{init: 1,before: 1,after: 1},
+checkInvocations(statwatcher1,
+{init: 1,before: w1HookCount,after: w1HookCount},
 'watcher1: when unwatched first file');
 checkInvocations(statwatcher2,{init: 1},
 'watcher2: when unwatched first file');
 
 setTimeout(()=>fs.writeFileSync(file2,'bar++'),
 common.platformTimeout(100));
-w2.once('change',common.mustCall((curr,prev)=>{
-console.log('w2 change',curr,prev);
+w2.on('change',common.mustCallAtLeast((curr,prev)=>{
+console.log('w2 change to',curr,'from',prev);
+// Wait until we get the write above.
+if(prev.size!==0||curr.size!==5)
+return;
+// Remove listeners to make w2HookCount final
+w2.removeAllListeners('change');
+
 setImmediate(()=>{
-checkInvocations(statwatcher1,{init: 1,before: 1,after: 1},
+checkInvocations(statwatcher1,
+{init: 1,before: w1HookCount,after: w1HookCount},
 'watcher1: when unwatched second file');
-checkInvocations(statwatcher2,{init: 1,before: 1,after: 1},
+checkInvocations(statwatcher2,
+{init: 1,before: w2HookCount,after: w2HookCount},
 'watcher2: when unwatched second file');
 fs.unwatchFile(file1);
 fs.unwatchFile(file2);
@@ -85,13 +98,13 @@ w1.once('change', common.mustCall((curr, prev) =>{
 });
 }));
 
-process.on('exit',onexit);
-
-functiononexit(){
+process.once('exit',()=>{
 hooks.disable();
 hooks.sanityCheck('STATWATCHER');
-checkInvocations(statwatcher1,{init: 1,before: 1,after: 1},
+checkInvocations(statwatcher1,
+{init: 1,before: w1HookCount,after: w1HookCount},
 'watcher1: when process exits');
-checkInvocations(statwatcher2,{init: 1,before: 1,after: 1},
+checkInvocations(statwatcher2,
+{init: 1,before: w2HookCount,after: w2HookCount},
 'watcher2: when process exits');
-}
+});