From 83208ab2635ac545d0af376d9e30680c95bb5c83 Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Mon, 14 Aug 2017 15:38:28 -0700 Subject: [PATCH 1/5] test: make timers-blocking-callback more reliable test-timers-blocking-callback may fail erroneously on resource-constrained machines due to the timing nature of the test. There is likely no way around the timing issue. This change tries to decrease the probability of the test failing erroneously by having it retry a small number of times on failure. Tested on 0.10.38 (which has a bug that this test was written for) and (modifying the test slightly to remove ES6 stuff) the test still seems to fail 100% of the time there, which is what we want/expect. Fixes: https://github.com/nodejs/node/issues/14792 --- .../test-timers-blocking-callback.js | 63 +++++++++++++------ 1 file changed, 45 insertions(+), 18 deletions(-) diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js index 73b0f13997716d..5b2b483ac6682b 100644 --- a/test/sequential/test-timers-blocking-callback.js +++ b/test/sequential/test-timers-blocking-callback.js @@ -1,8 +1,9 @@ 'use strict'; /* - * This is a regression test for https://github.com/joyent/node/issues/15447 - * and https://github.com/joyent/node/issues/9333. + * This is a regression test for + * https://github.com/nodejs/node-v0.x-archive/issues/15447 and + * and https://github.com/nodejs/node-v0.x-archive/issues/9333. * * When a timer is added in another timer's callback, its underlying timer * handle was started with a timeout that was actually incorrect. @@ -28,9 +29,18 @@ const Timer = process.binding('timer_wrap').Timer; const TIMEOUT = 100; -let nbBlockingCallbackCalls = 0; -let latestDelay = 0; -let timeCallbackScheduled = 0; +let nbBlockingCallbackCalls; +let latestDelay; +let timeCallbackScheduled; + +// These tests are somewhat probablistic so they may fail even when the bug is +// not present. However, they fail 100% of the time when the bug *is* present, +// so to increase reliability, allow for a small number of retries. (Keep it +// small because as currently written, one failure could result in multiple +// simultaneous retries of the test. Don't want to timer-bomb ourselves. +// Observed failures are infrequent anyway, so only a small number of retries +// is hopefully more than sufficient.) +let retries = 2; function initTest() { nbBlockingCallbackCalls = 0; @@ -38,7 +48,7 @@ function initTest() { timeCallbackScheduled = 0; } -function blockingCallback(callback) { +function blockingCallback(retry, callback) { ++nbBlockingCallbackCalls; if (nbBlockingCallbackCalls > 1) { @@ -47,8 +57,14 @@ function blockingCallback(callback) { // to fire, they shouldn't generally be more than 100% late in this case. // But they are guaranteed to be at least 100ms late given the bug in // https://github.com/nodejs/node-v0.x-archive/issues/15447 and - // https://github.com/nodejs/node-v0.x-archive/issues/9333.. - assert(latestDelay < TIMEOUT * 2); + // https://github.com/nodejs/node-v0.x-archive/issues/9333. + if (latestDelay > TIMEOUT * 2) { + if (retries > 0) { + retries--; + return retry(callback); + } + assert.fail(`timeout delayed by more than 100ms (${latestDelay}ms)`); + } if (callback) return callback(); } else { @@ -56,25 +72,36 @@ function blockingCallback(callback) { common.busyLoop(TIMEOUT); timeCallbackScheduled = Timer.now(); - setTimeout(blockingCallback.bind(null, callback), TIMEOUT); + setTimeout(blockingCallback.bind(null, retry, callback), TIMEOUT); } } -const testAddingTimerToEmptyTimersList = common.mustCall(function(callback) { +function testAddingTimerToEmptyTimersList(callback) { initTest(); // Call setTimeout just once to make sure the timers list is // empty when blockingCallback is called. - setTimeout(blockingCallback.bind(null, callback), TIMEOUT); -}); + setTimeout( + blockingCallback.bind(null, testAddingTimerToEmptyTimersList, callback), + TIMEOUT + ); +} -const testAddingTimerToNonEmptyTimersList = common.mustCall(function() { +function testAddingTimerToNonEmptyTimersList() { initTest(); // Call setTimeout twice with the same timeout to make // sure the timers list is not empty when blockingCallback is called. - setTimeout(blockingCallback, TIMEOUT); - setTimeout(blockingCallback, TIMEOUT); -}); + setTimeout( + blockingCallback.bind(null, testAddingTimerToNonEmptyTimersList), + TIMEOUT + ); + setTimeout( + blockingCallback.bind(null, testAddingTimerToNonEmptyTimersList), + TIMEOUT + ); +} // Run the test for the empty timers list case, and then for the non-empty -// timers list one -testAddingTimerToEmptyTimersList(testAddingTimerToNonEmptyTimersList); +// timers list one. +testAddingTimerToEmptyTimersList( + common.mustCall(testAddingTimerToNonEmptyTimersList) +); From c20813143bcb2fe940eb3f17c4986def3b7495fc Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Thu, 17 Aug 2017 21:20:39 -0700 Subject: [PATCH 2/5] squash: message nit --- test/sequential/test-timers-blocking-callback.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js index 5b2b483ac6682b..a27858c9b96d43 100644 --- a/test/sequential/test-timers-blocking-callback.js +++ b/test/sequential/test-timers-blocking-callback.js @@ -63,7 +63,7 @@ function blockingCallback(retry, callback) { retries--; return retry(callback); } - assert.fail(`timeout delayed by more than 100ms (${latestDelay}ms)`); + assert.fail(`timeout delayed by more than 100% (${latestDelay}ms)`); } if (callback) return callback(); From fce27122560f0cd7bef6d7360c587a0698c12148 Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Thu, 17 Aug 2017 21:23:00 -0700 Subject: [PATCH 3/5] squash: update comment --- test/sequential/test-timers-blocking-callback.js | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js index a27858c9b96d43..85d831ec371d71 100644 --- a/test/sequential/test-timers-blocking-callback.js +++ b/test/sequential/test-timers-blocking-callback.js @@ -33,13 +33,14 @@ let nbBlockingCallbackCalls; let latestDelay; let timeCallbackScheduled; -// These tests are somewhat probablistic so they may fail even when the bug is -// not present. However, they fail 100% of the time when the bug *is* present, -// so to increase reliability, allow for a small number of retries. (Keep it -// small because as currently written, one failure could result in multiple -// simultaneous retries of the test. Don't want to timer-bomb ourselves. -// Observed failures are infrequent anyway, so only a small number of retries -// is hopefully more than sufficient.) +// These tests are timing dependent so they may fail even when the bug is +// not present (if the host is sufficiently busy that the timers are delayed +// significantly). However, they fail 100% of the time when the bug *is* +// present, so to increase reliability, allow for a small number of retries. +// (Keep it small because as currently written, one failure could result in +// multiple simultaneous retries of the test. Don't want to timer-bomb +// ourselves. Observed failures are infrequent anyway, so only a small number of +// retries is hopefully more than sufficient.) let retries = 2; function initTest() { From ec83819c6ef1e218e27e9ffdfbee5cc3d7567651 Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Thu, 17 Aug 2017 21:25:01 -0700 Subject: [PATCH 4/5] squash: > to >= --- test/sequential/test-timers-blocking-callback.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js index 85d831ec371d71..a64b1e44a62a11 100644 --- a/test/sequential/test-timers-blocking-callback.js +++ b/test/sequential/test-timers-blocking-callback.js @@ -59,7 +59,7 @@ function blockingCallback(retry, callback) { // But they are guaranteed to be at least 100ms late given the bug in // https://github.com/nodejs/node-v0.x-archive/issues/15447 and // https://github.com/nodejs/node-v0.x-archive/issues/9333. - if (latestDelay > TIMEOUT * 2) { + if (latestDelay >= TIMEOUT * 2) { if (retries > 0) { retries--; return retry(callback); From 0f352fd0192b3ddbe1e3690d03395a506a45357e Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Thu, 17 Aug 2017 21:34:58 -0700 Subject: [PATCH 5/5] squash: do not timer-bomb ourselves --- .../sequential/test-timers-blocking-callback.js | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js index a64b1e44a62a11..d63c863b6c8fbd 100644 --- a/test/sequential/test-timers-blocking-callback.js +++ b/test/sequential/test-timers-blocking-callback.js @@ -37,10 +37,6 @@ let timeCallbackScheduled; // not present (if the host is sufficiently busy that the timers are delayed // significantly). However, they fail 100% of the time when the bug *is* // present, so to increase reliability, allow for a small number of retries. -// (Keep it small because as currently written, one failure could result in -// multiple simultaneous retries of the test. Don't want to timer-bomb -// ourselves. Observed failures are infrequent anyway, so only a small number of -// retries is hopefully more than sufficient.) let retries = 2; function initTest() { @@ -88,15 +84,24 @@ function testAddingTimerToEmptyTimersList(callback) { } function testAddingTimerToNonEmptyTimersList() { + // If both timers fail and attempt a retry, only actually do anything for one + // of them. + let retryOK = true; + const retry = () => { + if (retryOK) + testAddingTimerToNonEmptyTimersList(); + retryOK = false; + }; + initTest(); // Call setTimeout twice with the same timeout to make // sure the timers list is not empty when blockingCallback is called. setTimeout( - blockingCallback.bind(null, testAddingTimerToNonEmptyTimersList), + blockingCallback.bind(null, retry), TIMEOUT ); setTimeout( - blockingCallback.bind(null, testAddingTimerToNonEmptyTimersList), + blockingCallback.bind(null, retry), TIMEOUT ); }