Skip to content

fix(observability): emit a finish for every cucumber test/hook to prevent orphaned runs #56

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
xxshubhamxx wants to merge 2 commits into from
+502 −31
Closed

fix(observability): emit a finish for every cucumber test/hook to prevent orphaned runs #56

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0ca31da
fix(observability): correlate cucumber finishes by unique attempt id …
xxshubhamxx Jun 9, 2026
2f2b0c4
fix(observability): make cucumber TestCaseFinished idempotent and dro…
xxshubhamxx Jun 10, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
126 changes: 101 additions & 25 deletions nightwatch/globals.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,15 +21,21 @@ 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 = '';
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) => {
Expand Down Expand Up @@ -115,8 +121,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});
}
});
Expand All @@ -139,7 +144,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);
Expand All @@ -153,18 +161,33 @@ module.exports = {
}
try {
const reportData = args.report;
const testCaseId = _testCasesData[args.envelope.testCaseStartedId].testCaseId;
const uniqueId = args.envelope.testCaseStartedId;
// 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);
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);
}
delete _tests[uniqueId];
_finishedTestCaseIds.add(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}`);
Expand All @@ -177,17 +200,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 = [];
}
Expand All @@ -196,7 +220,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);
Expand All @@ -211,13 +235,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;
Expand All @@ -226,9 +251,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,
Expand All @@ -250,8 +275,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) {
Expand Down Expand Up @@ -561,6 +586,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`);
Expand Down Expand Up @@ -659,6 +688,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);
Expand All @@ -667,6 +699,50 @@ 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);
}
};
// 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 = () => {
try {
const Coordinator = helper.requireModule('@cucumber/cucumber/lib/runtime/parallel/coordinator.js');
Expand Down
100 changes: 97 additions & 3 deletions src/testObservability.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -871,17 +871,111 @@ 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: 'nightwatch',
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;
}
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}`);
}
}
}
}

async appendTestItemLog (log, testUuid) {
Expand Down
35 changes: 32 additions & 3 deletions src/utils/testMap.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,11 +68,40 @@ 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).
// 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) {
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) {
Expand Down
Loading
Loading