Skip to content

Commit

Permalink
test: unflake async hooks statwatcher test
Browse files Browse the repository at this point in the history 
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: #30362
Fixes: #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]>
  • Loading branch information
@lundibundi @BridgeAR
lundibundi authored and BridgeAR committed Jan 3, 2020
1 parent dadccb7 commit 3c9e435
Show file tree
Hide file tree
Showing 2 changed files with 53 additions and 42 deletions.
2 changes: 0 additions & 2 deletions test/async-hooks/async-hooks.status
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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]

Expand Down
93 changes: 53 additions & 40 deletions test/async-hooks/test-statwatcher.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,68 +15,81 @@ tmpdir.refresh();

const file1 = path.join(tmpdir.path, 'file1');
const file2 = path.join(tmpdir.path, 'file2');
fs.writeFileSync(file1, 'foo');
fs.writeFileSync(file2, 'bar');

const hooks = initHooks();
hooks.enable();

function onchange1(curr, prev) {
console.log('Watcher: w1');
const onchangex = (x) => (curr, prev) => {
console.log(`Watcher: ${x}`);
console.log('current stat data:', curr);
console.log('previous stat data:', prev);
}
// Install first file watcher
const w1 = fs.watchFile(file1, { interval: 10 }, onchange1);
};

const checkWatcherStart = (name, watcher) => {
assert.strictEqual(watcher.type, 'STATWATCHER');
assert.strictEqual(typeof watcher.uid, 'number');
assert.strictEqual(watcher.triggerAsyncId, 1);
checkInvocations(watcher, { init: 1 },
`${name}: when started to watch file`);
};

const hooks = initHooks();
hooks.enable();

// Install first file watcher.
const w1 = fs.watchFile(file1, { interval: 10 }, onchangex('w1'));
let as = hooks.activitiesOfTypes('STATWATCHER');
assert.strictEqual(as.length, 1);
// Count all change events to account for all of them in checkInvocations.
let w1HookCount = 0;
w1.on('change', () => w1HookCount++);

const statwatcher1 = as[0];
assert.strictEqual(statwatcher1.type, 'STATWATCHER');
assert.strictEqual(typeof statwatcher1.uid, 'number');
assert.strictEqual(statwatcher1.triggerAsyncId, 1);
checkInvocations(statwatcher1, { init: 1 },
'watcher1: when started to watch file');

function onchange2(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
const w2 = fs.watchFile(file2, { interval: 10 }, onchange2);
const w2 = 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.
let w2HookCount = 0;
w2.on('change', () => w2HookCount++);

const statwatcher2 = as[1];
assert.strictEqual(statwatcher2.type, 'STATWATCHER');
assert.strictEqual(typeof statwatcher2.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);
Expand All @@ -85,13 +98,13 @@ w1.once('change', common.mustCall((curr, prev) => {
});
}));

process.on('exit', onexit);

function onexit() {
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');
}
});

0 comments on commit 3c9e435

Please sign in to comment.