diff --git a/__tests__/reporters/__snapshots__/json.test.ts.snap b/__tests__/reporters/__snapshots__/json.test.ts.snap index 00c53384..e5bbab25 100644 --- a/__tests__/reporters/__snapshots__/json.test.ts.snap +++ b/__tests__/reporters/__snapshots__/json.test.ts.snap @@ -195,7 +195,7 @@ exports[`json reporter screenshots write block & reference docs 1`] = ` {"type":"screenshot/block","_id":"e89af7cc2cae152df54ccf091793db64b3dfe995","@timestamp":1600300800000000,"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"blob":"/9j/2wBDAAYEBQYFBAYGBQYHBwYIChAKCgkJChQODwwQFxQYGBcUFhYaHSUfGhsjHBYWICwgIyYnKSopGR8tMC0oMCUoKSj/2wBDAQcHBwoIChMKChMoGhYaKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCj/wAARCABaAKADASIAAhEBAxEB/8QAFQABAQAAAAAAAAAAAAAAAAAAAAj/xAAUEAEAAAAAAAAAAAAAAAAAAAAA/8QAFAEBAAAAAAAAAAAAAAAAAAAAAP/EABQRAQAAAAAAAAAAAAAAAAAAAAD/2gAMAwEAAhEDEQA/AKcAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAB//9k=","blob_mime":"image/jpeg","package_version":"0.0.1"} {"type":"screenshot/block","_id":"e89af7cc2cae152df54ccf091793db64b3dfe995","@timestamp":1600300800000000,"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"blob":"/9j/2wBDAAYEBQYFBAYGBQYHBwYIChAKCgkJChQODwwQFxQYGBcUFhYaHSUfGhsjHBYWICwgIyYnKSopGR8tMC0oMCUoKSj/2wBDAQcHBwoIChMKChMoGhYaKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCj/wAARCABaAKADASIAAhEBAxEB/8QAFQABAQAAAAAAAAAAAAAAAAAAAAj/xAAUEAEAAAAAAAAAAAAAAAAAAAAA/8QAFAEBAAAAAAAAAAAAAAAAAAAAAP/EABQRAQAAAAAAAAAAAAAAAAAAAAD/2gAMAwEAAhEDEQA/AKcAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAB//9k=","blob_mime":"image/jpeg","package_version":"0.0.1"} {"type":"step/screenshot_ref","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"launch app","index":1},"root_fields":{"screenshot_ref":{"width":1280,"height":720,"blocks":[{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":320,"width":160,"height":90},{"hash":"7207d2da8fc8a9423ea2e38501061ba30dca2e49","top":0,"left":480,"width":160,"height":90},{"hash":"c895742d0c552bb1e90bb9054dce0a207e0612f4","top":0,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":160,"width":160,"height":90},{"hash":"8dab22ef3ba33256e102c7755d6d05309d447a5d","top":90,"left":320,"width":160,"height":90},{"hash":"0503e01e69b834685b61bb12b897189f70b7f8cf","top":90,"left":480,"width":160,"height":90},{"hash":"1e2e95c527b7911704f108caa2dc124b71a6906c","top":90,"left":640,"width":160,"height":90},{"hash":"6bb91d0bcccfe17810c585ff9676da9bf060e7ea","top":90,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":160,"width":160,"height":90},{"hash":"4bef2a34c082065f7fd8a9246be3b82265640151","top":180,"left":320,"width":160,"height":90},{"hash":"166035c43b7ec64602a23cecb800d72d07a8fd07","top":180,"left":480,"width":160,"height":90},{"hash":"5da56b5b7ff6d979000b0e6c3e5047a07eb746a9","top":180,"left":640,"width":160,"height":90},{"hash":"2cd55289e3819c419182ad42af7b0e017ef252ec","top":180,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":320,"width":160,"height":90},{"hash":"fead29b7726776d52be4fa448f1e0c603f89ea21","top":270,"left":480,"width":160,"height":90},{"hash":"07b755d38bae03aac9cfd6c0f10d98387d81026d","top":270,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":1120,"width":160,"height":90}]},"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"package_version":"0.0.1"} -{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"failed"},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"start":0,"end":2,"status":"failed"},"package_version":"0.0.1"} +{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"failed","duration":{"us":2000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"status":"failed","browser_delay_us":0,"process_startup_epoch_us":1600300800000000},"package_version":"0.0.1"} " `; @@ -210,6 +210,6 @@ exports[`json reporter writes each step as NDJSON to the FD 1`] = ` {"type":"step/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"s1","index":1,"status":"succeeded","duration":{"us":10000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"source":"function noop() { }","url":"dummy","status":"succeeded"},"url":"dummy","package_version":"0.0.1"} {"type":"journey/network_info","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"root_fields":{"user_agent":{},"http":{"request":{}},"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"browser":{},"is_navigation_request":true},"package_version":"0.0.1"} {"type":"journey/browserconsole","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"step-name","index":0},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"text":"Boom","type":"error"},"package_version":"0.0.1"} -{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"succeeded"},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"start":0,"end":11,"status":"succeeded"},"package_version":"0.0.1"} +{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"succeeded","duration":{"us":11000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"status":"succeeded","browser_delay_us":2000000,"process_startup_epoch_us":1600300800000000},"package_version":"0.0.1"} " `; diff --git a/__tests__/reporters/base.test.ts b/__tests__/reporters/base.test.ts index d58aab56..a99dc6d1 100644 --- a/__tests__/reporters/base.test.ts +++ b/__tests__/reporters/base.test.ts @@ -92,6 +92,7 @@ describe('base reporter', () => { error, start: 0, end: 1, + browserDelay: 0, options: {}, }); reporter.onEnd(); diff --git a/__tests__/reporters/buildkite-cli.test.ts b/__tests__/reporters/buildkite-cli.test.ts index 17f795a0..6add4ab4 100644 --- a/__tests__/reporters/buildkite-cli.test.ts +++ b/__tests__/reporters/buildkite-cli.test.ts @@ -39,7 +39,7 @@ describe('buildkite cli reporter', () => { let stream: SonicBoom; let reporter: BuildKiteCLIReporter; const timestamp = 1600300800000000; - const j1 = journey('j1', () => {}); + const j1 = journey('j1', () => { }); const readAndCloseStream = async () => { /** @@ -90,6 +90,7 @@ describe('buildkite cli reporter', () => { }, start: 0, end: 1, + browserDelay: 0, options: {}, }); reporter.onEnd(); @@ -111,6 +112,7 @@ describe('buildkite cli reporter', () => { error, start: 0, end: 1, + browserDelay: 0, options: {}, }); reporter.onEnd(); @@ -138,6 +140,7 @@ describe('buildkite cli reporter', () => { status: 'succeeded', start: 4, end: 6, + browserDelay: 0, options: {}, }); reporter.onEnd(); diff --git a/__tests__/reporters/json.test.ts b/__tests__/reporters/json.test.ts index b07ce567..19111e81 100644 --- a/__tests__/reporters/json.test.ts +++ b/__tests__/reporters/json.test.ts @@ -48,9 +48,18 @@ jest.mock( jest.fn(() => ({ version: '0.0.1', name: '@elastic/synthetics' })) ); +/** + * Mock the timeOrigin to log process startup time + */ +jest.mock('perf_hooks', () => ({ + performance: { + timeOrigin: 1600300800000, + }, +})); + describe('json reporter', () => { let dest: string; - const j1 = journey('j1', () => {}); + const j1 = journey('j1', () => { }); let stream: SonicBoom; let reporter: JSONReporter; const timestamp = 1600300800000000; @@ -160,6 +169,7 @@ describe('json reporter', () => { status: 'succeeded', start: 0, end: 11, + browserDelay: 2, options: {}, networkinfo: [ { @@ -238,6 +248,7 @@ describe('json reporter', () => { timestamp, start: 0, end: 1, + browserDelay: 0, status: 'failed', error: myErr, options: {}, @@ -254,6 +265,7 @@ describe('json reporter', () => { timestamp, start: 0, end: 1, + browserDelay: 0, status: 'failed', error: 'boom' as any, options: {}, @@ -269,11 +281,12 @@ describe('json reporter', () => { const journeyOpts = { name: 'name', id: 'id', tags: ['tag1', 'tag2'] }; reporter.onJourneyEnd( - journey(journeyOpts, () => {}), + journey(journeyOpts, () => { }), { timestamp, start: 0, end: 1, + browserDelay: 0, status: 'skipped', options: {}, } @@ -282,7 +295,11 @@ describe('json reporter', () => { const journeyEnd = (await readAndCloseStreamJson()).find( json => json.type == 'journey/end' ); - expect(journeyEnd.journey).toEqual({ ...journeyOpts, status: 'skipped' }); + expect(journeyEnd.journey).toEqual({ + ...journeyOpts, + duration: { us: 1 * 1e6 }, + status: 'skipped', + }); }); it('captures number of journeys as metadata event', async () => { @@ -331,6 +348,7 @@ describe('json reporter', () => { reporter.onJourneyEnd(j1, { timestamp, start: 0, + browserDelay: 0, end: 2, status, options, diff --git a/__tests__/reporters/junit.test.ts b/__tests__/reporters/junit.test.ts index 07992ea7..c23bbc2d 100644 --- a/__tests__/reporters/junit.test.ts +++ b/__tests__/reporters/junit.test.ts @@ -70,6 +70,7 @@ describe('junit reporter', () => { timestamp, start: 0, end: 2, + browserDelay: 0, status: 'failed', options: {}, }); @@ -98,6 +99,7 @@ describe('junit reporter', () => { timestamp, start: 0, end: 2, + browserDelay: 0, status: 'failed', options: {}, }); diff --git a/src/common_types.ts b/src/common_types.ts index 21c2df2e..33a59f48 100644 --- a/src/common_types.ts +++ b/src/common_types.ts @@ -323,6 +323,7 @@ export type JourneyEndResult = JourneyStartResult & JourneyResult & { start: number; end: number; + browserDelay: number; options: RunOptions; timestamp: number; }; diff --git a/src/core/runner.ts b/src/core/runner.ts index c30ce385..fd04ba9e 100644 --- a/src/core/runner.ts +++ b/src/core/runner.ts @@ -60,6 +60,7 @@ export type SuiteHooks = Record>; type JourneyContext = { params?: Params; + browserDelay: number; start: number; driver: Driver; pluginManager: PluginManager; @@ -78,6 +79,7 @@ export default class Runner { static screenshotPath = join(CACHE_PATH, 'screenshots'); static async createContext(options: RunOptions): Promise { + const browserStart = monotonicTimeInSeconds(); const driver = await Gatherer.setupDriver(options); /** * Do not include browser launch/context creation duration @@ -92,6 +94,7 @@ export default class Runner { await mkdir(this.screenshotPath, { recursive: true }); return { start, + browserDelay: start - browserStart, params: options.params, driver, pluginManager, @@ -314,13 +317,14 @@ export default class Runner { options: RunOptions ) { const end = monotonicTimeInSeconds(); - const { pluginManager, start, status, error } = result; + const { pluginManager, start, status, error, browserDelay } = result; const pluginOutput = await pluginManager.output(); await this.#reporter?.onJourneyEnd?.(journey, { status, error, start, end, + browserDelay, timestamp: getTimestamp(), options, ...pluginOutput, @@ -350,6 +354,7 @@ export default class Runner { timestamp: getTimestamp(), start, options, + browserDelay: 0, end: monotonicTimeInSeconds(), ...result, }); diff --git a/src/helpers.ts b/src/helpers.ts index 47c06730..cdd1a198 100644 --- a/src/helpers.ts +++ b/src/helpers.ts @@ -95,7 +95,7 @@ export function microSecsToSeconds(ts: number) { /** * Timestamp at which the current node process began. */ -const processStart = performance.timeOrigin; +export const processStart = performance.timeOrigin; export function getTimestamp() { return (processStart + now()) * 1000; } diff --git a/src/reporters/json.ts b/src/reporters/json.ts index 63885c41..6f5325a6 100644 --- a/src/reporters/json.ts +++ b/src/reporters/json.ts @@ -35,6 +35,7 @@ import { totalist, isDirectory, getDurationInUs, + processStart, } from '../helpers'; import { Journey, Step } from '../dsl'; import snakeCaseKeys from 'snakecase-keys'; @@ -73,9 +74,9 @@ type OutputType = type Payload = { source?: string; - start?: number; - end?: number; url?: string; + browser_delay_us?: number; + process_startup_epoch_us?: number; status?: StatusValue; pagemetrics?: PageMetrics; type?: OutputType; @@ -84,17 +85,19 @@ type Payload = { network_conditions?: NetworkConditions; }; +type Duration = { + duration?: { + us: number; + }; +}; + type OutputFields = { type: OutputType; _id?: string; - journey?: Journey; + journey?: Partial & Duration; timestamp?: number; url?: string; - step?: Partial & { - duration?: { - us: number; - }; - }; + step?: Partial & Duration; error?: Error; root_fields?: Record; payload?: Payload; @@ -260,6 +263,7 @@ function journeyInfo( id: journey.id, tags: journey.tags, status: type === 'journey/end' ? status : undefined, + duration: journey.duration, }; } @@ -369,8 +373,8 @@ export default class JSONReporter extends BaseReporter { }, payload: event.networkConditions ? { - network_conditions: event.networkConditions, - } + network_conditions: event.networkConditions, + } : undefined, }); } @@ -451,6 +455,7 @@ export default class JSONReporter extends BaseReporter { timestamp, start, end, + browserDelay, networkinfo, browserconsole, status, @@ -517,13 +522,20 @@ export default class JSONReporter extends BaseReporter { this.writeJSON({ type: 'journey/end', - journey, + journey: { + ...journey, + duration: { + us: getDurationInUs(end - start), + }, + }, timestamp, error, payload: { - start, - end, status, + // convert from monotonic seconds time to microseconds + browser_delay_us: getDurationInUs(browserDelay), + // timestamp in microseconds at which the current node process began, measured in Unix time. + process_startup_epoch_us: Math.trunc(processStart * 1000), }, }); }