From 0ca31da829f481ff0099af910c701a740dd48244 Mon Sep 17 00:00:00 2001 From: xxshubhamxx Date: Wed, 10 Jun 2026 01:29:24 +0530 Subject: [PATCH 1/2] fix(observability): correlate cucumber finishes by unique attempt id and sweep open entities at teardown Key the cucumber _tests map by the unique testCaseStartedId instead of the non-unique testCaseId, so reruns/retries/parallel-interleaved attempts of the same scenario no longer clobber each other and every attempt emits its own TestRunFinished. Harden TestCaseFinished to reconstruct a minimal payload and still emit a terminal finish when the map entry is missing. Add a teardown sweep (run before queue drain / build stop in both the main and worker teardown paths) that emits terminal failed finishes for any scenario, hook, or native run left open, so nothing is left running to be reaped as a timeout. Make getCucumberHookType always return a known hook_type, and let TestMap.getUUID fall back to the most recent unfinished run. Co-Authored-By: Claude Opus 4.8 --- nightwatch/globals.js | 116 ++++++++++++++---- src/testObservability.js | 96 ++++++++++++++- src/utils/testMap.js | 30 ++++- .../test-observability/cucumberOrphanFix.js | 114 +++++++++++++++++ .../test-observability/orphanSweepUnits.js | 114 +++++++++++++++++ 5 files changed, 440 insertions(+), 30 deletions(-) create mode 100644 test/src/test-observability/cucumberOrphanFix.js create mode 100644 test/src/test-observability/orphanSweepUnits.js diff --git a/nightwatch/globals.js b/nightwatch/globals.js index 16f029b..9e4aa53 100644 --- a/nightwatch/globals.js +++ b/nightwatch/globals.js @@ -28,8 +28,9 @@ let testEventPromises = []; eventHelper.eventEmitter.on(EVENTS.LOG_INIT, (loggingData) => { const testCaseStartedId = loggingData.message.replace('TEST-OBSERVABILITY-PID-TESTCASE-MAPPING-', '').slice(1, -1); - const testCaseId = _testCasesData[testCaseStartedId]?.testCaseId; - currentTestUUID = _tests[testCaseId]?.uuid; + // _tests is keyed by the unique per-attempt testCaseStartedId so reruns and + // retries of the same scenario do not clobber each other's uuid. + currentTestUUID = _tests[testCaseStartedId]?.uuid; }); eventHelper.eventEmitter.on(EVENTS.LOG, (loggingData) => { @@ -115,8 +116,7 @@ module.exports = { } if (data.eventType === EVENTS.LOG_INIT) { const testCaseStartedId = data.loggingData.message.replace('TEST-OBSERVABILITY-PID-TESTCASE-MAPPING-', '').slice(1, -1); - const testCaseId = _testCasesData[testCaseStartedId]?.testCaseId; - const uuid = _tests[testCaseId]?.uuid; + const uuid = _tests[testCaseStartedId]?.uuid; await worker.process.send({testCaseStartedId, uuid}); } }); @@ -139,7 +139,10 @@ module.exports = { description: featureData.description }; } - _tests[testCaseId] = testMetaData; + // Key by the unique per-attempt id (envelope.id === testCaseStartedId) + // instead of the non-unique testCaseId, so a rerun/retry/parallel second + // attempt of the same scenario does not overwrite the first one's entry. + _tests[args.envelope.id] = testMetaData; await testObservability.sendTestRunEventForCucumber(reportData, gherkinDocument, pickleData, 'TestRunStarted', testMetaData, args); } catch (error) { CrashReporter.uploadCrashReport(error.message, error.stack); @@ -153,18 +156,33 @@ module.exports = { } try { const reportData = args.report; - const testCaseId = _testCasesData[args.envelope.testCaseStartedId].testCaseId; + const uniqueId = args.envelope.testCaseStartedId; + const testCaseId = _testCasesData[uniqueId].testCaseId; const pickleId = reportData.testCases.find((testCase) => testCase.id === testCaseId).pickleId; const pickleData = reportData.pickle.find((pickle) => pickle.id === pickleId); const gherkinDocument = reportData?.gherkinDocument.find((document) => document.uri === pickleData.uri); - const testMetaData = _tests[testCaseId]; - if (testMetaData) { - delete _tests[testCaseId]; - testMetaData.finishedAt = new Date().toISOString(); - CustomTagManager.drainPendingTestTags(testMetaData.uuid); - await testObservability.sendTestRunEventForCucumber(reportData, gherkinDocument, pickleData, 'TestRunFinished', testMetaData, args); + // Look up by the unique per-attempt id. If the entry is missing (a duplicate + // or out-of-order finish, or a start that was never recorded) reconstruct a + // minimal payload so a terminal finish is still emitted and the run can never + // be left open to be flipped to a timeout by the reaper. + let testMetaData = _tests[uniqueId]; + if (!testMetaData) { + testMetaData = { + uuid: uuidv4(), + startedAt: new Date().toISOString(), + scenario: {name: pickleData?.name}, + feature: (gherkinDocument && gherkinDocument.feature) ? { + path: gherkinDocument.uri, + name: gherkinDocument.feature.name, + description: gherkinDocument.feature.description + } : undefined + }; } + delete _tests[uniqueId]; + testMetaData.finishedAt = new Date().toISOString(); + CustomTagManager.drainPendingTestTags(testMetaData.uuid); + await testObservability.sendTestRunEventForCucumber(reportData, gherkinDocument, pickleData, 'TestRunFinished', testMetaData, args); } catch (error) { CrashReporter.uploadCrashReport(error.message, error.stack); Logger.error(`Something went wrong in processing report file for test reporting and analytics - ${error.message} with stacktrace ${error.stack}`); @@ -177,17 +195,18 @@ module.exports = { } try { const reportData = args.report; - const testCaseId = _testCasesData[args.envelope.testCaseStartedId].testCaseId; + const uniqueId = args.envelope.testCaseStartedId; + const testCaseId = _testCasesData[uniqueId].testCaseId; const pickleId = reportData.testCases.find((testCase) => testCase.id === testCaseId).pickleId; const pickleData = reportData.pickle.find((pickle) => pickle.id === pickleId); const testSteps = reportData.testCases.find((testCase) => testCase.id === testCaseId).testSteps; const testStepId = reportData.testStepStarted[args.envelope.testCaseStartedId].testStepId; - await testObservability.sendHook(args, 'HookRunStarted', testSteps, testStepId, _tests[testCaseId]); + await testObservability.sendHook(args, 'HookRunStarted', testSteps, testStepId, _tests[uniqueId]); const pickleStepId = testSteps.find((testStep) => testStep.id === testStepId).pickleStepId; - if (pickleStepId && _tests[testCaseId]?.['testStepId'] !== testStepId) { - _tests[testCaseId]['testStepId'] = testStepId; + if (pickleStepId && _tests[uniqueId]?.['testStepId'] !== testStepId) { + _tests[uniqueId]['testStepId'] = testStepId; const pickleStepData = pickleData.steps.find((pickle) => pickle.id === pickleStepId); - const testMetaData = _tests[testCaseId] || {steps: []}; + const testMetaData = _tests[uniqueId] || {steps: []}; if (testMetaData && !testMetaData.steps) { testMetaData.steps = []; } @@ -196,7 +215,7 @@ module.exports = { text: pickleStepData.text, started_at: new Date().toISOString() }); - _tests[testCaseId] = testMetaData; + _tests[uniqueId] = testMetaData; } } catch (error) { CrashReporter.uploadCrashReport(error.message, error.stack); @@ -211,13 +230,14 @@ module.exports = { try { const reportData = args.report; helper.storeSessionsData(args); - const testCaseId = _testCasesData[args.envelope.testCaseStartedId].testCaseId; + const uniqueId = args.envelope.testCaseStartedId; + const testCaseId = _testCasesData[uniqueId].testCaseId; const testStepFinished = reportData.testStepFinished[args.envelope.testCaseStartedId]; const pickleId = reportData.testCases.find((testCase) => testCase.id === testCaseId).pickleId; const pickleData = reportData.pickle.find((pickle) => pickle.id === pickleId); const testSteps = reportData.testCases.find((testCase) => testCase.id === testCaseId).testSteps; const testStepId = reportData.testStepFinished[args.envelope.testCaseStartedId].testStepId; - await testObservability.sendHook(args, 'HookRunFinished', testSteps, testStepId, _tests[testCaseId]); + await testObservability.sendHook(args, 'HookRunFinished', testSteps, testStepId, _tests[uniqueId]); const pickleStepId = testSteps.find((testStep) => testStep.id === testStepId).pickleStepId; let failure; let failureType; @@ -226,9 +246,9 @@ module.exports = { failureType = (testStepFinished.testStepResult?.exception === undefined) ? 'UnhandledError' : testStepFinished.testStepResult?.message; } - if (pickleStepId && _tests[testCaseId]['testStepId']) { + if (pickleStepId && _tests[uniqueId]['testStepId']) { const pickleStepData = pickleData.steps.find((pickle) => pickle.id === pickleStepId); - const testMetaData = _tests[testCaseId] || {steps: []}; + const testMetaData = _tests[uniqueId] || {steps: []}; if (!testMetaData.steps) { testMetaData.steps = [{ id: pickleStepData.id, @@ -250,8 +270,8 @@ module.exports = { } }); } - _tests[testCaseId] = testMetaData; - delete _tests[testCaseId]['testStepId']; + _tests[uniqueId] = testMetaData; + delete _tests[uniqueId]['testStepId']; if (testStepFinished.httpOutput && testStepFinished.httpOutput.length > 0) { for (const [index, output] of testStepFinished.httpOutput.entries()) { if (index % 2 === 0) { @@ -561,6 +581,10 @@ module.exports = { Logger.debug(`Error aggregating build-level tags from workers: ${err}`); } + // Sweep any still-open scenarios/hooks/native runs to terminal finishes + // BEFORE the queue is drained and the build is stopped, so they flush in + // this run instead of being left open for the reaper to time out. + await performTeardownSweep(); await testObservability.stopBuildUpstream(); if (process.env.BROWSERSTACK_TESTHUB_UUID) { Logger.info(`\nVisit https://automation.browserstack.com/builds/${process.env.BROWSERSTACK_TESTHUB_UUID} to view build report, insights, and many more debugging information all at one place!\n`); @@ -659,6 +683,9 @@ module.exports = { Logger.debug(`Error sending build-level tags from worker: ${err}`); } + // Sweep still-open entities to terminal finishes before the worker drains + // its request queue, so synthetic finishes are flushed for this worker. + await performTeardownSweep(); await helper.shutDownRequestHandler(); if (testEventPromises.length > 0) { await Promise.all(testEventPromises); @@ -667,6 +694,47 @@ module.exports = { } }; +const performTeardownSweep = async () => { + try { + // Cucumber: a scenario still present in _tests never received its + // TestCaseFinished. Emit a terminal finish, then drop the entry (idempotent). + for (const uniqueId of Object.keys(_tests)) { + const testMetaData = _tests[uniqueId]; + delete _tests[uniqueId]; + try { + await testObservability.sendSyntheticTestRunFinishedForCucumber(testMetaData); + } catch (err) { + Logger.debug(`Error sweeping open scenario ${uniqueId}: ${err && err.message}`); + } + } + + // Cucumber: hooks that started but never finished. + try { + await testObservability.sweepOpenHooks(); + } catch (err) { + Logger.debug(`Error sweeping open hooks: ${err && err.message}`); + } + + // Native: test runs still marked unfinished in the TestMap. + try { + const openRuns = TestMap.getOpenRuns(); + for (const run of openRuns) { + try { + await testObservability.sendSyntheticTestRunFinished(run.uuid, run); + } catch (err) { + Logger.debug(`Error sweeping open run ${run.uuid}: ${err && err.message}`); + } + TestMap.markTestFinished(run.uuid); + } + } catch (err) { + Logger.debug(`Error sweeping open native runs: ${err && err.message}`); + } + } catch (error) { + CrashReporter.uploadCrashReport(error.message, error.stack); + } +}; +module.exports.performTeardownSweep = performTeardownSweep; + const cucumberPatcher = () => { try { const Coordinator = helper.requireModule('@cucumber/cucumber/lib/runtime/parallel/coordinator.js'); diff --git a/src/testObservability.js b/src/testObservability.js index 7dcef52..5627703 100644 --- a/src/testObservability.js +++ b/src/testObservability.js @@ -871,17 +871,107 @@ class TestObservability { }; } - // BEFORE_ALL and AFTER_ALL are not implemented for TO + // Classify the cucumber hook so an emitted hook never carries a null hook_type. + // A hook found alongside scenario steps is a per-scenario hook (BEFORE_EACH / + // AFTER_EACH depending on whether any scenario step preceded it). A hook not + // found among the scenario steps is a suite-level hook, classified as + // BEFORE_ALL / AFTER_ALL by the same step-seen heuristic. getCucumberHookType(testSteps, hookData) { let isStep = false; - for (const step of testSteps) { + for (const step of testSteps || []) { if (step.pickleStepId) { isStep = true; } - if (hookData.id === step.id) { + if (hookData && hookData.id === step.id) { return (isStep) ? 'AFTER_EACH' : 'BEFORE_EACH'; } } + + return isStep ? 'AFTER_ALL' : 'BEFORE_ALL'; + } + + // Emit a terminal TestRunFinished for a cucumber scenario left open at teardown. + // Builds a minimal payload from the stored metadata and marks it failed so the + // backend treats the run as terminal and clears the running state. + async sendSyntheticTestRunFinishedForCucumber(testMetaData) { + const {feature, scenario, steps, uuid, startedAt} = testMetaData || {}; + if (!uuid) { + return; + } + const featurePath = feature && feature.path; + const testData = { + uuid: uuid, + started_at: startedAt, + finished_at: new Date().toISOString(), + type: 'test', + body: { + lang: 'nightwatch', + code: null + }, + name: scenario && scenario.name, + scope: scenario && scenario.name, + scopes: [feature && feature.name ? feature.name : ''], + identifier: scenario && scenario.name, + file_name: featurePath ? path.relative(process.cwd(), featurePath) : undefined, + location: featurePath ? path.relative(process.cwd(), featurePath) : undefined, + framework: 'nightwatch', + result: 'failed', + meta: { + feature: feature, + scenario: scenario, + steps: steps + } + }; + await helper.uploadEventData({event_type: 'TestRunFinished', test_run: testData}); + } + + // Emit a terminal TestRunFinished for a native (non-cucumber) run left open at + // teardown, built from the TestMap run info and marked failed so the backend + // clears the running state instead of letting the reaper time it out. + async sendSyntheticTestRunFinished(uuid, runInfo = {}) { + if (!uuid) { + return; + } + const identifier = runInfo.identifier || ''; + const separatorIndex = identifier.indexOf('::'); + const moduleName = separatorIndex === -1 ? identifier : identifier.slice(0, separatorIndex); + const testName = separatorIndex === -1 ? identifier : identifier.slice(separatorIndex + 2); + const testData = { + uuid: uuid, + type: 'test', + name: testName || 'unknown', + body: { + lang: 'javascript', + code: null + }, + scope: identifier, + scopes: [moduleName || ''], + started_at: runInfo.startedAt, + finished_at: new Date().toISOString(), + result: 'failed', + framework: 'nightwatch' + }; + await helper.uploadEventData({event_type: 'TestRunFinished', test_run: testData}); + } + + // Emit a terminal HookRunFinished for every hook that started but never finished + // (no finished_at). Idempotent: a finished hook is skipped, so re-running the + // sweep never double-finishes a hook. + async sweepOpenHooks() { + for (const testCaseStartedId of Object.keys(hooksMap)) { + const hookList = hooksMap[testCaseStartedId]; + if (!(hookList instanceof Array)) { + continue; + } + for (const hookEventData of hookList) { + if (hookEventData.finished_at) { + continue; + } + hookEventData.result = 'failed'; + hookEventData.finished_at = new Date().toISOString(); + await helper.uploadEventData({event_type: 'HookRunFinished', hook_run: hookEventData}); + } + } } async appendTestItemLog (log, testUuid) { diff --git a/src/utils/testMap.js b/src/utils/testMap.js index 1c95c0e..a528315 100644 --- a/src/utils/testMap.js +++ b/src/utils/testMap.js @@ -68,11 +68,35 @@ class TestMap { if (test) { const testIdentifier = typeof test === 'string' ? test : this.generateTestIdentifier(test); const testData = sharedTestMap.get(testIdentifier); - - return testData ? testData.currentUuid : null; + if (testData) { + return testData.currentUuid; + } } - return null; + // Fall back to the most recently started run that has not finished yet, so a + // finish event whose identifier cannot be resolved still lands on an open run + // instead of being dropped (which would otherwise leave that run to be reaped). + let fallbackUuid = null; + for (const [uuid, run] of activeTestRuns) { + if (!run.hasFinished) { + fallbackUuid = uuid; + } + } + + return fallbackUuid; + } + + // Returns every run that started but was never marked finished, joined with its + // stored metadata, so the teardown sweep can emit a terminal finish for each. + static getOpenRuns() { + const openRuns = []; + for (const [uuid, run] of activeTestRuns) { + if (!run.hasFinished) { + openRuns.push({uuid, ...run}); + } + } + + return openRuns; } static markTestFinished(uuid) { diff --git a/test/src/test-observability/cucumberOrphanFix.js b/test/src/test-observability/cucumberOrphanFix.js new file mode 100644 index 0000000..77b4d28 --- /dev/null +++ b/test/src/test-observability/cucumberOrphanFix.js @@ -0,0 +1,114 @@ +const assert = require('assert'); +const sinon = require('sinon'); + +const helper = require('../../../src/utils/helper'); +const TestObservability = require('../../../src/testObservability'); + +// Coverage for the cucumber orphan/timeout fix. +// +// The cucumber _tests map used to be keyed by the non-unique testCaseId. On +// reruns/retries/parallel interleaving, a second TestCaseStarted overwrote the +// first attempt's entry, so the first TestCaseFinished deleted it and the later +// attempt found no entry -> no TestRunFinished was emitted, leaving the run open +// to be reaped as a timeout. The map is now keyed by the unique testCaseStartedId, +// and a teardown sweep finishes anything still open. +const GLOBALS_PATH = require.resolve('../../../nightwatch/globals.js'); + +function loadGlobals() { + delete require.cache[GLOBALS_PATH]; + + return require('../../../nightwatch/globals.js'); +} + +function makeBroadcaster() { + const handlers = {}; + + return { + on(name, fn) { + handlers[name] = fn; + }, + handlers + }; +} + +function buildReport() { + return { + testCaseStarted: { + 'tcs-1': {testCaseId: 'tc-1'}, + 'tcs-2': {testCaseId: 'tc-1'} + }, + testCases: [{id: 'tc-1', pickleId: 'p-1', testSteps: []}], + pickle: [{id: 'p-1', name: 'Scenario A', uri: 'features/a.feature', tags: [], steps: []}], + gherkinDocument: [{uri: 'features/a.feature', feature: {name: 'Feature A', description: ''}}] + }; +} + +describe('globals - cucumber rerun correlation and teardown sweep', function () { + let sandbox; + let cucumberCalls; + let uploads; + + beforeEach(function () { + sandbox = sinon.createSandbox(); + cucumberCalls = []; + uploads = []; + + sandbox.stub(helper, 'isTestObservabilitySession').returns(true); + sandbox.stub(helper, 'isTestHubBuild').returns(true); + sandbox.stub(TestObservability.prototype, 'sendTestRunEventForCucumber') + .callsFake(async (reportData, gherkinDocument, pickleData, eventType, testMetaData) => { + cucumberCalls.push({eventType, uuid: testMetaData && testMetaData.uuid}); + }); + sandbox.stub(helper, 'uploadEventData').callsFake(async (payload) => { + uploads.push(payload); + }); + }); + + afterEach(function () { + sandbox.restore(); + }); + + it('emits a TestRunFinished for two attempts sharing a testCaseId but differing by testCaseStartedId', async function () { + const globals = loadGlobals(); + const broadcaster = makeBroadcaster(); + globals.registerEventHandlers(broadcaster); + const report = buildReport(); + + await broadcaster.handlers['TestCaseStarted']({envelope: {id: 'tcs-1', testCaseId: 'tc-1'}, report}); + await broadcaster.handlers['TestCaseStarted']({envelope: {id: 'tcs-2', testCaseId: 'tc-1'}, report}); + await broadcaster.handlers['TestCaseFinished']({envelope: {testCaseStartedId: 'tcs-1'}, report}); + await broadcaster.handlers['TestCaseFinished']({envelope: {testCaseStartedId: 'tcs-2'}, report}); + + const started = cucumberCalls.filter((c) => c.eventType === 'TestRunStarted'); + const finished = cucumberCalls.filter((c) => c.eventType === 'TestRunFinished'); + + assert.strictEqual(started.length, 2, 'both attempts should start'); + assert.strictEqual(finished.length, 2, 'both attempts should finish (no orphan)'); + + const startUuids = started.map((c) => c.uuid).sort(); + const finishUuids = finished.map((c) => c.uuid).sort(); + assert.notStrictEqual(startUuids[0], startUuids[1], 'attempts have distinct uuids'); + assert.deepStrictEqual(finishUuids, startUuids, 'both started uuids are finished'); + }); + + it('sweep emits a terminal failed TestRunFinished for a scenario left open in _tests, idempotently', async function () { + const globals = loadGlobals(); + const broadcaster = makeBroadcaster(); + globals.registerEventHandlers(broadcaster); + const report = buildReport(); + + await broadcaster.handlers['TestCaseStarted']({envelope: {id: 'tcs-1', testCaseId: 'tc-1'}, report}); + const startCall = cucumberCalls.find((c) => c.eventType === 'TestRunStarted'); + const openUuid = startCall.uuid; + + await globals.performTeardownSweep(); + + const swept = uploads.filter((u) => u.event_type === 'TestRunFinished' && u.test_run && u.test_run.uuid === openUuid); + assert.strictEqual(swept.length, 1, 'open scenario is finished exactly once by the sweep'); + assert.strictEqual(swept[0].test_run.result, 'failed', 'synthetic finish is terminal (failed)'); + + await globals.performTeardownSweep(); + const sweptAgain = uploads.filter((u) => u.event_type === 'TestRunFinished' && u.test_run && u.test_run.uuid === openUuid); + assert.strictEqual(sweptAgain.length, 1, 'second sweep does not double-finish the scenario'); + }); +}); diff --git a/test/src/test-observability/orphanSweepUnits.js b/test/src/test-observability/orphanSweepUnits.js new file mode 100644 index 0000000..f6c5059 --- /dev/null +++ b/test/src/test-observability/orphanSweepUnits.js @@ -0,0 +1,114 @@ +const assert = require('assert'); +const sinon = require('sinon'); + +const helper = require('../../../src/utils/helper'); +const TestMap = require('../../../src/utils/testMap'); +const TestObservability = require('../../../src/testObservability'); + +describe('TestObservability - getCucumberHookType never returns undefined', function () { + let testObservability; + + beforeEach(function () { + testObservability = new TestObservability(); + }); + + it('classifies a per-scenario hook before any step as BEFORE_EACH', function () { + const testSteps = [{id: 'h1', hookId: 'hook-1'}, {id: 's1', pickleStepId: 'ps1'}]; + assert.strictEqual(testObservability.getCucumberHookType(testSteps, {id: 'h1'}), 'BEFORE_EACH'); + }); + + it('classifies a per-scenario hook after a step as AFTER_EACH', function () { + const testSteps = [{id: 's1', pickleStepId: 'ps1'}, {id: 'h1', hookId: 'hook-1'}]; + assert.strictEqual(testObservability.getCucumberHookType(testSteps, {id: 'h1'}), 'AFTER_EACH'); + }); + + it('classifies a hook absent from the scenario steps as a suite-level hook', function () { + assert.strictEqual(testObservability.getCucumberHookType([], {id: 'missing'}), 'BEFORE_ALL'); + assert.strictEqual(testObservability.getCucumberHookType([{id: 's1', pickleStepId: 'ps1'}], {id: 'missing'}), 'AFTER_ALL'); + }); + + it('never returns undefined across malformed inputs', function () { + const cases = [ + testObservability.getCucumberHookType([], {}), + testObservability.getCucumberHookType(undefined, {id: 'x'}), + testObservability.getCucumberHookType([{id: 's1', pickleStepId: 'ps1'}], {id: 'h1'}) + ]; + cases.forEach((hookType) => { + assert.notStrictEqual(hookType, undefined, 'hook_type must never be undefined'); + assert.ok(['BEFORE_EACH', 'AFTER_EACH', 'BEFORE_ALL', 'AFTER_ALL'].includes(hookType)); + }); + }); +}); + +describe('TestObservability - sweepOpenHooks', function () { + let sandbox; + let uploads; + let testObservability; + + beforeEach(function () { + sandbox = sinon.createSandbox(); + uploads = []; + testObservability = new TestObservability(); + sandbox.stub(helper, 'uploadEventData').callsFake(async (payload) => { + uploads.push(payload); + }); + }); + + afterEach(function () { + sandbox.restore(); + }); + + it('finishes a hook that started but never finished, idempotently', async function () { + const args = { + envelope: {testCaseStartedId: 'sweep-tcs-1'}, + report: {hooks: [{id: 'hook-A', name: 'Before', sourceReference: {uri: 'features/support/hooks.js'}}]} + }; + const testSteps = [{id: 'step-A', hookId: 'hook-A'}]; + + await testObservability.sendHook(args, 'HookRunStarted', testSteps, 'step-A', {feature: {name: 'Feature A'}}); + await testObservability.sweepOpenHooks(); + + const finished = uploads.filter((u) => u.event_type === 'HookRunFinished' && u.hook_run && u.hook_run.uuid === 'step-A'); + assert.strictEqual(finished.length, 1, 'open hook is finished once'); + assert.strictEqual(finished[0].hook_run.result, 'failed', 'synthetic hook finish is terminal (failed)'); + + await testObservability.sweepOpenHooks(); + const finishedAgain = uploads.filter((u) => u.event_type === 'HookRunFinished' && u.hook_run && u.hook_run.uuid === 'step-A'); + assert.strictEqual(finishedAgain.length, 1, 'second sweep does not double-finish the hook'); + }); +}); + +describe('TestMap.getOpenRuns and synthetic native finish', function () { + let sandbox; + let uploads; + let testObservability; + + beforeEach(function () { + sandbox = sinon.createSandbox(); + uploads = []; + testObservability = new TestObservability(); + sandbox.stub(helper, 'uploadEventData').callsFake(async (payload) => { + uploads.push(payload); + }); + }); + + afterEach(function () { + sandbox.restore(); + }); + + it('reports an unfinished run, synthesises a failed finish, and clears it after markTestFinished', async function () { + const uuid = TestMap.storeTestDetails({testcase: 'native test', metadata: {name: 'Native Module'}}); + + const openBefore = TestMap.getOpenRuns().filter((r) => r.uuid === uuid); + assert.strictEqual(openBefore.length, 1, 'stored run is reported as open'); + + await testObservability.sendSyntheticTestRunFinished(uuid, openBefore[0]); + const finished = uploads.filter((u) => u.event_type === 'TestRunFinished' && u.test_run && u.test_run.uuid === uuid); + assert.strictEqual(finished.length, 1, 'a terminal finish is emitted for the open run'); + assert.strictEqual(finished[0].test_run.result, 'failed', 'synthetic native finish is terminal (failed)'); + + TestMap.markTestFinished(uuid); + const openAfter = TestMap.getOpenRuns().filter((r) => r.uuid === uuid); + assert.strictEqual(openAfter.length, 0, 'finished run is no longer reported as open'); + }); +}); From 2f2b0c4ab06cbc7c3b443a68dae64fc34d69b49f Mon Sep 17 00:00:00 2001 From: xxshubhamxx Date: Wed, 10 Jun 2026 11:39:38 +0530 Subject: [PATCH 2/2] fix(observability): make cucumber TestCaseFinished idempotent and drop fresh-uuid reconstruct A duplicate/out-of-order TestCaseFinished for the same attempt used to find the entry already deleted, hit the reconstruct branch, mint a fresh uuid, and emit a phantom TestRunFinished for a run the backend never saw started. And the reconstruct branch was dead code for the genuine start-never-recorded orphan: the unguarded _testCasesData read threw before it ran (and the reconstruct itself threw on undefined), all silently swallowed. Track handled attempt ids in a Set and early-return on a duplicate finish, guard the _testCasesData read so an unknown finish no-ops cleanly, and remove the fresh-uuid reconstruct branch entirely. True orphans (started, never finished) are owned solely by the teardown sweep, which holds the real stored uuid. The Set is per-process and bounded by attempt count (same bound as _testCasesData). Also: per-hook try/catch in sweepOpenHooks so one bad upload no longer aborts the remaining hook sweeps; fix the synthetic native finish lang to 'nightwatch'; and document the single-open-run-per-process assumption behind the TestMap.getUUID fallback. Add tests for the duplicate-finish and never-started-finish cases. Co-Authored-By: Claude Opus 4.8 --- nightwatch/globals.js | 44 +++++++++++-------- src/testObservability.js | 12 +++-- src/utils/testMap.js | 5 +++ .../test-observability/cucumberOrphanFix.js | 44 +++++++++++++++++++ 4 files changed, 83 insertions(+), 22 deletions(-) diff --git a/nightwatch/globals.js b/nightwatch/globals.js index 9e4aa53..9476760 100644 --- a/nightwatch/globals.js +++ b/nightwatch/globals.js @@ -21,6 +21,11 @@ const nightwatchRerun = process.env.NIGHTWATCH_RERUN_FAILED; const nightwatchRerunFile = process.env.NIGHTWATCH_RERUN_REPORT_FILE; const _tests = {}; const _testCasesData = {}; +// Per-attempt testCaseStartedId of every TestCaseFinished already handled, so a +// duplicate/out-of-order finish for the same attempt is a no-op instead of +// re-emitting a phantom TestRunFinished. Bounded by attempt count per worker +// process (same bound as _testCasesData), so it cannot grow unbounded. +const _finishedTestCaseIds = new Set(); let currentTestUUID = ''; let workerList = {}; let testRunner = ''; @@ -157,29 +162,29 @@ module.exports = { try { const reportData = args.report; const uniqueId = args.envelope.testCaseStartedId; - const testCaseId = _testCasesData[uniqueId].testCaseId; + // A duplicate/out-of-order finish for an attempt we have already finished + // is a no-op: re-emitting would mint a phantom TestRunFinished for a run the + // backend never saw started. + if (_finishedTestCaseIds.has(uniqueId)) { + return; + } + const testCaseId = _testCasesData[uniqueId]?.testCaseId; + const testMetaData = _tests[uniqueId]; + // A finish whose start was never recorded has no stored metadata to finish + // and no real backend run to terminate; no-op here. The teardown sweep is the + // single owner of true orphans (it holds the real stored uuid for any entry + // that started but never finished). + if (!testCaseId || !testMetaData) { + _finishedTestCaseIds.add(uniqueId); + + return; + } const pickleId = reportData.testCases.find((testCase) => testCase.id === testCaseId).pickleId; const pickleData = reportData.pickle.find((pickle) => pickle.id === pickleId); const gherkinDocument = reportData?.gherkinDocument.find((document) => document.uri === pickleData.uri); - // Look up by the unique per-attempt id. If the entry is missing (a duplicate - // or out-of-order finish, or a start that was never recorded) reconstruct a - // minimal payload so a terminal finish is still emitted and the run can never - // be left open to be flipped to a timeout by the reaper. - let testMetaData = _tests[uniqueId]; - if (!testMetaData) { - testMetaData = { - uuid: uuidv4(), - startedAt: new Date().toISOString(), - scenario: {name: pickleData?.name}, - feature: (gherkinDocument && gherkinDocument.feature) ? { - path: gherkinDocument.uri, - name: gherkinDocument.feature.name, - description: gherkinDocument.feature.description - } : undefined - }; - } delete _tests[uniqueId]; + _finishedTestCaseIds.add(uniqueId); testMetaData.finishedAt = new Date().toISOString(); CustomTagManager.drainPendingTestTags(testMetaData.uuid); await testObservability.sendTestRunEventForCucumber(reportData, gherkinDocument, pickleData, 'TestRunFinished', testMetaData, args); @@ -733,6 +738,9 @@ const performTeardownSweep = async () => { CrashReporter.uploadCrashReport(error.message, error.stack); } }; +// Attached as a named export (rather than folded into the module.exports object +// literal above) so unit tests can drive the sweep directly without relocating the +// const, which is referenced by the teardown closures earlier in the literal. module.exports.performTeardownSweep = performTeardownSweep; const cucumberPatcher = () => { diff --git a/src/testObservability.js b/src/testObservability.js index 5627703..8113cb1 100644 --- a/src/testObservability.js +++ b/src/testObservability.js @@ -941,7 +941,7 @@ class TestObservability { type: 'test', name: testName || 'unknown', body: { - lang: 'javascript', + lang: 'nightwatch', code: null }, scope: identifier, @@ -967,9 +967,13 @@ class TestObservability { if (hookEventData.finished_at) { continue; } - hookEventData.result = 'failed'; - hookEventData.finished_at = new Date().toISOString(); - await helper.uploadEventData({event_type: 'HookRunFinished', hook_run: hookEventData}); + try { + hookEventData.result = 'failed'; + hookEventData.finished_at = new Date().toISOString(); + await helper.uploadEventData({event_type: 'HookRunFinished', hook_run: hookEventData}); + } catch (err) { + Logger.debug(`Error sweeping open hook ${hookEventData.uuid}: ${err && err.message}`); + } } } } diff --git a/src/utils/testMap.js b/src/utils/testMap.js index a528315..4bdc6bf 100644 --- a/src/utils/testMap.js +++ b/src/utils/testMap.js @@ -76,6 +76,11 @@ class TestMap { // Fall back to the most recently started run that has not finished yet, so a // finish event whose identifier cannot be resolved still lands on an open run // instead of being dropped (which would otherwise leave that run to be reaped). + // Assumes a single open run per worker process: Nightwatch parallelism is across + // processes (each gets its own TestMap), and within a process tests run serially, + // so at most one run is open at a time. If in-process parallel tests are ever + // added, this "most recent open run" pick would need a real identifier match to + // avoid bleeding a finish onto the wrong concurrent run. let fallbackUuid = null; for (const [uuid, run] of activeTestRuns) { if (!run.hasFinished) { diff --git a/test/src/test-observability/cucumberOrphanFix.js b/test/src/test-observability/cucumberOrphanFix.js index 77b4d28..fe57be1 100644 --- a/test/src/test-observability/cucumberOrphanFix.js +++ b/test/src/test-observability/cucumberOrphanFix.js @@ -91,6 +91,50 @@ describe('globals - cucumber rerun correlation and teardown sweep', function () assert.deepStrictEqual(finishUuids, startUuids, 'both started uuids are finished'); }); + it('a duplicate TestCaseFinished for the same attempt emits exactly one TestRunFinished and no phantom uuid', async function () { + const globals = loadGlobals(); + const broadcaster = makeBroadcaster(); + globals.registerEventHandlers(broadcaster); + const report = buildReport(); + + await broadcaster.handlers['TestCaseStarted']({envelope: {id: 'tcs-1', testCaseId: 'tc-1'}, report}); + const startCall = cucumberCalls.find((c) => c.eventType === 'TestRunStarted'); + const startedUuid = startCall.uuid; + + await broadcaster.handlers['TestCaseFinished']({envelope: {testCaseStartedId: 'tcs-1'}, report}); + // Second finish for the SAME attempt: the entry is already gone, so the old + // reconstruct branch would have minted a fresh uuid and emitted a phantom + // TestRunFinished. It must now be a clean no-op. + await broadcaster.handlers['TestCaseFinished']({envelope: {testCaseStartedId: 'tcs-1'}, report}); + + const finished = cucumberCalls.filter((c) => c.eventType === 'TestRunFinished'); + assert.strictEqual(finished.length, 1, 'only one TestRunFinished for the attempt'); + assert.strictEqual(finished[0].uuid, startedUuid, 'finish carries the started uuid, not a fresh phantom one'); + }); + + it('a TestCaseFinished whose start was never recorded neither throws nor emits, and the sweep still finishes a stored-but-unfinished entry', async function () { + const globals = loadGlobals(); + const broadcaster = makeBroadcaster(); + globals.registerEventHandlers(broadcaster); + const report = buildReport(); + + // No TestCaseStarted for tcs-1: a finish arrives for an attempt we never saw start. + await broadcaster.handlers['TestCaseFinished']({envelope: {testCaseStartedId: 'tcs-1'}, report}); + + const finished = cucumberCalls.filter((c) => c.eventType === 'TestRunFinished'); + assert.strictEqual(finished.length, 0, 'an unknown finish emits nothing (no phantom run)'); + assert.strictEqual(uploads.length, 0, 'and uploads nothing'); + + // A genuine orphan (started, never finished) is still owned by the sweep, which + // holds the real stored uuid. + await broadcaster.handlers['TestCaseStarted']({envelope: {id: 'tcs-2', testCaseId: 'tc-1'}, report}); + const openUuid = cucumberCalls.find((c) => c.eventType === 'TestRunStarted').uuid; + + await globals.performTeardownSweep(); + const swept = uploads.filter((u) => u.event_type === 'TestRunFinished' && u.test_run && u.test_run.uuid === openUuid); + assert.strictEqual(swept.length, 1, 'the sweep finishes the stored-but-unfinished entry with its real uuid'); + }); + it('sweep emits a terminal failed TestRunFinished for a scenario left open in _tests, idempotently', async function () { const globals = loadGlobals(); const broadcaster = makeBroadcaster();