From a92cd9696d0765c30b91569a68fd23d6860c429c Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 14:36:07 -0500 Subject: [PATCH 01/12] perf log automation command --- packages/server/lib/automation/automation.ts | 3 ++ .../commands/record_performance_entry.ts | 46 +++++++++++++++++++ .../server/lib/browsers/bidi_automation.ts | 2 + .../server/lib/browsers/cdp_automation.ts | 4 +- packages/server/lib/modes/index.ts | 4 ++ packages/types/src/server.ts | 9 ++++ 6 files changed, 67 insertions(+), 1 deletion(-) create mode 100644 packages/server/lib/automation/commands/record_performance_entry.ts diff --git a/packages/server/lib/automation/automation.ts b/packages/server/lib/automation/automation.ts index b4073451dbc..fdafb87f8f8 100644 --- a/packages/server/lib/automation/automation.ts +++ b/packages/server/lib/automation/automation.ts @@ -8,6 +8,7 @@ import { cookieJar } from '../util/cookies' import type { ServiceWorkerEventHandler } from '@packages/proxy/lib/http/util/service-worker-manager' import Debug from 'debug' import { AutomationNotImplemented } from './automation_not_implemented' +import { recordPerformanceEntry } from './commands/record_performance_entry' const debug = Debug('cypress:server:automation') @@ -174,6 +175,8 @@ export class Automation { case 'canceled:download': case 'complete:download': return data + case 'log:command:performance': + return recordPerformanceEntry(data) default: return automate(data) } diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts new file mode 100644 index 00000000000..c72f95bb34c --- /dev/null +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -0,0 +1,46 @@ +import Debug from 'debug' +import type { CommandPerformanceEntry } from '@packages/types' +import path from 'path' +import fs from 'fs/promises' +import fsSync from 'fs' + +const debug = Debug('cypress-verbose:server:automation:commands:record_performance_entry') + +function logFilePath () { + return process.env.CYPRESS_INTERNAL_PERFORMANCE_LOG_FILE_PATH ?? path.join(process.cwd(), 'cypress', 'logs') +} + +function performanceLogsEnabled () { + return ['1', 'true'].includes(process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING ?? 'false') +} + +const COLUMNS = [ + 'startTime', + 'duration', + 'command', + 'numElements', + 'spec', +] + +export function initializePerformanceLogFile () { + if (!performanceLogsEnabled()) { + return + } + + fsSync.mkdirSync(logFilePath(), { recursive: true }) + fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' }) +} + +export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { + debug('recording performance entry %o', entry) + + if (!performanceLogsEnabled()) { + return + } + + await fs.writeFile( + path.join(logFilePath(), 'performance.log'), + `${entry.startTime},${entry.duration},${entry.command},${entry.numElements},${entry.spec}\n`, + { flag: 'a' }, + ) +} diff --git a/packages/server/lib/browsers/bidi_automation.ts b/packages/server/lib/browsers/bidi_automation.ts index 3e6afd71867..a35debcefd8 100644 --- a/packages/server/lib/browsers/bidi_automation.ts +++ b/packages/server/lib/browsers/bidi_automation.ts @@ -726,6 +726,8 @@ export class BidiAutomation { throw new Error('Cannot get AUT title no AUT context initialized') } + case 'log:command:performance': + return recordPerformanceEntry(data) default: debug('BiDi automation not implemented for message: %s', message) throw new AutomationNotImplemented(message, 'BiDiAutomation') diff --git a/packages/server/lib/browsers/cdp_automation.ts b/packages/server/lib/browsers/cdp_automation.ts index 140dcb291b0..dff3dd8bbd6 100644 --- a/packages/server/lib/browsers/cdp_automation.ts +++ b/packages/server/lib/browsers/cdp_automation.ts @@ -8,7 +8,7 @@ import { parseDomain, isLocalhost as isLocalhostNetworkTools } from '@packages/n import debugModule from 'debug' import { URL } from 'url' import { performance } from 'perf_hooks' - +import { recordPerformanceEntry } from '../automation/commands/record_performance_entry' import type { ResourceType, BrowserPreRequest, BrowserResponseReceived } from '@packages/proxy' import type { CDPClient, ProtocolManagerShape, WriteVideoFrame, AutomationMiddleware, AutomationCommands } from '@packages/types' import type { Automation } from '../automation' @@ -662,6 +662,8 @@ export class CdpAutomation implements CDPClient, AutomationMiddleware { return cdpNavigateHistory(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame(), data.historyNumber) case 'get:aut:title': return cdpGetFrameTitle(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame()) + case 'log:command:performance': + return recordPerformanceEntry(data) default: throw new Error(`No automation handler registered for: '${message}'`) } diff --git a/packages/server/lib/modes/index.ts b/packages/server/lib/modes/index.ts index 57e88e1b843..2873eacdf91 100644 --- a/packages/server/lib/modes/index.ts +++ b/packages/server/lib/modes/index.ts @@ -4,6 +4,7 @@ import _ from 'lodash' import { makeDataContext } from '../makeDataContext' import { id as randomId } from '../util/random' import { telemetry } from '@packages/telemetry' +import { initializePerformanceLogFile } from '../automation/commands/record_performance_entry' export = (mode, options) => { if (mode === 'smokeTest') { @@ -24,6 +25,9 @@ export = (mode, options) => { } const span = telemetry.startSpan({ name: `initialize:mode:${mode}` }) + + initializePerformanceLogFile() + const ctx = setCtx(makeDataContext({ mode: mode === 'run' ? mode : 'open', modeOptions: options })) telemetry.getSpan('cypress')?.setAttribute('name', `cypress:${mode}`) diff --git a/packages/types/src/server.ts b/packages/types/src/server.ts index 99abf858e0f..187b6801b53 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -125,6 +125,14 @@ export interface KeyPressParams { key: SupportedKey } +export interface CommandPerformanceEntry { + name: string + spec: string + numElements: number + duration: number + startTime: number +} + export interface AutomationCommands { 'take:screenshot': CommandSignature 'get:cookies': CommandSignature @@ -151,6 +159,7 @@ export interface AutomationCommands { 'reload:aut:frame': CommandSignature<{ forceReload: boolean }, void> 'navigate:aut:history': CommandSignature<{ historyNumber: number }, void> 'get:aut:title': CommandSignature + 'log:command:performance': CommandSignature } export type OnRequestEvent = (message: T, data: AutomationCommands[T]['dataType']) => Promise From b938ad7194b99e0db59756c52bc1c5e3765d8867 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 14:50:42 -0500 Subject: [PATCH 02/12] write a performance log entry for each command --- packages/driver/src/cypress/command_queue.ts | 16 ++++++++++++++ .../commands/record_performance_entry.ts | 21 +++++++++++++++++-- packages/types/src/server.ts | 12 ++++++++--- 3 files changed, 44 insertions(+), 5 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 09ac6e460bf..2d9d1271162 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -229,6 +229,7 @@ export class CommandQueue extends Queue<$Command> { } private runCommand (command: $Command) { + const startTime = performance.now() const isQuery = command.get('query') const name = command.get('name') @@ -362,6 +363,8 @@ export class CommandQueue extends Queue<$Command> { command.set({ subject }) command.pass() + const numElements = subject ? subject.length ?? 1 : 0 + // end / snapshot our logs if they need it command.finishLogs() @@ -397,6 +400,19 @@ export class CommandQueue extends Queue<$Command> { current: null, }) + const duration = performance.now() - startTime + + Cypress.automation('log:command:performance', { + name: `command:run:${command.attributes.name}`, + startTime, + duration, + detail: { + runnable: this.state('runnable'), + spec: Cypress.spec.relative, + numElements, + }, + }) + return subject }) } diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index c72f95bb34c..b2459ac1b3e 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -17,8 +17,9 @@ function performanceLogsEnabled () { const COLUMNS = [ 'startTime', 'duration', - 'command', + 'name', 'numElements', + 'runnable', 'spec', ] @@ -27,6 +28,8 @@ export function initializePerformanceLogFile () { return } + debug('initializing performance log file: %s', path.join(logFilePath(), 'performance.log')) + fsSync.mkdirSync(logFilePath(), { recursive: true }) fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' }) } @@ -38,9 +41,23 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { return } + const { + startTime, + duration, + name, + detail: { + numElements, + runnable: { + title, + type, + }, + spec, + }, + } = entry + await fs.writeFile( path.join(logFilePath(), 'performance.log'), - `${entry.startTime},${entry.duration},${entry.command},${entry.numElements},${entry.spec}\n`, + [startTime, duration, name, numElements, `${title} (${type})`, spec].join(',') + '\n', { flag: 'a' }, ) } diff --git a/packages/types/src/server.ts b/packages/types/src/server.ts index 187b6801b53..1dce7496c50 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -127,10 +127,16 @@ export interface KeyPressParams { export interface CommandPerformanceEntry { name: string - spec: string - numElements: number - duration: number startTime: number + duration: number + detail: { + runnable: { + type: string + title: string + } + spec: string + numElements: number + } } export interface AutomationCommands { From 6ca1bb11fe60e03a7eababc4bac86b56b8a5c5c2 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 14:58:36 -0500 Subject: [PATCH 03/12] better log entries --- packages/driver/src/cypress/command_queue.ts | 4 ++-- .../lib/automation/commands/record_performance_entry.ts | 5 ++--- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 2d9d1271162..7f84ff7ca5c 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -403,11 +403,11 @@ export class CommandQueue extends Queue<$Command> { const duration = performance.now() - startTime Cypress.automation('log:command:performance', { - name: `command:run:${command.attributes.name}`, + name: command?.attributes?.name ?? 'unknown', startTime, duration, detail: { - runnable: this.state('runnable'), + runnable: this.state('runnable') ?? {}, spec: Cypress.spec.relative, numElements, }, diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index b2459ac1b3e..7e26c4a9d47 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -19,7 +19,7 @@ const COLUMNS = [ 'duration', 'name', 'numElements', - 'runnable', + 'runnableTitle', 'spec', ] @@ -49,7 +49,6 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { numElements, runnable: { title, - type, }, spec, }, @@ -57,7 +56,7 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { await fs.writeFile( path.join(logFilePath(), 'performance.log'), - [startTime, duration, name, numElements, `${title} (${type})`, spec].join(',') + '\n', + [startTime, duration, name, numElements, title, spec].join(',') + '\n', { flag: 'a' }, ) } From ef2acf775d19ed6ca2c5c74740e1f8db24f5184a Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 15:02:54 -0500 Subject: [PATCH 04/12] changelog --- cli/CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/cli/CHANGELOG.md b/cli/CHANGELOG.md index 6e9465c8124..f6bbd486ec9 100644 --- a/cli/CHANGELOG.md +++ b/cli/CHANGELOG.md @@ -12,6 +12,7 @@ _Released 11/18/2025 (PENDING)_ - The keyboard shortcuts modal now displays the keyboard shortcut for saving Studio changes - `⌘` + `s` for Mac or `Ctrl` + `s` for Windows/Linux. Addressed [#32862](https://github.com/cypress-io/cypress/issues/32862). Addressed in [#32864](https://github.com/cypress-io/cypress/pull/32864). - The Cursor logo now correctly displays in the External editor dropdown. Addresses [#32062](https://github.com/cypress-io/cypress/issues/32062). Addressed in [#32911](https://github.com/cypress-io/cypress/pull/32911). +- Command execution can be benchmarked by setting the `CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING` environment variable to `1` or `true`. The performance log is recorded to `./cypress/logs/performance.log` by default. Addressed in [#32938](https://github.com/cypress-io/cypress/pull/32938) ## 15.6.0 From 39aa6f22390e8c133f045ec64efff28f73f25d5a Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 15:14:13 -0500 Subject: [PATCH 05/12] esc --- .../commands/record_performance_entry.ts | 28 ++++++++++++++++++- 1 file changed, 27 insertions(+), 1 deletion(-) diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index 7e26c4a9d47..6b5be800ed4 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -23,6 +23,23 @@ const COLUMNS = [ 'spec', ] +/** + * Escapes a value for CSV format according to RFC 4180. + * - If the value contains comma, newline, or double quote, wrap it in double quotes + * - Escape any double quotes within the value by doubling them + */ +function escapeCsvValue (value: string | number): string { + const stringValue = String(value) + + // If value contains comma, newline, or double quote, wrap in quotes + if (stringValue.includes(',') || stringValue.includes('\n') || stringValue.includes('"')) { + // Escape double quotes by doubling them + return `"${stringValue.replace(/"/g, '""')}"` + } + + return stringValue +} + export function initializePerformanceLogFile () { if (!performanceLogsEnabled()) { return @@ -54,9 +71,18 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { }, } = entry + const row = [ + startTime, + duration, + name, + numElements, + title, + spec, + ].map(escapeCsvValue).join(',') + await fs.writeFile( path.join(logFilePath(), 'performance.log'), - [startTime, duration, name, numElements, title, spec].join(',') + '\n', + `${row}\n`, { flag: 'a' }, ) } From 0aa7f21d0a7b6c6a4889bc37e0b1d1d0a7412bd8 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 15:15:32 -0500 Subject: [PATCH 06/12] fail with debug entry if error thrown initializing perf log --- .../commands/record_performance_entry.ts | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index 6b5be800ed4..234e7068b77 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -41,14 +41,18 @@ function escapeCsvValue (value: string | number): string { } export function initializePerformanceLogFile () { - if (!performanceLogsEnabled()) { - return - } + try { + if (!performanceLogsEnabled()) { + return + } - debug('initializing performance log file: %s', path.join(logFilePath(), 'performance.log')) + debug('initializing performance log file: %s', path.join(logFilePath(), 'performance.log')) - fsSync.mkdirSync(logFilePath(), { recursive: true }) - fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' }) + fsSync.mkdirSync(logFilePath(), { recursive: true }) + fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' }) + } catch (error) { + debug('error initializing performance log file: %s', error) + } } export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { From 8b2e51509803d4195a7841fa7f974ce82613eb47 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 12 Nov 2025 15:17:34 -0500 Subject: [PATCH 07/12] reduce serialization --- packages/driver/src/cypress/command_queue.ts | 2 +- .../lib/automation/commands/record_performance_entry.ts | 6 ++---- packages/types/src/server.ts | 5 +---- 3 files changed, 4 insertions(+), 9 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 7f84ff7ca5c..4020d168e53 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -407,7 +407,7 @@ export class CommandQueue extends Queue<$Command> { startTime, duration, detail: { - runnable: this.state('runnable') ?? {}, + runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', spec: Cypress.spec.relative, numElements, }, diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index 234e7068b77..d0dc3382b3e 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -68,9 +68,7 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { name, detail: { numElements, - runnable: { - title, - }, + runnableTitle, spec, }, } = entry @@ -80,7 +78,7 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { duration, name, numElements, - title, + runnableTitle, spec, ].map(escapeCsvValue).join(',') diff --git a/packages/types/src/server.ts b/packages/types/src/server.ts index 1dce7496c50..a0d7b20c8e0 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -130,10 +130,7 @@ export interface CommandPerformanceEntry { startTime: number duration: number detail: { - runnable: { - type: string - title: string - } + runnableTitle: string spec: string numElements: number } From d80bf84ec582a6b307d93a314f72bb851f5cfcdf Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Thu, 13 Nov 2025 10:58:10 -0500 Subject: [PATCH 08/12] ts --- packages/driver/src/cypress/command_queue.ts | 296 +++++++++--------- .../commands/record_performance_entry.ts | 16 +- .../server/lib/browsers/bidi_automation.ts | 2 + 3 files changed, 161 insertions(+), 153 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 4020d168e53..f5809239037 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -11,6 +11,7 @@ import type $Command from './command' import type { StateFunc } from './state' import type { $Cy } from './cy' import type { IStability } from '../cy/stability' +import { isJquery } from '../dom/jquery' const debugErrors = Debug('cypress:driver:errors') @@ -228,7 +229,7 @@ export class CommandQueue extends Queue<$Command> { this.state('isStable', true) } - private runCommand (command: $Command) { + private async runCommand (command: $Command) { const startTime = performance.now() const isQuery = command.get('query') const name = command.get('name') @@ -244,177 +245,178 @@ export class CommandQueue extends Queue<$Command> { this.state('current', command) this.state('chainerId', command.get('chainerId')) - return this.stability.whenStable(() => { - this.state('nestedIndex', this.index) - - return command.get('args') - }) - .then((args: any) => { - // store this if we enqueue new commands - // to check for promise violations - let ret - let enqueuedCmd - - // Queries can invoke other queries - they are synchronous, and get added to the subject chain without - // issue. But they cannot contain commands, which are async. - // This callback watches to ensure users don't try and invoke any commands while inside a query. - const commandEnqueued = (obj: Cypress.EnqueuedCommandAttributes) => { - if (isQuery && !obj.query) { - $errUtils.throwErrByPath( - 'query_command.invoked_action', { - args: { - name, - action: obj.name, - }, - }, - ) - } - - return enqueuedCmd = obj - } - - // only check for command enqueuing when none - // of our args are functions else commands - // like cy.then or cy.each would always fail - // since they return promises and queue more - // new commands - if ($utils.noArgsAreAFunction(args)) { - Cypress.once('command:enqueued', commandEnqueued) - } - - args = [command.get('chainerId'), ...args] - - // run the command's fn with runnable's context + let args = await new Promise((resolve, reject) => { try { - command.start() - ret = __stackReplacementMarker(command.get('fn'), args) - - // Queries return a function which takes the current subject and returns the next subject. We wrap this in - // retryQuery() - and let it retry until it passes, times out or is cancelled. - // We save the original return value on the $Command though - it's what gets added to the subject chain later. - if (isQuery) { - command.set('queryFn', ret) - ret = retryQuery(command, ret, this.cy) - } + this.stability.whenStable(() => { + this.state('nestedIndex', this.index) + resolve(command.get('args')) + }) } catch (err) { - throw err - } finally { - // always remove this listener - Cypress.removeListener('command:enqueued', commandEnqueued) + reject(err) } + }) - this.state('commandIntermediateValue', ret) - - // we cannot pass our cypress instance or our chainer - // back into bluebird else it will create a thenable - // which is never resolved - if (this.cy.isCy(ret)) { - return null - } + // store this if we enqueue new commands + // to check for promise violations + let subject + let enqueuedCmd - if (!(!enqueuedCmd || !$utils.isPromiseLike(ret))) { + // Queries can invoke other queries - they are synchronous, and get added to the subject chain without + // issue. But they cannot contain commands, which are async. + // This callback watches to ensure users don't try and invoke any commands while inside a query. + const commandEnqueued = (obj: Cypress.EnqueuedCommandAttributes) => { + if (isQuery && !obj.query) { $errUtils.throwErrByPath( - 'miscellaneous.command_returned_promise_and_commands', { + 'query_command.invoked_action', { args: { - current: name, - called: enqueuedCmd.name, + name, + action: obj.name, }, }, ) } - if (!(!enqueuedCmd || !!_.isUndefined(ret))) { - ret = _.isFunction(ret) ? - ret.toString() : - $utils.stringify(ret) - - // if we got a return value and we enqueued - // a new command and we didn't return cy - // or an undefined value then throw - $errUtils.throwErrByPath( - 'miscellaneous.returned_value_and_commands_from_custom_command', { - args: { current: name, returned: ret }, - }, - ) - } - - return ret - }) - .then((subject) => { - // we may be given a regular array here so - // we need to re-wrap the array in jquery - // if that's the case if the first item - // in this subject is a jquery element. - // we want to do this because in 3.1.2 there - // was a regression when wrapping an array of elements - const firstSubject = $utils.unwrapFirst(subject) - - // if ret is a DOM element and its not an instance of our own jQuery - if (subject && $dom.isElement(firstSubject) && !$utils.isInstanceOf(subject, $)) { - // set it back to our own jquery object - // to prevent it from being passed downstream - // TODO: enable turning this off - // wrapSubjectsInJquery: false - // which will just pass subjects downstream - // without modifying them - subject = $dom.wrap(subject) - } + return enqueuedCmd = obj + } - command.set({ subject }) - command.pass() + // only check for command enqueuing when none + // of our args are functions else commands + // like cy.then or cy.each would always fail + // since they return promises and queue more + // new commands + if ($utils.noArgsAreAFunction(args)) { + Cypress.once('command:enqueued', commandEnqueued) + } - const numElements = subject ? subject.length ?? 1 : 0 + args = [command.get('chainerId'), ...args] - // end / snapshot our logs if they need it - command.finishLogs() + // run the command's fn with runnable's context + try { + command.start() + subject = __stackReplacementMarker(command.get('fn'), args) + // Queries return a function which takes the current subject and returns the next subject. We wrap this in + // retryQuery() - and let it retry until it passes, times out or is cancelled. + // We save the original return value on the $Command though - it's what gets added to the subject chain later. if (isQuery) { - subject = command.get('queryFn') - // For queries, the "subject" here is the query's return value, which is a function which - // accepts a subject and returns a subject, and can be re-invoked at any time. - - subject.commandName = name - subject.args = command.get('args') - - // Even though we've snapshotted, we only end the logs a query's logs if we're at the end of a query - // chain - either there is no next command (end of a test), the next command is an action, or the next - // command belongs to another chainer (end of a chain). - - // This is done so that any query's logs remain in the 'pending' state until the subject chain is finished. - this.cy.addQueryToChainer(command.get('chainerId'), subject) - } else { - // For commands, the "subject" here is the command's return value, which replaces - // the current subject chain. We cannot re-invoke commands - the return value here is final. - this.cy.setSubjectForChainer(command.get('chainerId'), [subject]) + command.set('queryFn', subject) + subject = retryQuery(command, subject, this.cy) } + } catch (err) { + throw err + } finally { + // always remove this listener + Cypress.removeListener('command:enqueued', commandEnqueued) + } - // TODO: This line was causing subjects to be cleaned up prematurely in some instances (Specifically seen on the within command) - // The command log would print the yielded value as null if checked outside of the current command chain. - // this.cleanSubjects() + this.state('commandIntermediateValue', subject) - this.state({ - commandIntermediateValue: undefined, - // reset the nestedIndex back to null - nestedIndex: null, - // we're finished with the current command so set it back to null - current: null, - }) + // we cannot pass our cypress instance or our chainer + // back into bluebird else it will create a thenable + // which is never resolved + if (this.cy.isCy(subject)) { + return null + } - const duration = performance.now() - startTime + if (!(!enqueuedCmd || !$utils.isPromiseLike(subject))) { + $errUtils.throwErrByPath( + 'miscellaneous.command_returned_promise_and_commands', { + args: { + current: name, + called: enqueuedCmd.name, + }, + }, + ) + } - Cypress.automation('log:command:performance', { - name: command?.attributes?.name ?? 'unknown', - startTime, - duration, - detail: { - runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', - spec: Cypress.spec.relative, - numElements, + if (!(!enqueuedCmd || !!_.isUndefined(subject))) { + subject = _.isFunction(subject) ? + subject.toString() : + $utils.stringify(subject) + + // if we got a return value and we enqueued + // a new command and we didn't return cy + // or an undefined value then throw + $errUtils.throwErrByPath( + 'miscellaneous.returned_value_and_commands_from_custom_command', { + args: { current: name, returned: subject }, }, - }) + ) + } + + // we may be given a regular array here so + // we need to re-wrap the array in jquery + // if that's the case if the first item + // in this subject is a jquery element. + // we want to do this because in 3.1.2 there + // was a regression when wrapping an array of elements + const firstSubject = $utils.unwrapFirst(subject) + + // if ret is a DOM element and its not an instance of our own jQuery + if (subject && $dom.isElement(firstSubject) && !$utils.isInstanceOf(subject, $)) { + // set it back to our own jquery object + // to prevent it from being passed downstream + // TODO: enable turning this off + // wrapSubjectsInJquery: false + // which will just pass subjects downstream + // without modifying them + subject = $dom.wrap(subject) + } + + command.set({ subject }) + command.pass() + + const numElements = isJquery(subject) ? subject.length : 0 - return subject + // end / snapshot our logs if they need it + command.finishLogs() + + if (isQuery) { + subject = command.get('queryFn') + // For queries, the "subject" here is the query's return value, which is a function which + // accepts a subject and returns a subject, and can be re-invoked at any time. + + subject.commandName = name + subject.args = command.get('args') + + // Even though we've snapshotted, we only end the logs a query's logs if we're at the end of a query + // chain - either there is no next command (end of a test), the next command is an action, or the next + // command belongs to another chainer (end of a chain). + + // This is done so that any query's logs remain in the 'pending' state until the subject chain is finished. + this.cy.addQueryToChainer(command.get('chainerId'), subject) + } else { + // For commands, the "subject" here is the command's return value, which replaces + // the current subject chain. We cannot re-invoke commands - the return value here is final. + this.cy.setSubjectForChainer(command.get('chainerId'), [subject]) + } + + // TODO: This line was causing subjects to be cleaned up prematurely in some instances (Specifically seen on the within command) + // The command log would print the yielded value as null if checked outside of the current command chain. + // this.cleanSubjects() + + this.state({ + commandIntermediateValue: undefined, + // reset the nestedIndex back to null + nestedIndex: null, + // we're finished with the current command so set it back to null + current: null, + }) + + const duration = performance.now() - startTime + + await Cypress.automation('log:command:performance', { + name: command?.attributes?.name ?? 'unknown', + startTime, + duration, + detail: { + runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', + spec: Cypress.spec.relative, + numElements, + }, }) + + return subject } // TypeScript doesn't allow overriding functions with different type signatures diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index d0dc3382b3e..9bcef9563e5 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -55,7 +55,7 @@ export function initializePerformanceLogFile () { } } -export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { +export function recordPerformanceEntry (entry: CommandPerformanceEntry) { debug('recording performance entry %o', entry) if (!performanceLogsEnabled()) { @@ -82,9 +82,13 @@ export async function recordPerformanceEntry (entry: CommandPerformanceEntry) { spec, ].map(escapeCsvValue).join(',') - await fs.writeFile( - path.join(logFilePath(), 'performance.log'), - `${row}\n`, - { flag: 'a' }, - ) + try { + fsSync.writeFile( + path.join(logFilePath(), 'performance.log'), + `${row}\n`, + { flag: 'a' }, + ) + } catch (error) { + debug('error recording performance entry: %s', error) + } } diff --git a/packages/server/lib/browsers/bidi_automation.ts b/packages/server/lib/browsers/bidi_automation.ts index a35debcefd8..ccc2edc70cd 100644 --- a/packages/server/lib/browsers/bidi_automation.ts +++ b/packages/server/lib/browsers/bidi_automation.ts @@ -25,6 +25,8 @@ import { bidiGetUrl } from '../automation/commands/get_url' import { bidiReloadFrame } from '../automation/commands/reload_frame' import { bidiNavigateHistory } from '../automation/commands/navigate_history' import { bidiGetFrameTitle } from '../automation/commands/get_frame_title' +import { recordPerformanceEntry } from '../automation/commands/record_performance_entry' + import type { StorageCookieFilter, StoragePartialCookie as BidiStoragePartialCookie } from 'webdriver/build/bidi/remoteTypes' const BIDI_DEBUG_NAMESPACE = 'cypress:server:browsers:bidi_automation' From 39d87cba8b62da63929e587e7764d991aeca280e Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Wed, 19 Nov 2025 14:43:54 -0500 Subject: [PATCH 09/12] back out of async/await modification to command queue --- packages/driver/src/cypress/command_queue.ts | 298 +++++++++--------- .../commands/record_performance_entry.ts | 3 +- 2 files changed, 148 insertions(+), 153 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index f5809239037..dcebb0fac73 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -11,7 +11,6 @@ import type $Command from './command' import type { StateFunc } from './state' import type { $Cy } from './cy' import type { IStability } from '../cy/stability' -import { isJquery } from '../dom/jquery' const debugErrors = Debug('cypress:driver:errors') @@ -229,8 +228,9 @@ export class CommandQueue extends Queue<$Command> { this.state('isStable', true) } - private async runCommand (command: $Command) { + private runCommand (command: $Command) { const startTime = performance.now() + const isQuery = command.get('query') const name = command.get('name') @@ -245,178 +245,174 @@ export class CommandQueue extends Queue<$Command> { this.state('current', command) this.state('chainerId', command.get('chainerId')) - let args = await new Promise((resolve, reject) => { + return this.stability.whenStable(() => { + this.state('nestedIndex', this.index) + + return command.get('args') + }) + .then((args: any) => { + // store this if we enqueue new commands + // to check for promise violations + let ret + let enqueuedCmd + + // Queries can invoke other queries - they are synchronous, and get added to the subject chain without + // issue. But they cannot contain commands, which are async. + // This callback watches to ensure users don't try and invoke any commands while inside a query. + const commandEnqueued = (obj: Cypress.EnqueuedCommandAttributes) => { + if (isQuery && !obj.query) { + $errUtils.throwErrByPath( + 'query_command.invoked_action', { + args: { + name, + action: obj.name, + }, + }, + ) + } + + return enqueuedCmd = obj + } + + // only check for command enqueuing when none + // of our args are functions else commands + // like cy.then or cy.each would always fail + // since they return promises and queue more + // new commands + if ($utils.noArgsAreAFunction(args)) { + Cypress.once('command:enqueued', commandEnqueued) + } + + args = [command.get('chainerId'), ...args] + + // run the command's fn with runnable's context try { - this.stability.whenStable(() => { - this.state('nestedIndex', this.index) - resolve(command.get('args')) - }) + command.start() + ret = __stackReplacementMarker(command.get('fn'), args) + + // Queries return a function which takes the current subject and returns the next subject. We wrap this in + // retryQuery() - and let it retry until it passes, times out or is cancelled. + // We save the original return value on the $Command though - it's what gets added to the subject chain later. + if (isQuery) { + command.set('queryFn', ret) + ret = retryQuery(command, ret, this.cy) + } } catch (err) { - reject(err) + throw err + } finally { + // always remove this listener + Cypress.removeListener('command:enqueued', commandEnqueued) } - }) - // store this if we enqueue new commands - // to check for promise violations - let subject - let enqueuedCmd + this.state('commandIntermediateValue', ret) + + // we cannot pass our cypress instance or our chainer + // back into bluebird else it will create a thenable + // which is never resolved + if (this.cy.isCy(ret)) { + return null + } - // Queries can invoke other queries - they are synchronous, and get added to the subject chain without - // issue. But they cannot contain commands, which are async. - // This callback watches to ensure users don't try and invoke any commands while inside a query. - const commandEnqueued = (obj: Cypress.EnqueuedCommandAttributes) => { - if (isQuery && !obj.query) { + if (!(!enqueuedCmd || !$utils.isPromiseLike(ret))) { $errUtils.throwErrByPath( - 'query_command.invoked_action', { + 'miscellaneous.command_returned_promise_and_commands', { args: { - name, - action: obj.name, + current: name, + called: enqueuedCmd.name, }, }, ) } - return enqueuedCmd = obj - } + if (!(!enqueuedCmd || !!_.isUndefined(ret))) { + ret = _.isFunction(ret) ? + ret.toString() : + $utils.stringify(ret) - // only check for command enqueuing when none - // of our args are functions else commands - // like cy.then or cy.each would always fail - // since they return promises and queue more - // new commands - if ($utils.noArgsAreAFunction(args)) { - Cypress.once('command:enqueued', commandEnqueued) - } + // if we got a return value and we enqueued + // a new command and we didn't return cy + // or an undefined value then throw + $errUtils.throwErrByPath( + 'miscellaneous.returned_value_and_commands_from_custom_command', { + args: { current: name, returned: ret }, + }, + ) + } + + return ret + }) + .then((subject) => { + // we may be given a regular array here so + // we need to re-wrap the array in jquery + // if that's the case if the first item + // in this subject is a jquery element. + // we want to do this because in 3.1.2 there + // was a regression when wrapping an array of elements + const firstSubject = $utils.unwrapFirst(subject) + + // if ret is a DOM element and its not an instance of our own jQuery + if (subject && $dom.isElement(firstSubject) && !$utils.isInstanceOf(subject, $)) { + // set it back to our own jquery object + // to prevent it from being passed downstream + // TODO: enable turning this off + // wrapSubjectsInJquery: false + // which will just pass subjects downstream + // without modifying them + subject = $dom.wrap(subject) + } - args = [command.get('chainerId'), ...args] + command.set({ subject }) + command.pass() - // run the command's fn with runnable's context - try { - command.start() - subject = __stackReplacementMarker(command.get('fn'), args) + // end / snapshot our logs if they need it + command.finishLogs() - // Queries return a function which takes the current subject and returns the next subject. We wrap this in - // retryQuery() - and let it retry until it passes, times out or is cancelled. - // We save the original return value on the $Command though - it's what gets added to the subject chain later. if (isQuery) { - command.set('queryFn', subject) - subject = retryQuery(command, subject, this.cy) + subject = command.get('queryFn') + // For queries, the "subject" here is the query's return value, which is a function which + // accepts a subject and returns a subject, and can be re-invoked at any time. + + subject.commandName = name + subject.args = command.get('args') + + // Even though we've snapshotted, we only end the logs a query's logs if we're at the end of a query + // chain - either there is no next command (end of a test), the next command is an action, or the next + // command belongs to another chainer (end of a chain). + + // This is done so that any query's logs remain in the 'pending' state until the subject chain is finished. + this.cy.addQueryToChainer(command.get('chainerId'), subject) + } else { + // For commands, the "subject" here is the command's return value, which replaces + // the current subject chain. We cannot re-invoke commands - the return value here is final. + this.cy.setSubjectForChainer(command.get('chainerId'), [subject]) } - } catch (err) { - throw err - } finally { - // always remove this listener - Cypress.removeListener('command:enqueued', commandEnqueued) - } - - this.state('commandIntermediateValue', subject) - // we cannot pass our cypress instance or our chainer - // back into bluebird else it will create a thenable - // which is never resolved - if (this.cy.isCy(subject)) { - return null - } + // TODO: This line was causing subjects to be cleaned up prematurely in some instances (Specifically seen on the within command) + // The command log would print the yielded value as null if checked outside of the current command chain. + // this.cleanSubjects() - if (!(!enqueuedCmd || !$utils.isPromiseLike(subject))) { - $errUtils.throwErrByPath( - 'miscellaneous.command_returned_promise_and_commands', { - args: { - current: name, - called: enqueuedCmd.name, - }, - }, - ) - } + this.state({ + commandIntermediateValue: undefined, + // reset the nestedIndex back to null + nestedIndex: null, + // we're finished with the current command so set it back to null + current: null, + }) - if (!(!enqueuedCmd || !!_.isUndefined(subject))) { - subject = _.isFunction(subject) ? - subject.toString() : - $utils.stringify(subject) - - // if we got a return value and we enqueued - // a new command and we didn't return cy - // or an undefined value then throw - $errUtils.throwErrByPath( - 'miscellaneous.returned_value_and_commands_from_custom_command', { - args: { current: name, returned: subject }, + const duration = performance.now() - startTime + const numElements = subject?.length ?? 0 + + return Cypress.automation('log:command:performance', { + name: command?.attributes?.name ?? 'unknown', + startTime, + duration, + detail: { + runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', + spec: Cypress.spec.relative, + numElements, }, - ) - } - - // we may be given a regular array here so - // we need to re-wrap the array in jquery - // if that's the case if the first item - // in this subject is a jquery element. - // we want to do this because in 3.1.2 there - // was a regression when wrapping an array of elements - const firstSubject = $utils.unwrapFirst(subject) - - // if ret is a DOM element and its not an instance of our own jQuery - if (subject && $dom.isElement(firstSubject) && !$utils.isInstanceOf(subject, $)) { - // set it back to our own jquery object - // to prevent it from being passed downstream - // TODO: enable turning this off - // wrapSubjectsInJquery: false - // which will just pass subjects downstream - // without modifying them - subject = $dom.wrap(subject) - } - - command.set({ subject }) - command.pass() - - const numElements = isJquery(subject) ? subject.length : 0 - - // end / snapshot our logs if they need it - command.finishLogs() - - if (isQuery) { - subject = command.get('queryFn') - // For queries, the "subject" here is the query's return value, which is a function which - // accepts a subject and returns a subject, and can be re-invoked at any time. - - subject.commandName = name - subject.args = command.get('args') - - // Even though we've snapshotted, we only end the logs a query's logs if we're at the end of a query - // chain - either there is no next command (end of a test), the next command is an action, or the next - // command belongs to another chainer (end of a chain). - - // This is done so that any query's logs remain in the 'pending' state until the subject chain is finished. - this.cy.addQueryToChainer(command.get('chainerId'), subject) - } else { - // For commands, the "subject" here is the command's return value, which replaces - // the current subject chain. We cannot re-invoke commands - the return value here is final. - this.cy.setSubjectForChainer(command.get('chainerId'), [subject]) - } - - // TODO: This line was causing subjects to be cleaned up prematurely in some instances (Specifically seen on the within command) - // The command log would print the yielded value as null if checked outside of the current command chain. - // this.cleanSubjects() - - this.state({ - commandIntermediateValue: undefined, - // reset the nestedIndex back to null - nestedIndex: null, - // we're finished with the current command so set it back to null - current: null, - }) - - const duration = performance.now() - startTime - - await Cypress.automation('log:command:performance', { - name: command?.attributes?.name ?? 'unknown', - startTime, - duration, - detail: { - runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', - spec: Cypress.spec.relative, - numElements, - }, + }).then(() => subject) }) - - return subject } // TypeScript doesn't allow overriding functions with different type signatures diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index 9bcef9563e5..6374e86dfc6 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -83,10 +83,9 @@ export function recordPerformanceEntry (entry: CommandPerformanceEntry) { ].map(escapeCsvValue).join(',') try { - fsSync.writeFile( + fsSync.appendFileSync( path.join(logFilePath(), 'performance.log'), `${row}\n`, - { flag: 'a' }, ) } catch (error) { debug('error recording performance entry: %s', error) From 8b4879c7616f63baddfcebfa335f5b1bd9a5cf54 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Thu, 20 Nov 2025 10:41:13 -0500 Subject: [PATCH 10/12] dont throw if automation throws --- packages/driver/src/cypress/command_queue.ts | 28 ++++++++++++-------- 1 file changed, 17 insertions(+), 11 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index dcebb0fac73..7aaa93cbafc 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -341,7 +341,7 @@ export class CommandQueue extends Queue<$Command> { return ret }) - .then((subject) => { + .then(async (subject) => { // we may be given a regular array here so // we need to re-wrap the array in jquery // if that's the case if the first item @@ -402,16 +402,22 @@ export class CommandQueue extends Queue<$Command> { const duration = performance.now() - startTime const numElements = subject?.length ?? 0 - return Cypress.automation('log:command:performance', { - name: command?.attributes?.name ?? 'unknown', - startTime, - duration, - detail: { - runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', - spec: Cypress.spec.relative, - numElements, - }, - }).then(() => subject) + try { + await Cypress.automation('log:command:performance', { + name: command?.attributes?.name ?? 'unknown', + startTime, + duration, + detail: { + runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', + spec: Cypress.spec.relative, + numElements, + }, + }) + } catch (err) { + debugErrors('error logging command performance: %o', err) + } + + return subject }) } From 0e83cccf816dd4286857bce69733d54a8440673e Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Thu, 20 Nov 2025 12:48:50 -0500 Subject: [PATCH 11/12] rm numElements - causes serialization issues?? --- packages/driver/src/cypress/command_queue.ts | 2 -- .../lib/automation/commands/record_performance_entry.ts | 4 ---- packages/types/src/server.ts | 1 - system-tests/test/web_security_spec.js | 2 +- 4 files changed, 1 insertion(+), 8 deletions(-) diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 7aaa93cbafc..9bdebbde81f 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -400,7 +400,6 @@ export class CommandQueue extends Queue<$Command> { }) const duration = performance.now() - startTime - const numElements = subject?.length ?? 0 try { await Cypress.automation('log:command:performance', { @@ -410,7 +409,6 @@ export class CommandQueue extends Queue<$Command> { detail: { runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', spec: Cypress.spec.relative, - numElements, }, }) } catch (err) { diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts index 6374e86dfc6..bee7960c81e 100644 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ b/packages/server/lib/automation/commands/record_performance_entry.ts @@ -1,7 +1,6 @@ import Debug from 'debug' import type { CommandPerformanceEntry } from '@packages/types' import path from 'path' -import fs from 'fs/promises' import fsSync from 'fs' const debug = Debug('cypress-verbose:server:automation:commands:record_performance_entry') @@ -18,7 +17,6 @@ const COLUMNS = [ 'startTime', 'duration', 'name', - 'numElements', 'runnableTitle', 'spec', ] @@ -67,7 +65,6 @@ export function recordPerformanceEntry (entry: CommandPerformanceEntry) { duration, name, detail: { - numElements, runnableTitle, spec, }, @@ -77,7 +74,6 @@ export function recordPerformanceEntry (entry: CommandPerformanceEntry) { startTime, duration, name, - numElements, runnableTitle, spec, ].map(escapeCsvValue).join(',') diff --git a/packages/types/src/server.ts b/packages/types/src/server.ts index a0d7b20c8e0..cc092fee2ac 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -132,7 +132,6 @@ export interface CommandPerformanceEntry { detail: { runnableTitle: string spec: string - numElements: number } } diff --git a/system-tests/test/web_security_spec.js b/system-tests/test/web_security_spec.js index 772d3a501d3..c1b2d8a9bf6 100644 --- a/system-tests/test/web_security_spec.js +++ b/system-tests/test/web_security_spec.js @@ -72,7 +72,7 @@ describe('e2e web security', () => { context('when enabled', () => { systemTests.it('fails', { - browser: '!webkit', // TODO(webkit): fix+unskip + browser: 'chrome', // TODO(webkit): fix+unskip spec: 'web_security.cy.js', config: { pageLoadTimeout: 5000, From 7084eafc4afc6d19c7044e5973f40de0701b4835 Mon Sep 17 00:00:00 2001 From: Cacie Prins Date: Fri, 21 Nov 2025 15:30:03 -0500 Subject: [PATCH 12/12] refactor to performance marks, clean up telemetry on the client, make log writer more resiliant --- packages/app/src/runner/events/telemetry.ts | 205 +++++--- packages/driver/src/cypress/command_queue.ts | 18 - packages/server/lib/automation/automation.ts | 4 +- .../automation/automation_not_implemented.ts | 2 +- .../commands/record_performance_entry.ts | 89 ---- .../lib/automation/performance_logger.ts | 159 ++++++ .../server/lib/browsers/bidi_automation.ts | 3 +- .../server/lib/browsers/cdp_automation.ts | 7 +- packages/server/lib/cypress.ts | 9 +- packages/server/lib/modes/index.ts | 3 - packages/server/lib/modes/interactive.ts | 8 +- .../automation/performance_logger_spec.ts | 469 ++++++++++++++++++ packages/types/src/server.ts | 4 - 13 files changed, 772 insertions(+), 208 deletions(-) delete mode 100644 packages/server/lib/automation/commands/record_performance_entry.ts create mode 100644 packages/server/lib/automation/performance_logger.ts create mode 100644 packages/server/test/unit/automation/performance_logger_spec.ts diff --git a/packages/app/src/runner/events/telemetry.ts b/packages/app/src/runner/events/telemetry.ts index 013d8bc132f..5542dfb76b8 100644 --- a/packages/app/src/runner/events/telemetry.ts +++ b/packages/app/src/runner/events/telemetry.ts @@ -1,104 +1,149 @@ import { telemetry } from '@packages/telemetry/browser/client' -export const addTelemetryListeners = (Cypress: Cypress.Cypress) => { - Cypress.on('test:before:run', (attributes, test) => { - // we emit the 'test:before:run' events within various driver tests - try { - // If a span for a previous test hasn't been ended, end it before starting the new test span - const previousTestSpan = telemetry.findActiveSpan((span) => { - return span.name.startsWith('test:') - }) - - if (previousTestSpan) { - telemetry.endActiveSpanAndChildren(previousTestSpan) - } +function startTestOtelSpan (attributes: Cypress.ObjectLike, test: Mocha.Test) { + // we emit the 'test:before:run' events within various driver tests + try { + // If a span for a previous test hasn't been ended, end it before starting the new test span + const previousTestSpan = telemetry.findActiveSpan((span) => { + return span.name.startsWith('test:') + }) + + if (previousTestSpan) { + telemetry.endActiveSpanAndChildren(previousTestSpan) + } - const span = telemetry.startSpan({ name: `test:${test.fullTitle()}`, active: true }) + const span = telemetry.startSpan({ name: `test:${test.fullTitle()}`, active: true }) - span?.setAttributes({ - currentRetry: attributes.currentRetry, - }) - } catch (error) { - // TODO: log error when client side debug logging is available - } - }) + span?.setAttributes({ + currentRetry: attributes.currentRetry, + }) + } catch (error) { + // TODO: log error when client side debug logging is available + } +} - Cypress.on('test:after:run', (attributes, test) => { - try { - const span = telemetry.getSpan(`test:${test.fullTitle()}`) +function endTestOtelSpan (attributes: Cypress.ObjectLike, test: Mocha.Test) { + try { + const span = telemetry.getSpan(`test:${test.fullTitle()}`) - span?.setAttributes({ - timings: JSON.stringify(attributes.timings), - }) + span?.setAttributes({ + timings: JSON.stringify(attributes.timings), + }) - span?.end() - } catch (error) { - // TODO: log error when client side debug logging is available - } - }) + span?.end() + } catch (error) { + // TODO: log error when client side debug logging is available + } +} - const commandSpanInfo = (command: Cypress.CommandQueue) => { - const runnable = Cypress.state('runnable') - const runnableType = runnable.type === 'hook' ? runnable.hookName : runnable.type +const commandSpanInfo = (command: Cypress.CommandQueue) => { + const runnable = Cypress.state('runnable') + const runnableType = runnable.type === 'hook' ? runnable.hookName : runnable.type - return { - name: `${runnableType}: ${command.attributes.name}(${command.attributes.args.join(',')})`, - runnable, - runnableType, - } + return { + name: `${runnableType}: ${command.attributes.name}(${command.attributes.args.join(',')})`, + runnable, + runnableType, } +} - Cypress.on('command:start', (command: Cypress.CommandQueue) => { - try { - const test = Cypress.state('test') - - const { name, runnable, runnableType } = commandSpanInfo(command) - - const span = telemetry.startSpan({ - name, - opts: { - attributes: { - spec: runnable.invocationDetails.relativeFile, - test: `test:${test.fullTitle()}`, - 'runnable-type': runnableType, - }, +function startCommandOtelSpan (command: Cypress.CommandQueue) { + try { + const test = Cypress.state('test') + + const { name, runnable, runnableType } = commandSpanInfo(command) + + const span = telemetry.startSpan({ + name, + opts: { + attributes: { + spec: runnable.invocationDetails.relativeFile, + test: `test:${test.fullTitle()}`, + 'runnable-type': runnableType, }, - isVerbose: true, - }) + }, + isVerbose: true, + }) - span?.setAttribute('command-name', command.attributes.name) - } catch (error) { - // TODO: log error when client side debug logging is available - } - }) + span?.setAttribute('command-name', command.attributes.name) + } catch (error) { + // TODO: log error when client side debug logging is available + } +} - const onCommandEnd = (command: Cypress.CommandQueue) => { - try { - const span = telemetry.getSpan(commandSpanInfo(command).name) +function endCommandOtelSpan (command: Cypress.CommandQueue) { + try { + const span = telemetry.getSpan(commandSpanInfo(command).name) - span?.setAttribute('state', command.state) - span?.setAttribute('numLogs', command.logs?.length || 0) - span?.end() - } catch (error) { - // TODO: log error when client side debug logging is available - } + span?.setAttribute('state', command.state) + span?.setAttribute('numLogs', command.logs?.length || 0) + span?.end() + } catch (error) { + // TODO: log error when client side debug logging is available } +} - Cypress.on('command:end', onCommandEnd) +function failCommandOtelSpan (command: Cypress.CommandQueue, error: Error) { + try { + const span = telemetry.getSpan(commandSpanInfo(command).name) - Cypress.on('skipped:command:end', onCommandEnd) + span?.setAttribute('state', command.state) + span?.setAttribute('numLogs', command.logs?.length || 0) + span?.setAttribute('error.name', error.name) + span?.setAttribute('error.message', error.message) + span?.end() + } catch (error) { + // TODO: log error when client side debug logging is available + } +} - Cypress.on('command:failed', (command: Cypress.CommandQueue, error: Error) => { +function startCommandPerformanceMark (command: Cypress.CommandQueue) { + try { + performance.mark(`cy:command:${command.attributes.id}:start`) + } catch (error) { + // TODO: log error when client side debug logging is available + } +} + +function endCommandPerformanceMark (Cypress: Cypress.Cypress) { + return (command: Cypress.CommandQueue) => { try { - const span = telemetry.getSpan(commandSpanInfo(command).name) + const { id } = command.attributes + + performance.mark(`cy:command:${id}:end`) + const measure = performance.measure(`cy:command:${id}:measure`, { + start: `cy:command:${id}:start`, + end: `cy:command:${id}:end`, + }) + + if (!measure) { + return + } - span?.setAttribute('state', command.state) - span?.setAttribute('numLogs', command.logs?.length || 0) - span?.setAttribute('error.name', error.name) - span?.setAttribute('error.message', error.message) - span?.end() + Cypress.automation('log:command:performance', { + name: command.attributes.name, + startTime: measure.startTime, + duration: measure.duration, + }).catch(() => {}).finally(() => { + performance.clearMarks(`cy:command:${id}:start`) + performance.clearMarks(`cy:command:${id}:end`) + performance.clearMeasures(`cy:command:${id}:measure`) + }) } catch (error) { - // TODO: log error when client side debug logging is available + // noop } - }) + } +} + +export const addTelemetryListeners = (Cypress: Cypress.Cypress) => { + Cypress.on('test:before:run', startTestOtelSpan) + Cypress.on('test:after:run', endTestOtelSpan) + Cypress.on('command:start', startCommandOtelSpan) + Cypress.on('command:end', endCommandOtelSpan) + Cypress.on('command:failed', failCommandOtelSpan) + Cypress.on('skipped:command:end', endCommandOtelSpan) + + Cypress.on('command:start', startCommandPerformanceMark) + Cypress.on('command:end', endCommandPerformanceMark(Cypress)) + Cypress.on('skipped:command:end', endCommandPerformanceMark(Cypress)) } diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts index 9bdebbde81f..d4f3472b625 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -229,8 +229,6 @@ export class CommandQueue extends Queue<$Command> { } private runCommand (command: $Command) { - const startTime = performance.now() - const isQuery = command.get('query') const name = command.get('name') @@ -399,22 +397,6 @@ export class CommandQueue extends Queue<$Command> { current: null, }) - const duration = performance.now() - startTime - - try { - await Cypress.automation('log:command:performance', { - name: command?.attributes?.name ?? 'unknown', - startTime, - duration, - detail: { - runnableTitle: (this.state('runnable') ?? {}).title ?? 'unknown', - spec: Cypress.spec.relative, - }, - }) - } catch (err) { - debugErrors('error logging command performance: %o', err) - } - return subject }) } diff --git a/packages/server/lib/automation/automation.ts b/packages/server/lib/automation/automation.ts index fdafb87f8f8..b6c291affb2 100644 --- a/packages/server/lib/automation/automation.ts +++ b/packages/server/lib/automation/automation.ts @@ -8,7 +8,7 @@ import { cookieJar } from '../util/cookies' import type { ServiceWorkerEventHandler } from '@packages/proxy/lib/http/util/service-worker-manager' import Debug from 'debug' import { AutomationNotImplemented } from './automation_not_implemented' -import { recordPerformanceEntry } from './commands/record_performance_entry' +import { PerformanceLogger } from './performance_logger' const debug = Debug('cypress:server:automation') @@ -176,7 +176,7 @@ export class Automation { case 'complete:download': return data case 'log:command:performance': - return recordPerformanceEntry(data) + return PerformanceLogger.write(data) default: return automate(data) } diff --git a/packages/server/lib/automation/automation_not_implemented.ts b/packages/server/lib/automation/automation_not_implemented.ts index 50e12b3aa48..e3a05538d9e 100644 --- a/packages/server/lib/automation/automation_not_implemented.ts +++ b/packages/server/lib/automation/automation_not_implemented.ts @@ -2,7 +2,7 @@ const AutomationNotImplementedKind = 'AutomationNotImplemented' export class AutomationNotImplemented extends Error { readonly kind = AutomationNotImplementedKind - constructor (message: string, automationType: string, ...args) { + constructor (message: any, automationType: string, ...args) { super(`Automation command '${message}' not implemented by ${automationType}`) } diff --git a/packages/server/lib/automation/commands/record_performance_entry.ts b/packages/server/lib/automation/commands/record_performance_entry.ts deleted file mode 100644 index bee7960c81e..00000000000 --- a/packages/server/lib/automation/commands/record_performance_entry.ts +++ /dev/null @@ -1,89 +0,0 @@ -import Debug from 'debug' -import type { CommandPerformanceEntry } from '@packages/types' -import path from 'path' -import fsSync from 'fs' - -const debug = Debug('cypress-verbose:server:automation:commands:record_performance_entry') - -function logFilePath () { - return process.env.CYPRESS_INTERNAL_PERFORMANCE_LOG_FILE_PATH ?? path.join(process.cwd(), 'cypress', 'logs') -} - -function performanceLogsEnabled () { - return ['1', 'true'].includes(process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING ?? 'false') -} - -const COLUMNS = [ - 'startTime', - 'duration', - 'name', - 'runnableTitle', - 'spec', -] - -/** - * Escapes a value for CSV format according to RFC 4180. - * - If the value contains comma, newline, or double quote, wrap it in double quotes - * - Escape any double quotes within the value by doubling them - */ -function escapeCsvValue (value: string | number): string { - const stringValue = String(value) - - // If value contains comma, newline, or double quote, wrap in quotes - if (stringValue.includes(',') || stringValue.includes('\n') || stringValue.includes('"')) { - // Escape double quotes by doubling them - return `"${stringValue.replace(/"/g, '""')}"` - } - - return stringValue -} - -export function initializePerformanceLogFile () { - try { - if (!performanceLogsEnabled()) { - return - } - - debug('initializing performance log file: %s', path.join(logFilePath(), 'performance.log')) - - fsSync.mkdirSync(logFilePath(), { recursive: true }) - fsSync.writeFileSync(path.join(logFilePath(), 'performance.log'), `${COLUMNS.join(',')}\n`, { flag: 'w' }) - } catch (error) { - debug('error initializing performance log file: %s', error) - } -} - -export function recordPerformanceEntry (entry: CommandPerformanceEntry) { - debug('recording performance entry %o', entry) - - if (!performanceLogsEnabled()) { - return - } - - const { - startTime, - duration, - name, - detail: { - runnableTitle, - spec, - }, - } = entry - - const row = [ - startTime, - duration, - name, - runnableTitle, - spec, - ].map(escapeCsvValue).join(',') - - try { - fsSync.appendFileSync( - path.join(logFilePath(), 'performance.log'), - `${row}\n`, - ) - } catch (error) { - debug('error recording performance entry: %s', error) - } -} diff --git a/packages/server/lib/automation/performance_logger.ts b/packages/server/lib/automation/performance_logger.ts new file mode 100644 index 00000000000..3b091af7c7f --- /dev/null +++ b/packages/server/lib/automation/performance_logger.ts @@ -0,0 +1,159 @@ +import { randomUUID } from 'crypto' +import { createWriteStream, writeFileSync, mkdirSync } from 'fs' +import path from 'path' + +import Debug from 'debug' + +import type { CommandPerformanceEntry } from '@packages/types' +import type { WriteStream } from 'fs' + +const debugVerbose = Debug('cypress-verbose:server:automation:performance-logger') +const debug = Debug('cypress:server:automation:performance-logger') +const commandPerformanceDebug = Debug('cypress-verbose:performance:command') + +export class PerformanceLogger { + static get enabled (): boolean { + return ['1', 'true'].includes(process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING ?? 'false') + } + + static async close (): Promise { + if (!PerformanceLogger.enabled) { + return + } + + try { + await this.instance?.close() + } catch (error) { + debug('error closing performance logger: %s', error) + } + } + + static async write (entry: CommandPerformanceEntry): Promise { + if (PerformanceLogger.enabled) { + try { + await this.instance?.write(entry) + } catch (error) { + debugVerbose('error writing performance entry: %s', error) + } + } + + if (commandPerformanceDebug.enabled) { + try { + this.instance?.writeToDebugger(entry) + } catch (error) { + debugVerbose('error writing performance entry to debugger: %s', error) + } + } + } + + private static _instance: PerformanceLogger | undefined = undefined + + private static get instance () { + if (!PerformanceLogger._instance && PerformanceLogger.enabled) { + PerformanceLogger._instance = new PerformanceLogger() + } + + return PerformanceLogger._instance + } + + private logWriter: WriteStream | undefined = undefined + private readonly columns: (keyof CommandPerformanceEntry)[] = [ + 'startTime', + 'duration', + 'name', + ] + + private commandDebuggers: Map> = new Map() + + private backpressurePause: Promise | undefined = undefined + + private constructor () { + const filePath = path.join(process.cwd(), 'cypress', 'logs') + const fileName = `performance-${randomUUID()}.csv` + + mkdirSync(filePath, { recursive: true }) + writeFileSync(path.join(filePath, fileName), `${this.columns.join(',')}\n`, { flag: 'w' }) + this.logWriter = createWriteStream(path.join(filePath, fileName), { flags: 'a' }) + this.logWriter.on('error', (err) => { + debugVerbose('error writing performance entry: %s', err) + }) + } + + private async write (entry: CommandPerformanceEntry): Promise { + if (this.logWriter?.closed) { + debugVerbose('log writer is closed, skipping write') + + return + } + + if (this.backpressurePause) { + await this.backpressurePause + this.backpressurePause = undefined + } + + const row = this.columns.map((column) => this.escapeCsvValue(entry[column])).join(',') + + const canWrite = this.logWriter?.write(`${row}\n`) + + if (!canWrite) { + this.backpressurePause = this.backpressurePause ?? new Promise((resolve) => { + this.logWriter?.once('drain', () => { + resolve() + }) + }) + } + } + + private writeToDebugger (entry: CommandPerformanceEntry): void { + if (!this.commandDebuggers.has(entry.name)) { + this.commandDebuggers.set(entry.name, Debug(`${commandPerformanceDebug.namespace}:${entry.name}`)) + } + + this.commandDebuggers.get(entry.name)?.('%d ms', entry.duration) + } + + private async close (): Promise { + if (this.logWriter?.closed || !this.logWriter) { + return + } + + const cleanup = () => { + this.logWriter?.removeAllListeners() + this.logWriter = undefined + } + + return Promise.race([ + new Promise((resolve) => { + this.logWriter?.once('close', () => { + cleanup() + resolve() + }) + + this.logWriter?.end() + }), + new Promise((resolve) => { + setTimeout(() => { + cleanup() + resolve() + }, 5000) + }), + ]) + } + + /** + * Escapes a value for CSV format according to RFC 4180. + * - If the value contains comma, newline, or double quote, wrap it in double quotes + * - Escape any double quotes within the value by doubling them + */ + private escapeCsvValue (value: string | number): string { + const stringValue = String(value) + + // If value contains comma, newline, or double quote, wrap in quotes + if (stringValue.includes(',') || stringValue.includes('\n') || stringValue.includes('"')) { + // Escape double quotes by doubling them + return `"${stringValue.replace(/"/g, '""')}"` + } + + return stringValue + } +} diff --git a/packages/server/lib/browsers/bidi_automation.ts b/packages/server/lib/browsers/bidi_automation.ts index ccc2edc70cd..019969c7cbb 100644 --- a/packages/server/lib/browsers/bidi_automation.ts +++ b/packages/server/lib/browsers/bidi_automation.ts @@ -25,7 +25,6 @@ import { bidiGetUrl } from '../automation/commands/get_url' import { bidiReloadFrame } from '../automation/commands/reload_frame' import { bidiNavigateHistory } from '../automation/commands/navigate_history' import { bidiGetFrameTitle } from '../automation/commands/get_frame_title' -import { recordPerformanceEntry } from '../automation/commands/record_performance_entry' import type { StorageCookieFilter, StoragePartialCookie as BidiStoragePartialCookie } from 'webdriver/build/bidi/remoteTypes' @@ -729,7 +728,7 @@ export class BidiAutomation { throw new Error('Cannot get AUT title no AUT context initialized') } case 'log:command:performance': - return recordPerformanceEntry(data) + return PerformanceLogger.write(data) default: debug('BiDi automation not implemented for message: %s', message) throw new AutomationNotImplemented(message, 'BiDiAutomation') diff --git a/packages/server/lib/browsers/cdp_automation.ts b/packages/server/lib/browsers/cdp_automation.ts index dff3dd8bbd6..02b9d53bb25 100644 --- a/packages/server/lib/browsers/cdp_automation.ts +++ b/packages/server/lib/browsers/cdp_automation.ts @@ -8,7 +8,6 @@ import { parseDomain, isLocalhost as isLocalhostNetworkTools } from '@packages/n import debugModule from 'debug' import { URL } from 'url' import { performance } from 'perf_hooks' -import { recordPerformanceEntry } from '../automation/commands/record_performance_entry' import type { ResourceType, BrowserPreRequest, BrowserResponseReceived } from '@packages/proxy' import type { CDPClient, ProtocolManagerShape, WriteVideoFrame, AutomationMiddleware, AutomationCommands } from '@packages/types' import type { Automation } from '../automation' @@ -23,6 +22,7 @@ import { cdpGetUrl } from '../automation/commands/get_url' import { cdpReloadFrame } from '../automation/commands/reload_frame' import { cdpNavigateHistory } from '../automation/commands/navigate_history' import { cdpGetFrameTitle } from '../automation/commands/get_frame_title' +import { AutomationNotImplemented } from '../automation/automation_not_implemented' export type CdpCommand = keyof ProtocolMapping.Commands @@ -662,10 +662,9 @@ export class CdpAutomation implements CDPClient, AutomationMiddleware { return cdpNavigateHistory(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame(), data.historyNumber) case 'get:aut:title': return cdpGetFrameTitle(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame()) - case 'log:command:performance': - return recordPerformanceEntry(data) default: - throw new Error(`No automation handler registered for: '${message}'`) + debugVerbose('CDP automation not implemented for message: %s', message) + throw new AutomationNotImplemented(message, 'CDPAutomation') } } } diff --git a/packages/server/lib/cypress.ts b/packages/server/lib/cypress.ts index eb91c46f0a4..fcf142f450a 100644 --- a/packages/server/lib/cypress.ts +++ b/packages/server/lib/cypress.ts @@ -17,6 +17,7 @@ import { warning as errorsWarning } from './errors' import { getCwd } from './cwd' import type { CypressError } from '@packages/errors' import { toNumber } from 'lodash' +import { PerformanceLogger } from './automation/performance_logger' const debug = Debug('cypress:server:cypress') type Mode = 'exit' | 'info' | 'interactive' | 'pkg' | 'record' | 'results' | 'run' | 'smokeTest' | 'version' | 'returnPkg' | 'exitWithCode' @@ -38,9 +39,11 @@ const exit = async (code = 0) => { span?.setAttribute('exitCode', code) span?.end() - await telemetry.shutdown().catch((err: any) => { - debug('telemetry shutdown errored with: ', err) - }) + try { + await Promise.all([telemetry.shutdown(), PerformanceLogger.close()]) + } catch (error) { + debug('error shutting down telemetry or performance logger: %s', error) + } debug('process.exit', code) diff --git a/packages/server/lib/modes/index.ts b/packages/server/lib/modes/index.ts index 2873eacdf91..5300c6473e3 100644 --- a/packages/server/lib/modes/index.ts +++ b/packages/server/lib/modes/index.ts @@ -4,7 +4,6 @@ import _ from 'lodash' import { makeDataContext } from '../makeDataContext' import { id as randomId } from '../util/random' import { telemetry } from '@packages/telemetry' -import { initializePerformanceLogFile } from '../automation/commands/record_performance_entry' export = (mode, options) => { if (mode === 'smokeTest') { @@ -26,8 +25,6 @@ export = (mode, options) => { const span = telemetry.startSpan({ name: `initialize:mode:${mode}` }) - initializePerformanceLogFile() - const ctx = setCtx(makeDataContext({ mode: mode === 'run' ? mode : 'open', modeOptions: options })) telemetry.getSpan('cypress')?.setAttribute('name', `cypress:${mode}`) diff --git a/packages/server/lib/modes/interactive.ts b/packages/server/lib/modes/interactive.ts index 484eeb45b4c..45352b0f285 100644 --- a/packages/server/lib/modes/interactive.ts +++ b/packages/server/lib/modes/interactive.ts @@ -10,7 +10,7 @@ import * as Windows from '../gui/windows' import { makeGraphQLServer } from '@packages/data-context/graphql/makeGraphQLServer' import { globalPubSub, getCtx, clearCtx } from '@packages/data-context' import { telemetry } from '@packages/telemetry' - +import { PerformanceLogger } from '../automation/performance_logger' // tslint:disable-next-line no-implicit-dependencies - electron dep needs to be defined import type { WebContents } from 'electron' import type { LaunchArgs, Preferences } from '@packages/types' @@ -202,7 +202,11 @@ export = { telemetry.getSpan('cypress')?.end() - await telemetry.shutdown() + try { + await Promise.all([telemetry.shutdown(), PerformanceLogger.close()]) + } catch (error) { + debug('error shutting down telemetry or performance logger: %s', error) + } app.quit() }) diff --git a/packages/server/test/unit/automation/performance_logger_spec.ts b/packages/server/test/unit/automation/performance_logger_spec.ts new file mode 100644 index 00000000000..f48545fc9b3 --- /dev/null +++ b/packages/server/test/unit/automation/performance_logger_spec.ts @@ -0,0 +1,469 @@ +import { expect } from '../../spec_helper' +import sinon from 'sinon' +import type { CommandPerformanceEntry } from '@packages/types' + +import { PerformanceLogger } from '../../../lib/automation/performance_logger' + +describe('lib/automation/performance_logger', () => { + let originalEnv: string | undefined + let mockWriteStream: any + let mkdirSyncStub: sinon.SinonStub + let writeFileSyncStub: sinon.SinonStub + let createWriteStreamStub: sinon.SinonStub + let randomUUIDStub: sinon.SinonStub + + beforeEach(function () { + // Save original env var + originalEnv = process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING + + // Reset singleton instance + ;(PerformanceLogger as any)._instance = undefined + + // Create mock write stream + mockWriteStream = { + write: sinon.stub().returns(true), + end: sinon.stub().returns(mockWriteStream), + once: sinon.stub().returns(mockWriteStream), + on: sinon.stub().returns(mockWriteStream), + emit: sinon.stub(), + removeAllListeners: sinon.stub(), + closed: false, + } + + // Mock fs operations + const fs = require('fs') + + mkdirSyncStub = sinon.stub(fs, 'mkdirSync').returns(undefined) + writeFileSyncStub = sinon.stub(fs, 'writeFileSync').returns(undefined) + createWriteStreamStub = sinon.stub(fs, 'createWriteStream').returns(mockWriteStream) + + // Mock randomUUID + const crypto = require('crypto') + + randomUUIDStub = sinon.stub(crypto, 'randomUUID').returns('test-uuid-123') + }) + + afterEach(function () { + // Restore original env var + if (originalEnv !== undefined) { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = originalEnv + } else { + delete process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING + } + + // Clean up singleton + return PerformanceLogger.close().then(() => { + ;(PerformanceLogger as any)._instance = undefined + }).finally(() => { + // Restore all stubs + sinon.restore() + }) + }) + + describe('.enabled', () => { + it('returns false when env var is not set', () => { + delete process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING + + expect(PerformanceLogger.enabled).to.be.false + }) + + it('returns false when env var is "false"', () => { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = 'false' + + expect(PerformanceLogger.enabled).to.be.false + }) + + it('returns true when env var is "1"', () => { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = '1' + + expect(PerformanceLogger.enabled).to.be.true + }) + + it('returns true when env var is "true"', () => { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = 'true' + + expect(PerformanceLogger.enabled).to.be.true + }) + }) + + describe('.write', () => { + context('when enabled', () => { + beforeEach(function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = '1' + }) + + it('creates directory and file with CSV header on first write', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mkdirSyncStub).to.be.called + expect(writeFileSyncStub).to.be.called + const headerCall = writeFileSyncStub.getCall(0) + + expect(headerCall.args[1]).to.equal('startTime,duration,name\n') + }) + + it('writes entry to stream', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000.5, + duration: 50.25, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.write).to.be.called + const writeCall = mockWriteStream.write.getCall(0) + + expect(writeCall.args[0]).to.equal('1000.5,50.25,test-command\n') + }) + + it('handles multiple writes', async function () { + const entries: CommandPerformanceEntry[] = [ + { name: 'command1', startTime: 1000, duration: 50 }, + { name: 'command2', startTime: 1050, duration: 75 }, + ] + + for (const entry of entries) { + await PerformanceLogger.write(entry) + } + + expect(mockWriteStream.write).to.be.calledTwice + expect(mockWriteStream.write.getCall(0).args[0]).to.equal('1000,50,command1\n') + expect(mockWriteStream.write.getCall(1).args[0]).to.equal('1050,75,command2\n') + }) + + it('escapes commas in command names', async function () { + const entry: CommandPerformanceEntry = { + name: 'test,command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.write).to.be.called + const writeCall = mockWriteStream.write.getCall(0) + + expect(writeCall.args[0]).to.equal('1000,50,"test,command"\n') + }) + + it('escapes quotes in command names', async function () { + const entry: CommandPerformanceEntry = { + name: 'test"command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.write).to.be.called + const writeCall = mockWriteStream.write.getCall(0) + + expect(writeCall.args[0]).to.equal('1000,50,"test""command"\n') + }) + + it('escapes newlines in command names', async function () { + const entry: CommandPerformanceEntry = { + name: 'test\ncommand', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.write).to.be.called + const writeCall = mockWriteStream.write.getCall(0) + + expect(writeCall.args[0]).to.equal('1000,50,"test\ncommand"\n') + }) + + it('does not quote simple values', async function () { + const entry: CommandPerformanceEntry = { + name: 'simple-command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.write).to.be.called + const writeCall = mockWriteStream.write.getCall(0) + + expect(writeCall.args[0]).to.equal('1000,50,simple-command\n') + expect(writeCall.args[0]).to.not.include('"') + }) + + it('handles write errors gracefully', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + // Create instance first + await PerformanceLogger.write(entry) + + // Make instance write method throw + const instance = (PerformanceLogger as any)._instance + + sinon.stub(instance, 'write').rejects(new Error('write failed')) + + // Should not throw + await expect(PerformanceLogger.write(entry)).to.be.fulfilled + }) + + it('skips write when logWriter is closed', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + // Write once to create instance + await PerformanceLogger.write(entry) + + // Mark stream as closed + mockWriteStream.closed = true + + // Reset write call count + mockWriteStream.write.resetHistory() + + // Should not throw when writing to closed stream + await expect(PerformanceLogger.write(entry)).to.be.fulfilled + + // Write should not be called on closed stream + expect(mockWriteStream.write).to.not.be.called + }) + + it('waits for drain when buffer is full', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + // Write once to create instance + await PerformanceLogger.write(entry) + + // Force write to return false (buffer full) + mockWriteStream.write.returns(false) + + // Set up drain handler + let drainHandler: (() => void) | undefined + + mockWriteStream.once.callsFake((event: string, handler: () => void) => { + if (event === 'drain') { + drainHandler = handler + } + + return mockWriteStream + }) + + const writePromise = PerformanceLogger.write(entry) + + // Write should be pending + await new Promise((resolve) => setTimeout(resolve, 10)) + expect(drainHandler).to.exist + + // Emit drain event + if (drainHandler) { + drainHandler() + } + + await writePromise + expect(mockWriteStream.write).to.be.calledTwice + }) + }) + + context('when disabled', () => { + beforeEach(function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = 'false' + }) + + it('does not create log file', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mkdirSyncStub).to.not.be.called + expect(writeFileSyncStub).to.not.be.called + expect(createWriteStreamStub).to.not.be.called + }) + + it('does not throw', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + await expect(PerformanceLogger.write(entry)).to.be.fulfilled + }) + }) + }) + + describe('.close', () => { + context('when enabled', () => { + beforeEach(function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = '1' + }) + + it('closes the write stream', async function () { + const entry: CommandPerformanceEntry = { + name: 'test-command', + startTime: 1000, + duration: 50, + } + + await PerformanceLogger.write(entry) + + expect(mockWriteStream.end).to.not.be.called + + // Set up close event handler + let closeHandler: (() => void) | undefined + + mockWriteStream.once.callsFake((event: string, handler: () => void) => { + if (event === 'close') { + closeHandler = handler + } + + return mockWriteStream + }) + + const closePromise = PerformanceLogger.close() + + // Simulate close event + if (closeHandler) { + setTimeout(() => { + mockWriteStream.closed = true + closeHandler!() + }, 10) + } + + await closePromise + + expect(mockWriteStream.end).to.be.called + expect(mockWriteStream.removeAllListeners).to.be.called + }) + + it('handles close errors gracefully', async function () { + await PerformanceLogger.write({ + name: 'test', + startTime: 1000, + duration: 50, + }) + + const instance = (PerformanceLogger as any)._instance + + sinon.stub(instance, 'close').rejects(new Error('close failed')) + + await expect(PerformanceLogger.close()).to.be.fulfilled + }) + + it('times out after 5 seconds if stream does not close', async function () { + await PerformanceLogger.write({ + name: 'test', + startTime: 1000, + duration: 50, + }) + + // Prevent close event from firing + mockWriteStream.once.callsFake(() => mockWriteStream) + + const startTime = Date.now() + + await PerformanceLogger.close() + const duration = Date.now() - startTime + + // Should timeout around 5 seconds (with some tolerance) + expect(duration).to.be.at.least(4900) + expect(duration).to.be.at.most(5500) + }) + + it('returns immediately if stream is already closed', async function () { + await PerformanceLogger.write({ + name: 'test', + startTime: 1000, + duration: 50, + }) + + mockWriteStream.closed = true + + const startTime = Date.now() + + await PerformanceLogger.close() + const duration = Date.now() - startTime + + expect(duration).to.be.lessThan(100) + expect(mockWriteStream.end).to.not.be.called + }) + }) + + context('when disabled', () => { + beforeEach(function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = 'false' + }) + + it('returns immediately', async function () { + const startTime = Date.now() + + await PerformanceLogger.close() + const duration = Date.now() - startTime + + expect(duration).to.be.lessThan(100) + }) + }) + }) + + describe('singleton behavior', () => { + beforeEach(function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = '1' + }) + + it('creates single instance', async function () { + await PerformanceLogger.write({ + name: 'test1', + startTime: 1000, + duration: 50, + }) + + const instance1 = (PerformanceLogger as any)._instance + + await PerformanceLogger.write({ + name: 'test2', + startTime: 1050, + duration: 75, + }) + + const instance2 = (PerformanceLogger as any)._instance + + expect(instance1).to.equal(instance2) + expect(createWriteStreamStub).to.be.calledOnce + }) + + it('does not create instance when disabled', async function () { + process.env.CYPRESS_INTERNAL_COMMAND_PERFORMANCE_LOGGING = 'false' + + await PerformanceLogger.write({ + name: 'test', + startTime: 1000, + duration: 50, + }) + + const instance = (PerformanceLogger as any)._instance + + expect(instance).to.be.undefined + expect(createWriteStreamStub).to.not.be.called + }) + }) +}) diff --git a/packages/types/src/server.ts b/packages/types/src/server.ts index cc092fee2ac..4509a23312f 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -129,10 +129,6 @@ export interface CommandPerformanceEntry { name: string startTime: number duration: number - detail: { - runnableTitle: string - spec: string - } } export interface AutomationCommands {