From 851d46b99f4ff4549268219cb965b6219b02ce23 Mon Sep 17 00:00:00 2001 From: bewest <2492599-bewest@users.noreply.replit.com> Date: Sun, 18 Jan 2026 20:51:09 +0000 Subject: [PATCH] Add test instrumentation to detect and warn about flaky tests Introduce timing instrumentation to identify slow tests and setTimeout anti-patterns, refactor helper functions into a shared module, and update documentation and npm scripts. Replit-Commit-Author: Agent Replit-Commit-Session-Id: a10b5171-2266-431b-a8b1-bbc77898c289 Replit-Commit-Checkpoint-Type: intermediate_checkpoint Replit-Commit-Event-Id: fdf582ee-3e62-4543-a850-a72060814d7d Replit-Helium-Checkpoint-Created: true --- docs/test-specs/flaky-tests.md | 79 ++++++- package.json | 5 +- tests/hooks.js | 63 +++++- tests/lib/test-helpers.js | 277 +++++++++++++++++++++++++ tests/websocket.shape-handling.test.js | 71 +------ 5 files changed, 423 insertions(+), 72 deletions(-) create mode 100644 tests/lib/test-helpers.js diff --git a/docs/test-specs/flaky-tests.md b/docs/test-specs/flaky-tests.md index 68a36594..7ff87e3e 100644 --- a/docs/test-specs/flaky-tests.md +++ b/docs/test-specs/flaky-tests.md @@ -277,7 +277,16 @@ waitForConditionWithWarning({ }); ``` -The `waitForConditionWithWarning` helper is available in `tests/websocket.shape-handling.test.js` and can be extracted into a shared test utility if needed. +The `waitForConditionWithWarning` helper is now available in the shared test helper module: `tests/lib/test-helpers.js`. + +**Usage:** +```javascript +var testHelpers = require('./lib/test-helpers'); +var waitForConditionWithWarning = testHelpers.waitForConditionWithWarning; + +// For async/await tests: +var waitForConditionAsync = testHelpers.waitForConditionAsync; +``` **Benefits:** - Tests complete in ~50ms when operations are fast (vs. fixed 500ms delay) @@ -287,6 +296,72 @@ The `waitForConditionWithWarning` helper is available in `tests/websocket.shape- --- +## Timing Instrumentation + +The test suite includes built-in timing instrumentation to help identify slow tests and setTimeout anti-patterns. + +### Available Commands + +| Command | Description | +|---------|-------------| +| `npm run test:timing` | Run all tests with setTimeout anti-pattern detection enabled | +| `npm run test:timing:single` | Run single test file with timing warnings (use `TEST=filename`) | +| `npm run test:slow` | Run tests with slow test threshold set to 1000ms | + +### Environment Variables + +| Variable | Default | Description | +|----------|---------|-------------| +| `ENABLE_TIMING_WARNINGS` | false | Enable setTimeout anti-pattern warnings | +| `SLOW_TEST_THRESHOLD` | 2000 | Threshold (ms) for slow test warnings | + +### What the Instrumentation Detects + +1. **setTimeout Anti-Patterns**: Warns when tests use `setTimeout` with delays ≥100ms + - Output: `[SETTIMEOUT ANTI-PATTERN] Long delay of 500ms detected. This may cause flaky tests.` + +2. **Slow Tests**: Warns when individual tests take longer than the threshold + - Output: `[SLOW TEST] "test name" took 3500ms (threshold: 2000ms)` + +3. **Timing Summary**: After all tests complete, shows: + - List of slow tests with their durations + - Total setTimeout call count + - Average test duration + +### Example Output + +``` +[TIMING INSTRUMENTATION] Enabled - will warn on setTimeout anti-patterns +... +[SETTIMEOUT ANTI-PATTERN #42] Long delay of 200ms detected. This may cause flaky tests. +[SLOW TEST] "socket test" took 3500ms (threshold: 2000ms) +... + +[TIMING INSTRUMENTATION] Disabled - detected 84 setTimeout calls + +[SLOW TEST SUMMARY] 5 slow test(s) detected: + 1. WebSocket dbAdd test (3668ms) + 2. Socket event test (2742ms) + ... + +[TIMING STATS] Total: 50 tests, Avg: 1200ms, Slow: 5 +``` + +### Test Helper Module + +The `tests/lib/test-helpers.js` module provides additional utilities: + +| Function | Description | +|----------|-------------| +| `waitForConditionWithWarning(options)` | Callback-based polling with warnings | +| `waitForConditionAsync(options)` | Promise-based polling with warnings | +| `instrumentedSetTimeout(fn, delay, context)` | setTimeout wrapper with logging | +| `trackedDelay(ms, reason)` | Promise delay with timing logs | +| `startTestTimer(testName, warnThreshold, errThreshold)` | Manual test timing | +| `enableSetTimeoutWarnings(options)` | Enable global setTimeout monitoring | + +--- + ## Monitoring ### CI/CD Integration @@ -317,4 +392,6 @@ Monitor flaky test trends over time by: - [Testing Best Practices](https://github.com/goldbergyoni/javascript-testing-best-practices) - Main test runner: `scripts/flaky-test-runner.js` - Isolation harnesses: `scripts/flaky-harnesses/` +- Test helper module: `tests/lib/test-helpers.js` +- Test hooks (timing instrumentation): `tests/hooks.js` - Existing test specs: `docs/test-specs/` diff --git a/package.json b/package.json index 90e006c3..1594df66 100644 --- a/package.json +++ b/package.json @@ -47,7 +47,10 @@ "test:flaky:entries": "node scripts/flaky-harnesses/run-entries-isolation.js", "test:flaky:socket": "node scripts/flaky-harnesses/run-socket-isolation.js", "test:flaky:partial-failures": "node scripts/flaky-harnesses/run-partial-failures-isolation.js", - "test:flaky:isolate": "node scripts/flaky-harnesses/run-isolate.js" + "test:flaky:isolate": "node scripts/flaky-harnesses/run-isolate.js", + "test:timing": "ENABLE_TIMING_WARNINGS=true env-cmd -f ./my.test.env mocha --timeout 10000 --require ./tests/hooks.js --exit ./tests/*.test.js", + "test:timing:single": "ENABLE_TIMING_WARNINGS=true env-cmd -f ./my.test.env mocha --timeout 10000 --require ./tests/hooks.js --exit ./tests/$TEST.test.js", + "test:slow": "SLOW_TEST_THRESHOLD=1000 env-cmd -f ./my.test.env mocha --timeout 10000 --require ./tests/hooks.js --exit ./tests/*.test.js" }, "main": "lib/server/server.js", "nodemonConfig": { diff --git a/tests/hooks.js b/tests/hooks.js index 7f847f77..baf6c0bf 100644 --- a/tests/hooks.js +++ b/tests/hooks.js @@ -1,5 +1,12 @@ 'use strict;' +var testHelpers = require('./lib/test-helpers'); + +var slowTestThreshold = parseInt(process.env.SLOW_TEST_THRESHOLD, 10) || 2000; +var enableTimingWarnings = process.env.ENABLE_TIMING_WARNINGS === 'true'; +var restoreSetTimeout = null; +var testTimings = []; + function clearRequireCache () { Object.keys(require.cache).forEach(function(key) { delete require.cache[key]; @@ -7,8 +14,62 @@ function clearRequireCache () { } exports.mochaHooks = { - afterEach (done) { + beforeAll(done) { + if (enableTimingWarnings) { + console.log('[TIMING INSTRUMENTATION] Enabled - will warn on setTimeout anti-patterns'); + restoreSetTimeout = testHelpers.enableSetTimeoutWarnings({ + warnOnLongDelays: true, + longDelayThreshold: 100 + }); + } + done(); + }, + + beforeEach(done) { + this.testStartTime = Date.now(); + done(); + }, + + afterEach(done) { + if (this.testStartTime) { + var elapsed = Date.now() - this.testStartTime; + var testTitle = this.currentTest ? this.currentTest.fullTitle() : 'unknown'; + + testTimings.push({ + title: testTitle, + duration: elapsed, + slow: elapsed > slowTestThreshold + }); + + if (elapsed > slowTestThreshold) { + console.warn('[SLOW TEST] "' + testTitle + '" took ' + elapsed + 'ms (threshold: ' + slowTestThreshold + 'ms)'); + } + } + clearRequireCache(); + done(); + }, + + afterAll(done) { + if (restoreSetTimeout) { + var setTimeoutCallCount = restoreSetTimeout(); + console.log('[TIMING INSTRUMENTATION] Disabled - detected ' + setTimeoutCallCount + ' setTimeout calls'); + } + + if (testTimings.length > 0) { + var slowTests = testTimings.filter(function(t) { return t.slow; }); + if (slowTests.length > 0) { + console.log('\n[SLOW TEST SUMMARY] ' + slowTests.length + ' slow test(s) detected:'); + slowTests.forEach(function(t, i) { + console.log(' ' + (i + 1) + '. ' + t.title + ' (' + t.duration + 'ms)'); + }); + } + + var totalTime = testTimings.reduce(function(sum, t) { return sum + t.duration; }, 0); + var avgTime = Math.round(totalTime / testTimings.length); + console.log('\n[TIMING STATS] Total: ' + testTimings.length + ' tests, Avg: ' + avgTime + 'ms, Slow: ' + slowTests.length); + } + done(); } }; diff --git a/tests/lib/test-helpers.js b/tests/lib/test-helpers.js new file mode 100644 index 00000000..0fed7a9c --- /dev/null +++ b/tests/lib/test-helpers.js @@ -0,0 +1,277 @@ +'use strict'; + +/** + * Shared test helper utilities for the Nightscout test suite. + * + * This module provides utilities for: + * - Polling-based waits with warning timeouts (instead of arbitrary setTimeout) + * - Detecting slow operations in tests + * - Reducing flaky test issues caused by timing + */ + +/** + * Helper function to wait for a condition with warning timeout. + * Instead of using arbitrary setTimeout delays, this function: + * 1. Polls for a condition to be true + * 2. Warns if the operation is taking longer than expected + * 3. Fails hard only after a maximum timeout + * + * This approach: + * - Completes tests as fast as possible (polls immediately and frequently) + * - Surfaces slow operations (logs warnings when operations take longer than expected) + * - Has a hard timeout (fails cleanly if the expected state is never reached) + * + * @param {Object} options + * @param {Function} options.condition - Function that checks if expected state is reached, receives callback(err, result) + * @param {Function} options.assertion - Function to run assertions on result + * @param {Function} options.done - Mocha done callback + * @param {number} [options.warningThreshold=200] - ms before warning is logged + * @param {number} [options.pollInterval=50] - ms between polls + * @param {number} [options.maxTimeout=5000] - ms before hard failure + * @param {string} [options.operationName='Operation'] - Name for logging + * + * @example + * waitForConditionWithWarning({ + * condition: function(cb) { + * ctx.treatments.list({}, cb); + * }, + * assertion: function(list) { + * list.length.should.be.greaterThanOrEqual(3); + * }, + * done: done, + * operationName: 'verify treatments created', + * warningThreshold: 200, // Warn if taking >200ms + * maxTimeout: 5000 // Fail if >5s + * }); + */ +function waitForConditionWithWarning(options) { + var startTime = Date.now(); + var warningIssued = false; + var warningTimer = null; + + var warningThreshold = options.warningThreshold || 200; + var pollInterval = options.pollInterval || 50; + var maxTimeout = options.maxTimeout || 5000; + var operationName = options.operationName || 'Operation'; + + warningTimer = setTimeout(function() { + warningIssued = true; + console.warn('[SLOW TEST WARNING] ' + operationName + ' taking longer than ' + warningThreshold + 'ms'); + }, warningThreshold); + + function poll() { + var elapsed = Date.now() - startTime; + + if (elapsed > maxTimeout) { + clearTimeout(warningTimer); + options.done(new Error(operationName + ' timed out after ' + maxTimeout + 'ms')); + return; + } + + options.condition(function(err, result) { + if (err) { + clearTimeout(warningTimer); + options.done(err); + return; + } + + try { + options.assertion(result); + clearTimeout(warningTimer); + + if (warningIssued) { + console.log('[SLOW TEST INFO] ' + operationName + ' completed after ' + elapsed + 'ms'); + } + + options.done(); + } catch (assertionError) { + setTimeout(poll, pollInterval); + } + }); + } + + poll(); +} + +/** + * Promise-based version of waitForConditionWithWarning. + * Useful for async/await test patterns. + * + * @param {Object} options + * @param {Function} options.condition - Async function that returns the value to check + * @param {Function} options.assertion - Function to run assertions on result (throws if fails) + * @param {number} [options.warningThreshold=200] - ms before warning is logged + * @param {number} [options.pollInterval=50] - ms between polls + * @param {number} [options.maxTimeout=5000] - ms before hard failure + * @param {string} [options.operationName='Operation'] - Name for logging + * @returns {Promise} Resolves when condition is met, rejects on timeout + * + * @example + * await waitForConditionAsync({ + * condition: async () => await fetchTreatments(), + * assertion: (list) => { if (list.length < 3) throw new Error('Not enough'); }, + * operationName: 'wait for treatments', + * warningThreshold: 200, + * maxTimeout: 5000 + * }); + */ +function waitForConditionAsync(options) { + return new Promise((resolve, reject) => { + var startTime = Date.now(); + var warningIssued = false; + var warningTimer = null; + + var warningThreshold = options.warningThreshold || 200; + var pollInterval = options.pollInterval || 50; + var maxTimeout = options.maxTimeout || 5000; + var operationName = options.operationName || 'Operation'; + + warningTimer = setTimeout(function() { + warningIssued = true; + console.warn('[SLOW TEST WARNING] ' + operationName + ' taking longer than ' + warningThreshold + 'ms'); + }, warningThreshold); + + async function poll() { + var elapsed = Date.now() - startTime; + + if (elapsed > maxTimeout) { + clearTimeout(warningTimer); + reject(new Error(operationName + ' timed out after ' + maxTimeout + 'ms')); + return; + } + + try { + var result = await options.condition(); + options.assertion(result); + clearTimeout(warningTimer); + + if (warningIssued) { + console.log('[SLOW TEST INFO] ' + operationName + ' completed after ' + elapsed + 'ms'); + } + + resolve(result); + } catch (assertionError) { + setTimeout(poll, pollInterval); + } + } + + poll(); + }); +} + +/** + * Wraps setTimeout usage with timing instrumentation. + * Logs a warning if the delay is suspiciously long (potential flaky test source). + * + * @param {Function} fn - Function to execute after delay + * @param {number} delay - Delay in milliseconds + * @param {string} [context=''] - Optional context for logging + * @returns {number} Timer ID + */ +function instrumentedSetTimeout(fn, delay, context) { + var SUSPICIOUS_DELAY_THRESHOLD = 100; + + if (delay >= SUSPICIOUS_DELAY_THRESHOLD) { + console.warn('[TIMING WARNING] setTimeout with ' + delay + 'ms delay detected' + + (context ? ' in ' + context : '') + + '. Consider using waitForConditionWithWarning instead.'); + } + + return setTimeout(fn, delay); +} + +/** + * Creates a tracked delay that logs timing information. + * Useful for debugging slow tests or understanding where time is spent. + * + * @param {number} ms - Delay in milliseconds + * @param {string} [reason='unknown'] - Reason for the delay + * @returns {Promise} Resolves after delay + */ +function trackedDelay(ms, reason) { + var startTime = Date.now(); + console.log('[DELAY START] Waiting ' + ms + 'ms for: ' + (reason || 'unknown')); + + return new Promise(resolve => { + setTimeout(() => { + var actual = Date.now() - startTime; + if (Math.abs(actual - ms) > 20) { + console.warn('[DELAY WARNING] Expected ' + ms + 'ms but actual was ' + actual + 'ms for: ' + (reason || 'unknown')); + } + console.log('[DELAY END] Completed wait of ' + actual + 'ms for: ' + (reason || 'unknown')); + resolve(); + }, ms); + }); +} + +/** + * Monitors test execution time and warns if a test is taking too long. + * Call at the start of a test and it returns a function to call at the end. + * + * @param {string} testName - Name of the test + * @param {number} [warningThreshold=1000] - ms before warning + * @param {number} [errorThreshold=5000] - ms before error-level warning + * @returns {Function} Call this at the end of the test + */ +function startTestTimer(testName, warningThreshold, errorThreshold) { + var startTime = Date.now(); + warningThreshold = warningThreshold || 1000; + errorThreshold = errorThreshold || 5000; + + return function endTimer() { + var elapsed = Date.now() - startTime; + + if (elapsed > errorThreshold) { + console.error('[SLOW TEST ERROR] "' + testName + '" took ' + elapsed + 'ms (threshold: ' + errorThreshold + 'ms)'); + } else if (elapsed > warningThreshold) { + console.warn('[SLOW TEST WARNING] "' + testName + '" took ' + elapsed + 'ms (threshold: ' + warningThreshold + 'ms)'); + } + + return elapsed; + }; +} + +/** + * Detects setTimeout anti-patterns in test code. + * This is a development-time helper to find potential flaky test sources. + * + * @param {Object} options + * @param {boolean} [options.warnOnLongDelays=true] - Warn on delays > 100ms + * @param {boolean} [options.warnOnHardcodedDelays=false] - Warn on any hardcoded delay + * @param {number} [options.longDelayThreshold=100] - What counts as a "long" delay + */ +function enableSetTimeoutWarnings(options) { + options = options || {}; + var warnOnLongDelays = options.warnOnLongDelays !== false; + var warnOnHardcodedDelays = options.warnOnHardcodedDelays || false; + var longDelayThreshold = options.longDelayThreshold || 100; + + var originalSetTimeout = global.setTimeout; + var callCount = 0; + + global.setTimeout = function(fn, delay) { + callCount++; + + if (warnOnHardcodedDelays && typeof delay === 'number' && delay > 0) { + console.warn('[SETTIMEOUT ANTI-PATTERN #' + callCount + '] Hardcoded delay of ' + delay + 'ms detected. Consider using polling patterns.'); + } else if (warnOnLongDelays && delay >= longDelayThreshold) { + console.warn('[SETTIMEOUT ANTI-PATTERN #' + callCount + '] Long delay of ' + delay + 'ms detected. This may cause flaky tests.'); + } + + return originalSetTimeout.apply(global, arguments); + }; + + return function restore() { + global.setTimeout = originalSetTimeout; + return callCount; + }; +} + +module.exports = { + waitForConditionWithWarning: waitForConditionWithWarning, + waitForConditionAsync: waitForConditionAsync, + instrumentedSetTimeout: instrumentedSetTimeout, + trackedDelay: trackedDelay, + startTestTimer: startTestTimer, + enableSetTimeoutWarnings: enableSetTimeoutWarnings +}; diff --git a/tests/websocket.shape-handling.test.js b/tests/websocket.shape-handling.test.js index 943bf58e..700b9e4f 100644 --- a/tests/websocket.shape-handling.test.js +++ b/tests/websocket.shape-handling.test.js @@ -2,75 +2,8 @@ var should = require('should'); var language = require('../lib/language')(); - -/** - * Helper function to wait for a condition with warning timeout. - * Instead of using arbitrary setTimeout delays, this function: - * 1. Polls for a condition to be true - * 2. Warns if the operation is taking longer than expected - * 3. Fails hard only after a maximum timeout - * - * @param {Object} options - * @param {Function} options.condition - Function that checks if expected state is reached, receives callback(err, result) - * @param {Function} options.assertion - Function to run assertions on result - * @param {Function} options.done - Mocha done callback - * @param {number} [options.warningThreshold=200] - ms before warning is logged - * @param {number} [options.pollInterval=50] - ms between polls - * @param {number} [options.maxTimeout=5000] - ms before hard failure - * @param {string} [options.operationName='Operation'] - Name for logging - */ -function waitForConditionWithWarning(options) { - var startTime = Date.now(); - var warningIssued = false; - var warningTimer = null; - - var warningThreshold = options.warningThreshold || 200; - var pollInterval = options.pollInterval || 50; - var maxTimeout = options.maxTimeout || 5000; - var operationName = options.operationName || 'Operation'; - - // Set up warning timer - warningTimer = setTimeout(function() { - warningIssued = true; - console.warn('[SLOW TEST WARNING] ' + operationName + ' taking longer than ' + warningThreshold + 'ms'); - }, warningThreshold); - - function poll() { - var elapsed = Date.now() - startTime; - - if (elapsed > maxTimeout) { - clearTimeout(warningTimer); - options.done(new Error(operationName + ' timed out after ' + maxTimeout + 'ms')); - return; - } - - options.condition(function(err, result) { - if (err) { - clearTimeout(warningTimer); - options.done(err); - return; - } - - try { - // Try to run the assertion - if it passes, we're done - options.assertion(result); - clearTimeout(warningTimer); - - if (warningIssued) { - console.log('[SLOW TEST INFO] ' + operationName + ' completed after ' + elapsed + 'ms'); - } - - options.done(); - } catch (assertionError) { - // Assertion failed - poll again if we have time - setTimeout(poll, pollInterval); - } - }); - } - - // Start polling immediately - poll(); -} +var testHelpers = require('./lib/test-helpers'); +var waitForConditionWithWarning = testHelpers.waitForConditionWithWarning; describe('WebSocket Shape Handling - dbAdd Single vs Array Input', function () { this.timeout(15000);