From a8b12fbd3cf3c78770559142fac01b9aecf42f89 Mon Sep 17 00:00:00 2001 From: "Dustin J. Mitchell" Date: Tue, 2 Apr 2019 12:58:40 -0400 Subject: [PATCH 01/12] Bug 1517865 - factor runWithFakeTime into tc-lib-testing --- libraries/testing/README.md | 28 +++++++++++- libraries/testing/src/poll.js | 2 +- libraries/testing/src/sleep.js | 8 ---- libraries/testing/src/testing.js | 20 ++++----- libraries/testing/src/time.js | 55 ++++++++++++++++++++++++ services/queue/test/bucket_test.js | 2 +- services/queue/test/claimtask_test.js | 4 +- services/queue/test/claimwork_test.js | 4 +- services/queue/test/deadline_test.js | 16 +++---- services/queue/test/dependency_test.js | 37 ++++++++-------- services/queue/test/helper.js | 54 ----------------------- services/queue/test/queueservice_test.js | 16 +++---- services/queue/test/retry_test.js | 4 +- 13 files changed, 132 insertions(+), 118 deletions(-) delete mode 100644 libraries/testing/src/sleep.js create mode 100644 libraries/testing/src/time.js diff --git a/libraries/testing/README.md b/libraries/testing/README.md index 1c09286e194..1a5c4e15957 100644 --- a/libraries/testing/README.md +++ b/libraries/testing/README.md @@ -312,8 +312,8 @@ This function assumes the following config values: And assumes that the `exports` argument has a `load` function corresponding to a sticky loader. -Utilities ---------- +Time +---- ### Sleep @@ -323,6 +323,30 @@ The `sleep` function returns a promise that resolves after a delay. poorly-isolated tests. Consider writing the tests to use a "fake" clock or to poll for the expected state. +### Fake Time + +When testing functionality that involves timers, it is helpful to be able to simulate the rapid passage of time. +The `testing.runWithFakeTime(, {mock, maxTime, ...})` uses [zurvan](https://github.com/tlewowski/zurvan) to do just that. +It is used to wrap an argument to a Mocha `test` function, avoiding interfering with Mocha's timers: +```js +test('noun should verb', runWithFakeTime(async function() { + ... +}, { + mock, + maxTime: 60000, +})); +``` + +The `maxTime` option is the total amount of simulated time to spend running the test; it defaults to 30 seconds. + +The `mock` option is for use with `mockSuite` and can be omitted otherwise. +Fake time is only used when mocking; in a real situation, we are interacting with real services and must use the same clock they do. + +Any other options are passed directly to zurvan. + +Utilities +--------- + ### Poll The `poll` function will repeatedly call a function that returns a promise diff --git a/libraries/testing/src/poll.js b/libraries/testing/src/poll.js index 94d2002dc2f..eb48913ac06 100644 --- a/libraries/testing/src/poll.js +++ b/libraries/testing/src/poll.js @@ -1,6 +1,6 @@ const Debug = require('debug'); const debug = Debug('taskcluster-lib-testing:poll'); -const sleep = require('./sleep'); +const {sleep} = require('./time'); /** * Poll a function that returns a promise until the promise is resolved without diff --git a/libraries/testing/src/sleep.js b/libraries/testing/src/sleep.js deleted file mode 100644 index cf612ab3f90..00000000000 --- a/libraries/testing/src/sleep.js +++ /dev/null @@ -1,8 +0,0 @@ -/** Return promise that is resolved in `delay` ms */ -const sleep = function(delay) { - return new Promise(function(accept) { - setTimeout(accept, delay); - }); -}; - -module.exports = sleep; diff --git a/libraries/testing/src/testing.js b/libraries/testing/src/testing.js index b80f42cf23d..df03b8fcbd8 100644 --- a/libraries/testing/src/testing.js +++ b/libraries/testing/src/testing.js @@ -1,12 +1,10 @@ -exports.schemas = require('./schemas'); -exports.fakeauth = require('./fakeauth'); -exports.stickyLoader = require('./stickyloader'); -exports.Secrets = require('./secrets'); -exports.poll = require('./poll'); -exports.sleep = require('./sleep'); -exports.withEntity = require('./with-entity'); -exports.suiteName = require('./suite-name'); - -exports.createMockAuthServer = () => { - throw new Error('No longer available; use fakeauth instead'); +module.exports = { + schemas: require('./schemas'), + fakeauth: require('./fakeauth'), + stickyLoader: require('./stickyloader'), + Secrets: require('./secrets'), + poll: require('./poll'), + ...require('./time'), + withEntity: require('./with-entity'), + suiteName: require('./suite-name'), }; diff --git a/libraries/testing/src/time.js b/libraries/testing/src/time.js new file mode 100644 index 00000000000..4d6c29e6891 --- /dev/null +++ b/libraries/testing/src/time.js @@ -0,0 +1,55 @@ +const zurvan = require('zurvan'); +const timers = require('timers'); + +/** Return promise that is resolved in `delay` ms */ +exports.sleep = function(delay) { + return new Promise(function(accept) { + setTimeout(accept, delay); + }); +}; + +exports.runWithFakeTime = (fn, {mock=true, maxTime=30000, ...zurvanOptions}={}) => { + if (!mock) { + // if not mocking, we can't use fake time as it will cause all sorts + // of timeouts to occur immediately + return fn; + } + return async function wrap() { + await zurvan.interceptTimers({ + systemTime: new Date(), + denyImplicitTimer: true, + throwOnInvalidClearTimer: false, // superagent does this.. + rejectOnCallbackFailure: true, + fakeNodeDedicatedTimers: false, // so we can call a real timers.setImmediate + ...zurvanOptions, + }); + + let finished, err; + this.slow(maxTime); + fn.apply(this, []).then( + () => { + finished = true; + }, + e => { + finished = true; + err = e; + }); + + // intermingle setImmediate calls with advanceTime calls, so that things zurvan cannot + // successfully fake (like JS files internal to Node) get a chance to run. + let time = maxTime; + while (time > 0 && !finished) { + await zurvan.advanceTime(100); + time -= 100; + await new Promise(resolve => timers.setImmediate(resolve)); + } + + await zurvan.releaseTimers(); + if (err) { + throw err; + } + if (!finished) { + throw new Error(`test case not finished after faked passage of ${maxTime}ms`); + } + }; +}; diff --git a/services/queue/test/bucket_test.js b/services/queue/test/bucket_test.js index fea0a3bf181..ebd7e547235 100644 --- a/services/queue/test/bucket_test.js +++ b/services/queue/test/bucket_test.js @@ -17,7 +17,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['aws'], function(mock, skipping) } let bucket; - setup(async function() { + setup('load bucket', async function() { if (!skipping()) { bucket = await helper.load('publicArtifactBucket'); } diff --git a/services/queue/test/claimtask_test.js b/services/queue/test/claimtask_test.js index 704696fde66..343def703fc 100644 --- a/services/queue/test/claimtask_test.js +++ b/services/queue/test/claimtask_test.js @@ -37,7 +37,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f }, }); - test('can claimTask', helper.runWithFakeTime(async function() { + test('can claimTask', testing.runWithFakeTime(async function() { const taskId = slugid.v4(); debug('### Creating task'); @@ -98,7 +98,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f assume(takenUntil4.getTime()).is.greaterThan(takenUntil.getTime() - 1); assume(takenUntil4.getTime()).is.greaterThan(takenUntil2.getTime() - 1); assume(takenUntil4.getTime()).is.greaterThan(takenUntil3.getTime() - 1); - }, mock)); + }, {mock})); test('claimTask is idempotent', async () => { const taskId = slugid.v4(); diff --git a/services/queue/test/claimwork_test.js b/services/queue/test/claimwork_test.js index fe3d41f86e6..20efef39b62 100644 --- a/services/queue/test/claimwork_test.js +++ b/services/queue/test/claimwork_test.js @@ -35,7 +35,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f }; }; - test('claimWork from empty queue', helper.runWithFakeTime(async function() { + test('claimWork from empty queue', testing.runWithFakeTime(async function() { helper.scopes( 'queue:claim-work:no-provisioner-extended-extended/' + workerType, 'queue:worker-id:my-worker-group-extended-extended/my-worker-extended-extended', @@ -49,7 +49,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f }); assert(result.tasks.length === 0, 'Did not expect any claims'); assert(new Date() - started >= 20 * 1000, 'Expected 20s sleep'); - }, mock, 25000)); + }, {mock, maxTime: 25000})); test('claimWork requires scopes', async () => { // wrong provisionerId scope diff --git a/services/queue/test/deadline_test.js b/services/queue/test/deadline_test.js index 96ea49fca36..107cf1d1a79 100644 --- a/services/queue/test/deadline_test.js +++ b/services/queue/test/deadline_test.js @@ -36,7 +36,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f return {taskId: slugid.v4(), task}; }; - test('Resolve unscheduled task deadline', helper.runWithFakeTime(async () => { + test('Resolve unscheduled task deadline', testing.runWithFakeTime(async () => { const {taskId, task} = makeTask(); debug('### Define task'); @@ -74,9 +74,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f debug('### Validate task status'); const r2 = await helper.queue.status(taskId); assume(r2.status.state).equals('exception'); - }, mock)); + }, {mock})); - test('Resolve pending task deadline', helper.runWithFakeTime(async () => { + test('Resolve pending task deadline', testing.runWithFakeTime(async () => { const {taskId, task} = makeTask(); debug('### Creating task'); @@ -105,9 +105,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f debug('### Validate task status'); const r2 = await helper.queue.status(taskId); assume(r2.status.state).deep.equals('exception'); - }, mock)); + }, {mock})); - test('Resolve running task deadline', helper.runWithFakeTime(async () => { + test('Resolve running task deadline', testing.runWithFakeTime(async () => { const {taskId, task} = makeTask(); debug('### Creating task'); @@ -143,9 +143,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f debug('### Validate task status'); const r3 = await helper.queue.status(taskId); assume(r3.status.state).deep.equals('exception'); - }, mock)); + }, {mock})); - test('Resolve completed task by deadline (no change)', helper.runWithFakeTime(async () => { + test('Resolve completed task by deadline (no change)', testing.runWithFakeTime(async () => { const {taskId, task} = makeTask(); debug('### Creating task'); @@ -179,5 +179,5 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f debug('### Validate task status'); const r4 = await helper.queue.status(taskId); assume(r4.status).deep.equals(r3.status); - }, mock)); + }, {mock})); }); diff --git a/services/queue/test/dependency_test.js b/services/queue/test/dependency_test.js index b3c9ede7759..513766d2482 100644 --- a/services/queue/test/dependency_test.js +++ b/services/queue/test/dependency_test.js @@ -32,7 +32,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f }, }); - test('taskA <- taskB', helper.runWithFakeTime(async () => { + test('taskA <- taskB', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); @@ -136,9 +136,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f } await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('taskA <- taskB, taskC, taskD, taskE', helper.runWithFakeTime(async () => { + test('taskA <- taskB, taskC, taskD, taskE', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); let taskIdC = slugid.v4(); @@ -222,9 +222,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f assume(tids).contains(taskIdE); await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('taskA, taskB <- taskC && taskA <- taskD', helper.runWithFakeTime(async () => { + test('taskA, taskB <- taskC && taskA <- taskD', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); let taskIdC = slugid.v4(); @@ -291,9 +291,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f Infinity); await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('taskA <- taskA (self-dependency)', helper.runWithFakeTime(async () => { + test('taskA <- taskA (self-dependency)', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskA = _.defaults({ dependencies: [taskIdA], @@ -314,9 +314,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f workerGroup: 'my-worker-group-extended-extended', workerId: 'my-worker-extended-extended', }); - }, mock)); + }, {mock})); - test('taskA, taskB <- taskB (self-dependency)', helper.runWithFakeTime(async () => { + test('taskA, taskB <- taskB (self-dependency)', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); @@ -348,7 +348,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f let r3 = await helper.queue.status(taskIdB); assume(r3.status.state).equals('unscheduled'); helper.checkNoNextMessage('task-pending'); // because of the self-dep - }, mock)); + }, {mock})); test('taskX <- taskA (missing dependency)', async () => { let taskIdA = slugid.v4(); @@ -377,7 +377,7 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f ); }); - test('taskA <- taskB (reportFailed)', helper.runWithFakeTime(async () => { + test('taskA <- taskB (reportFailed)', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); @@ -409,9 +409,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f assume(r3.status.state).equals('unscheduled'); await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('taskA <- taskB (cancelTask)', helper.runWithFakeTime(async () => { + test('taskA <- taskB (cancelTask)', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); @@ -439,9 +439,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f assume(r3.status.state).equals('unscheduled'); await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('taskA <- taskB (reportFailed w. all-resolved)', helper.runWithFakeTime(async () => { + test('taskA <- taskB (reportFailed w. all-resolved)', testing.runWithFakeTime(async () => { let taskIdA = slugid.v4(); let taskIdB = slugid.v4(); @@ -479,9 +479,9 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f Infinity); await helper.stopPollingService(); - }, mock)); + }, {mock})); - test('expiration of relationships', helper.runWithFakeTime(async () => { + test('expiration of relationships', testing.runWithFakeTime(async () => { const taskIdA = slugid.v4(); const taskA = _.defaults({ dependencies: [taskIdA], @@ -533,6 +533,5 @@ helper.secrets.mockSuite(testing.suiteName(), ['taskcluster', 'aws', 'azure'], f const r10 = await TaskRequirement.load({taskId: taskIdB, requiredTaskId: taskIdB}, true); assert(r9, 'Expected TaskDependency'); assert(r10, 'Expected TaskRequirement'); - }, mock)); - + }, {mock})); }); diff --git a/services/queue/test/helper.js b/services/queue/test/helper.js index a90cff7ca7c..2e3bd6250ce 100644 --- a/services/queue/test/helper.js +++ b/services/queue/test/helper.js @@ -10,8 +10,6 @@ const mockAwsS3 = require('mock-aws-s3'); const nock = require('nock'); const FakeBlobStore = require('./fake_blob_store'); const {fakeauth, stickyLoader, Secrets, withEntity} = require('taskcluster-lib-testing'); -const zurvan = require('zurvan'); -const timers = require('timers'); const {FakeClient} = require('taskcluster-lib-pulse'); const helper = module.exports; @@ -65,58 +63,6 @@ setup(async function() { helper.monitor.reset(); }); -/** - * helper.runWithFakeTime(,