diff --git a/cli/CHANGELOG.md b/cli/CHANGELOG.md index 06aff74eac8..88acb008a61 100644 --- a/cli/CHANGELOG.md +++ b/cli/CHANGELOG.md @@ -30,6 +30,7 @@ _Released 11/19/2025_ - 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 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 09ac6e460bf..d4f3472b625 100644 --- a/packages/driver/src/cypress/command_queue.ts +++ b/packages/driver/src/cypress/command_queue.ts @@ -339,7 +339,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 diff --git a/packages/server/lib/automation/automation.ts b/packages/server/lib/automation/automation.ts index b4073451dbc..b6c291affb2 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 { PerformanceLogger } from './performance_logger' 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 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/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 3e6afd71867..019969c7cbb 100644 --- a/packages/server/lib/browsers/bidi_automation.ts +++ b/packages/server/lib/browsers/bidi_automation.ts @@ -25,6 +25,7 @@ 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 type { StorageCookieFilter, StoragePartialCookie as BidiStoragePartialCookie } from 'webdriver/build/bidi/remoteTypes' const BIDI_DEBUG_NAMESPACE = 'cypress:server:browsers:bidi_automation' @@ -726,6 +727,8 @@ export class BidiAutomation { throw new Error('Cannot get AUT title no AUT context initialized') } + case 'log:command:performance': + 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 140dcb291b0..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 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 @@ -663,7 +663,8 @@ export class CdpAutomation implements CDPClient, AutomationMiddleware { case 'get:aut:title': return cdpGetFrameTitle(this.sendDebuggerCommandFn, this.executionContexts, await this._getAutFrame()) 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 57e88e1b843..5300c6473e3 100644 --- a/packages/server/lib/modes/index.ts +++ b/packages/server/lib/modes/index.ts @@ -24,6 +24,7 @@ export = (mode, options) => { } const span = telemetry.startSpan({ name: `initialize:mode:${mode}` }) + 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 99abf858e0f..4509a23312f 100644 --- a/packages/types/src/server.ts +++ b/packages/types/src/server.ts @@ -125,6 +125,12 @@ export interface KeyPressParams { key: SupportedKey } +export interface CommandPerformanceEntry { + name: string + startTime: number + duration: number +} + export interface AutomationCommands { 'take:screenshot': CommandSignature 'get:cookies': CommandSignature @@ -151,6 +157,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 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,