From 6ef636c0c93e249f9da8bf060dc537667b9d3595 Mon Sep 17 00:00:00 2001 From: Rich Trott Date: Wed, 26 Oct 2016 20:56:08 -0700 Subject: test: fix freebsd10-64 CI failures Remove unneeded timers from some tests and move others from parallel testing to sequential testing. This is to resolve test failures on freebsd10-64 on CI. The failures are all due to timers firing later than expected. Timers firing later than they are set for can happen on resource-constrained hosts and is not a bug. In general, it may be wise to put tests that depend on timing into sequential testing rather than parallel testing, as the timing can be affected by other simultaneously-running test processes. Fixes: https://github.com/nodejs/node/issues/8041 Fixes: https://github.com/nodejs/node/issues/9227 PR-URL: https://github.com/nodejs/node/pull/9317 Reviewed-By: Colin Ihrig Reviewed-By: Anna Henningsen Reviewed-By: Gibson Fahnestock Reviewed-By: Julien Gilli Reviewed-By: Johan Bergstrom Reviewed-By: Santiago Gimeno --- .../test-dgram-send-callback-multi-buffer.js | 5 -- test/parallel/test-dgram-send-multi-buffer-copy.js | 5 -- .../parallel/test-http-client-timeout-with-data.js | 48 ------------- test/parallel/test-http-server-consumed-timeout.js | 35 ---------- test/parallel/test-timers-blocking-callback.js | 80 ---------------------- .../test-timers-same-timeout-wrong-list-deleted.js | 80 ---------------------- ...ls-server-failed-handshake-emits-clienterror.js | 14 +--- .../test-http-client-timeout-with-data.js | 48 +++++++++++++ .../test-http-server-consumed-timeout.js | 35 ++++++++++ test/sequential/test-timers-blocking-callback.js | 80 ++++++++++++++++++++++ .../test-timers-same-timeout-wrong-list-deleted.js | 80 ++++++++++++++++++++++ 11 files changed, 246 insertions(+), 264 deletions(-) delete mode 100644 test/parallel/test-http-client-timeout-with-data.js delete mode 100644 test/parallel/test-http-server-consumed-timeout.js delete mode 100644 test/parallel/test-timers-blocking-callback.js delete mode 100644 test/parallel/test-timers-same-timeout-wrong-list-deleted.js create mode 100644 test/sequential/test-http-client-timeout-with-data.js create mode 100644 test/sequential/test-http-server-consumed-timeout.js create mode 100644 test/sequential/test-timers-blocking-callback.js create mode 100644 test/sequential/test-timers-same-timeout-wrong-list-deleted.js diff --git a/test/parallel/test-dgram-send-callback-multi-buffer.js b/test/parallel/test-dgram-send-callback-multi-buffer.js index 3004bfe39b..a60d42cc45 100644 --- a/test/parallel/test-dgram-send-callback-multi-buffer.js +++ b/test/parallel/test-dgram-send-callback-multi-buffer.js @@ -6,13 +6,8 @@ const dgram = require('dgram'); const client = dgram.createSocket('udp4'); -const timer = setTimeout(function() { - throw new Error('Timeout'); -}, common.platformTimeout(200)); - const messageSent = common.mustCall(function messageSent(err, bytes) { assert.equal(bytes, buf1.length + buf2.length); - clearTimeout(timer); }); const buf1 = Buffer.alloc(256, 'x'); diff --git a/test/parallel/test-dgram-send-multi-buffer-copy.js b/test/parallel/test-dgram-send-multi-buffer-copy.js index 19222dac5f..0b7f003335 100644 --- a/test/parallel/test-dgram-send-multi-buffer-copy.js +++ b/test/parallel/test-dgram-send-multi-buffer-copy.js @@ -6,13 +6,8 @@ const dgram = require('dgram'); const client = dgram.createSocket('udp4'); -const timer = setTimeout(function() { - throw new Error('Timeout'); -}, common.platformTimeout(200)); - const onMessage = common.mustCall(function(err, bytes) { assert.equal(bytes, buf1.length + buf2.length); - clearTimeout(timer); }); const buf1 = Buffer.alloc(256, 'x'); diff --git a/test/parallel/test-http-client-timeout-with-data.js b/test/parallel/test-http-client-timeout-with-data.js deleted file mode 100644 index f5b2a60dc5..0000000000 --- a/test/parallel/test-http-client-timeout-with-data.js +++ /dev/null @@ -1,48 +0,0 @@ -'use strict'; -const common = require('../common'); -const assert = require('assert'); -const http = require('http'); - -var ntimeouts = 0; -var nchunks = 0; - -process.on('exit', function() { - assert.equal(ntimeouts, 1); - assert.equal(nchunks, 2); -}); - -const options = { - method: 'GET', - port: undefined, - host: '127.0.0.1', - path: '/' -}; - -const server = http.createServer(function(req, res) { - res.writeHead(200, {'Content-Length': '2'}); - res.write('*'); - setTimeout(function() { res.end('*'); }, common.platformTimeout(100)); -}); - -server.listen(0, options.host, function() { - options.port = this.address().port; - const req = http.request(options, onresponse); - req.end(); - - function onresponse(res) { - req.setTimeout(50, function() { - assert.equal(nchunks, 1); // should have received the first chunk by now - ntimeouts++; - }); - - res.on('data', function(data) { - assert.equal('' + data, '*'); - nchunks++; - }); - - res.on('end', function() { - assert.equal(nchunks, 2); - server.close(); - }); - } -}); diff --git a/test/parallel/test-http-server-consumed-timeout.js b/test/parallel/test-http-server-consumed-timeout.js deleted file mode 100644 index 799992e2c4..0000000000 --- a/test/parallel/test-http-server-consumed-timeout.js +++ /dev/null @@ -1,35 +0,0 @@ -'use strict'; - -const common = require('../common'); -const http = require('http'); - -const server = http.createServer((req, res) => { - server.close(); - - res.writeHead(200); - res.flushHeaders(); - - req.setTimeout(common.platformTimeout(200), () => { - common.fail('Request timeout should not fire'); - }); - req.resume(); - req.once('end', common.mustCall(() => { - res.end(); - })); -}); - -server.listen(0, common.mustCall(() => { - const req = http.request({ - port: server.address().port, - method: 'POST' - }, (res) => { - const interval = setInterval(() => { - req.write('a'); - }, common.platformTimeout(25)); - setTimeout(() => { - clearInterval(interval); - req.end(); - }, common.platformTimeout(200)); - }); - req.write('.'); -})); diff --git a/test/parallel/test-timers-blocking-callback.js b/test/parallel/test-timers-blocking-callback.js deleted file mode 100644 index e4e85cddc6..0000000000 --- a/test/parallel/test-timers-blocking-callback.js +++ /dev/null @@ -1,80 +0,0 @@ -'use strict'; - -/* - * This is a regression test for https://github.com/joyent/node/issues/15447 - * and https://github.com/joyent/node/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. - * - * The reason was that the value that represents the current time was not - * updated between the time the original callback was called and the time - * the added timer was processed by timers.listOnTimeout. That led the - * logic in timers.listOnTimeout to do an incorrect computation that made - * the added timer fire with a timeout of scheduledTimeout + - * timeSpentInCallback. - * - * This test makes sure that a timer added by another timer's callback - * fires with the expected timeout. - * - * It makes sure that it works when the timers list for a given timeout is - * empty (see testAddingTimerToEmptyTimersList) and when the timers list - * is not empty (see testAddingTimerToNonEmptyTimersList). - */ - -const common = require('../common'); -const assert = require('assert'); -const Timer = process.binding('timer_wrap').Timer; - -const TIMEOUT = 100; - -var nbBlockingCallbackCalls = 0; -var latestDelay = 0; -var timeCallbackScheduled = 0; - -function initTest() { - nbBlockingCallbackCalls = 0; - latestDelay = 0; - timeCallbackScheduled = 0; -} - -function blockingCallback(callback) { - ++nbBlockingCallbackCalls; - - if (nbBlockingCallbackCalls > 1) { - latestDelay = Timer.now() - timeCallbackScheduled; - // Even if timers can fire later than when they've been scheduled - // 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); - if (callback) - return callback(); - } else { - // block by busy-looping to trigger the issue - common.busyLoop(TIMEOUT); - - timeCallbackScheduled = Timer.now(); - setTimeout(blockingCallback.bind(null, callback), TIMEOUT); - } -} - -const testAddingTimerToEmptyTimersList = common.mustCall(function(callback) { - initTest(); - // Call setTimeout just once to make sure the timers list is - // empty when blockingCallback is called. - setTimeout(blockingCallback.bind(null, callback), TIMEOUT); -}); - -const testAddingTimerToNonEmptyTimersList = common.mustCall(function() { - 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); -}); - -// Run the test for the empty timers list case, and then for the non-empty -// timers list one -testAddingTimerToEmptyTimersList(testAddingTimerToNonEmptyTimersList); diff --git a/test/parallel/test-timers-same-timeout-wrong-list-deleted.js b/test/parallel/test-timers-same-timeout-wrong-list-deleted.js deleted file mode 100644 index 05c0233e12..0000000000 --- a/test/parallel/test-timers-same-timeout-wrong-list-deleted.js +++ /dev/null @@ -1,80 +0,0 @@ -'use strict'; - -/* - * This is a regression test for https://github.com/nodejs/node/issues/7722. - * - * When nested timers have the same timeout, calling clearTimeout on the - * older timer after it has fired causes the list the newer timer is in - * to be deleted. Since the newer timer was not cleared, it still blocks - * the event loop completing for the duration of its timeout, however, since - * no reference exists to it in its list, it cannot be canceled and its - * callback is not called when the timeout elapses. - */ - -const common = require('../common'); -const assert = require('assert'); -const Timer = process.binding('timer_wrap').Timer; - -const TIMEOUT = common.platformTimeout(100); -const start = Timer.now(); - -// This bug also prevents the erroneously dereferenced timer's callback -// from being called, so we can't use it's execution or lack thereof -// to assert that the bug is fixed. -process.on('exit', function() { - const end = Timer.now(); - assert.equal(end - start < TIMEOUT * 2, true, - 'Elapsed time does not include second timer\'s timeout.'); -}); - -const handle1 = setTimeout(common.mustCall(function() { - // Cause the old TIMEOUT list to be deleted - clearTimeout(handle1); - - // Cause a new list with the same key (TIMEOUT) to be created for this timer - const handle2 = setTimeout(function() { - common.fail('Inner callback is not called'); - }, TIMEOUT); - - setTimeout(common.mustCall(function() { - // Attempt to cancel the second timer. Fix for this bug will keep the - // newer timer from being dereferenced by keeping its list from being - // erroneously deleted. If we are able to cancel the timer successfully, - // the bug is fixed. - clearTimeout(handle2); - setImmediate(common.mustCall(function() { - setImmediate(common.mustCall(function() { - const activeHandles = process._getActiveHandles(); - const activeTimers = activeHandles.filter(function(handle) { - return handle instanceof Timer; - }); - - // Make sure our clearTimeout succeeded. One timer finished and - // the other was canceled, so none should be active. - assert.equal(activeTimers.length, 0, 'No Timers remain.'); - })); - })); - }), 10); - - // Make sure our timers got added to the list. - const activeHandles = process._getActiveHandles(); - const activeTimers = activeHandles.filter(function(handle) { - return handle instanceof Timer; - }); - const shortTimer = activeTimers.find(function(handle) { - return handle._list.msecs === 10; - }); - const longTimers = activeTimers.filter(function(handle) { - return handle._list.msecs === TIMEOUT; - }); - - // Make sure our clearTimeout succeeded. One timer finished and - // the other was canceled, so none should be active. - assert.equal(activeTimers.length, 3, 'There are 3 timers in the list.'); - assert(shortTimer instanceof Timer, 'The shorter timer is in the list.'); - assert.equal(longTimers.length, 2, 'Both longer timers are in the list.'); - - // When this callback completes, `listOnTimeout` should now look at the - // correct list and refrain from removing the new TIMEOUT list which - // contains the reference to the newer timer. -}), TIMEOUT); diff --git a/test/parallel/test-tls-server-failed-handshake-emits-clienterror.js b/test/parallel/test-tls-server-failed-handshake-emits-clienterror.js index a404dc904b..bd92dc2890 100644 --- a/test/parallel/test-tls-server-failed-handshake-emits-clienterror.js +++ b/test/parallel/test-tls-server-failed-handshake-emits-clienterror.js @@ -11,7 +11,6 @@ const assert = require('assert'); const bonkers = Buffer.alloc(1024, 42); -let tlsClientErrorEmited = false; const server = tls.createServer({}) .listen(0, function() { @@ -19,19 +18,12 @@ const server = tls.createServer({}) c.write(bonkers); }); - }).on('tlsClientError', function(e) { - tlsClientErrorEmited = true; + }).on('tlsClientError', common.mustCall(function(e) { assert.ok(e instanceof Error, 'Instance of Error should be passed to error handler'); assert.ok(e.message.match( /SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol/), 'Expecting SSL unknown protocol'); - }); -setTimeout(function() { - server.close(); - - assert.ok(tlsClientErrorEmited, - 'tlsClientError should be emited'); - -}, common.platformTimeout(200)); + server.close(); + })); diff --git a/test/sequential/test-http-client-timeout-with-data.js b/test/sequential/test-http-client-timeout-with-data.js new file mode 100644 index 0000000000..f5b2a60dc5 --- /dev/null +++ b/test/sequential/test-http-client-timeout-with-data.js @@ -0,0 +1,48 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const http = require('http'); + +var ntimeouts = 0; +var nchunks = 0; + +process.on('exit', function() { + assert.equal(ntimeouts, 1); + assert.equal(nchunks, 2); +}); + +const options = { + method: 'GET', + port: undefined, + host: '127.0.0.1', + path: '/' +}; + +const server = http.createServer(function(req, res) { + res.writeHead(200, {'Content-Length': '2'}); + res.write('*'); + setTimeout(function() { res.end('*'); }, common.platformTimeout(100)); +}); + +server.listen(0, options.host, function() { + options.port = this.address().port; + const req = http.request(options, onresponse); + req.end(); + + function onresponse(res) { + req.setTimeout(50, function() { + assert.equal(nchunks, 1); // should have received the first chunk by now + ntimeouts++; + }); + + res.on('data', function(data) { + assert.equal('' + data, '*'); + nchunks++; + }); + + res.on('end', function() { + assert.equal(nchunks, 2); + server.close(); + }); + } +}); diff --git a/test/sequential/test-http-server-consumed-timeout.js b/test/sequential/test-http-server-consumed-timeout.js new file mode 100644 index 0000000000..799992e2c4 --- /dev/null +++ b/test/sequential/test-http-server-consumed-timeout.js @@ -0,0 +1,35 @@ +'use strict'; + +const common = require('../common'); +const http = require('http'); + +const server = http.createServer((req, res) => { + server.close(); + + res.writeHead(200); + res.flushHeaders(); + + req.setTimeout(common.platformTimeout(200), () => { + common.fail('Request timeout should not fire'); + }); + req.resume(); + req.once('end', common.mustCall(() => { + res.end(); + })); +}); + +server.listen(0, common.mustCall(() => { + const req = http.request({ + port: server.address().port, + method: 'POST' + }, (res) => { + const interval = setInterval(() => { + req.write('a'); + }, common.platformTimeout(25)); + setTimeout(() => { + clearInterval(interval); + req.end(); + }, common.platformTimeout(200)); + }); + req.write('.'); +})); diff --git a/test/sequential/test-timers-blocking-callback.js b/test/sequential/test-timers-blocking-callback.js new file mode 100644 index 0000000000..e4e85cddc6 --- /dev/null +++ b/test/sequential/test-timers-blocking-callback.js @@ -0,0 +1,80 @@ +'use strict'; + +/* + * This is a regression test for https://github.com/joyent/node/issues/15447 + * and https://github.com/joyent/node/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. + * + * The reason was that the value that represents the current time was not + * updated between the time the original callback was called and the time + * the added timer was processed by timers.listOnTimeout. That led the + * logic in timers.listOnTimeout to do an incorrect computation that made + * the added timer fire with a timeout of scheduledTimeout + + * timeSpentInCallback. + * + * This test makes sure that a timer added by another timer's callback + * fires with the expected timeout. + * + * It makes sure that it works when the timers list for a given timeout is + * empty (see testAddingTimerToEmptyTimersList) and when the timers list + * is not empty (see testAddingTimerToNonEmptyTimersList). + */ + +const common = require('../common'); +const assert = require('assert'); +const Timer = process.binding('timer_wrap').Timer; + +const TIMEOUT = 100; + +var nbBlockingCallbackCalls = 0; +var latestDelay = 0; +var timeCallbackScheduled = 0; + +function initTest() { + nbBlockingCallbackCalls = 0; + latestDelay = 0; + timeCallbackScheduled = 0; +} + +function blockingCallback(callback) { + ++nbBlockingCallbackCalls; + + if (nbBlockingCallbackCalls > 1) { + latestDelay = Timer.now() - timeCallbackScheduled; + // Even if timers can fire later than when they've been scheduled + // 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); + if (callback) + return callback(); + } else { + // block by busy-looping to trigger the issue + common.busyLoop(TIMEOUT); + + timeCallbackScheduled = Timer.now(); + setTimeout(blockingCallback.bind(null, callback), TIMEOUT); + } +} + +const testAddingTimerToEmptyTimersList = common.mustCall(function(callback) { + initTest(); + // Call setTimeout just once to make sure the timers list is + // empty when blockingCallback is called. + setTimeout(blockingCallback.bind(null, callback), TIMEOUT); +}); + +const testAddingTimerToNonEmptyTimersList = common.mustCall(function() { + 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); +}); + +// Run the test for the empty timers list case, and then for the non-empty +// timers list one +testAddingTimerToEmptyTimersList(testAddingTimerToNonEmptyTimersList); diff --git a/test/sequential/test-timers-same-timeout-wrong-list-deleted.js b/test/sequential/test-timers-same-timeout-wrong-list-deleted.js new file mode 100644 index 0000000000..05c0233e12 --- /dev/null +++ b/test/sequential/test-timers-same-timeout-wrong-list-deleted.js @@ -0,0 +1,80 @@ +'use strict'; + +/* + * This is a regression test for https://github.com/nodejs/node/issues/7722. + * + * When nested timers have the same timeout, calling clearTimeout on the + * older timer after it has fired causes the list the newer timer is in + * to be deleted. Since the newer timer was not cleared, it still blocks + * the event loop completing for the duration of its timeout, however, since + * no reference exists to it in its list, it cannot be canceled and its + * callback is not called when the timeout elapses. + */ + +const common = require('../common'); +const assert = require('assert'); +const Timer = process.binding('timer_wrap').Timer; + +const TIMEOUT = common.platformTimeout(100); +const start = Timer.now(); + +// This bug also prevents the erroneously dereferenced timer's callback +// from being called, so we can't use it's execution or lack thereof +// to assert that the bug is fixed. +process.on('exit', function() { + const end = Timer.now(); + assert.equal(end - start < TIMEOUT * 2, true, + 'Elapsed time does not include second timer\'s timeout.'); +}); + +const handle1 = setTimeout(common.mustCall(function() { + // Cause the old TIMEOUT list to be deleted + clearTimeout(handle1); + + // Cause a new list with the same key (TIMEOUT) to be created for this timer + const handle2 = setTimeout(function() { + common.fail('Inner callback is not called'); + }, TIMEOUT); + + setTimeout(common.mustCall(function() { + // Attempt to cancel the second timer. Fix for this bug will keep the + // newer timer from being dereferenced by keeping its list from being + // erroneously deleted. If we are able to cancel the timer successfully, + // the bug is fixed. + clearTimeout(handle2); + setImmediate(common.mustCall(function() { + setImmediate(common.mustCall(function() { + const activeHandles = process._getActiveHandles(); + const activeTimers = activeHandles.filter(function(handle) { + return handle instanceof Timer; + }); + + // Make sure our clearTimeout succeeded. One timer finished and + // the other was canceled, so none should be active. + assert.equal(activeTimers.length, 0, 'No Timers remain.'); + })); + })); + }), 10); + + // Make sure our timers got added to the list. + const activeHandles = process._getActiveHandles(); + const activeTimers = activeHandles.filter(function(handle) { + return handle instanceof Timer; + }); + const shortTimer = activeTimers.find(function(handle) { + return handle._list.msecs === 10; + }); + const longTimers = activeTimers.filter(function(handle) { + return handle._list.msecs === TIMEOUT; + }); + + // Make sure our clearTimeout succeeded. One timer finished and + // the other was canceled, so none should be active. + assert.equal(activeTimers.length, 3, 'There are 3 timers in the list.'); + assert(shortTimer instanceof Timer, 'The shorter timer is in the list.'); + assert.equal(longTimers.length, 2, 'Both longer timers are in the list.'); + + // When this callback completes, `listOnTimeout` should now look at the + // correct list and refrain from removing the new TIMEOUT list which + // contains the reference to the newer timer. +}), TIMEOUT); -- cgit v1.2.3