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
2026-08-24 03:14:12 -05:00 · 2026-01-19 13:14:46 -08:00
parent 988ab23b4a
commit 851d46b99f
5 changed files with 423 additions and 72 deletions
@@ -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/`
@@ -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": {
@@ -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();
  }
 };
@@ -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
+};
@@ -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);