From e17585819a8a1c0f5f8fb203c9144fd38042d561 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Fri, 13 Sep 2024 16:06:27 +0200 Subject: [PATCH 01/15] feat(library): record timings for APIRequestContext --- examples/github-api/tests/demo.spec.ts | 7 ++++ packages/playwright-core/src/server/fetch.ts | 42 ++++++++++++++++++- .../src/server/har/harTracer.ts | 4 ++ 3 files changed, 52 insertions(+), 1 deletion(-) create mode 100644 examples/github-api/tests/demo.spec.ts diff --git a/examples/github-api/tests/demo.spec.ts b/examples/github-api/tests/demo.spec.ts new file mode 100644 index 0000000000000..3449819fab283 --- /dev/null +++ b/examples/github-api/tests/demo.spec.ts @@ -0,0 +1,7 @@ +import { test, expect } from "@playwright/test"; + +test('should get posts', async ({ request }) => { + const posts = await request.get(`https://jsonplaceholder.typicode.com/posts/1`); + expect(posts.ok()).toBeTruthy(); + expect(await posts.text()).toHaveLength(10) +}); \ No newline at end of file diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 7a6102a50d409..cfec0b8b09243 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -41,6 +41,7 @@ import type * as types from './types'; import type { HeadersArray, ProxySettings } from './types'; import { kMaxCookieExpiresDateInSeconds } from './network'; import { getMatchingTLSOptionsForOrigin, rewriteOpenSSLErrorIfNeeded } from './socksClientCertificatesInterceptor'; +import type * as har from '@trace/har'; type FetchRequestOptions = { userAgent: string; @@ -72,6 +73,7 @@ export type APIRequestFinishedEvent = { statusCode: number; statusMessage: string; body?: Buffer; + timings: har.Timings; }; type SendRequestOptions = https.RequestOptions & { @@ -307,8 +309,30 @@ export abstract class APIRequestContext extends SdkObject { // If we have a proxy agent already, do not override it. const agent = options.agent || (url.protocol === 'https:' ? httpsHappyEyeballsAgent : httpHappyEyeballsAgent); const requestOptions = { ...options, agent }; + + const startAt = monotonicTime(); + const timings: Record<'startAt' | 'requestFinishAt' | 'dnsLookupAt' | 'tcpConnectionAt' | 'tlsHandshakeAt' | 'firstByteAt' | 'endAt', number | undefined> = { + startAt, + requestFinishAt: undefined, + dnsLookupAt: undefined, + tcpConnectionAt: undefined, + tlsHandshakeAt: undefined, + firstByteAt: undefined, + endAt: undefined + }; + const request = requestConstructor(url, requestOptions as any, async response => { + response.once('readable', () => { timings.firstByteAt = monotonicTime(); }); + response.once('end', () => { timings.endAt = monotonicTime(); }); + const notifyRequestFinished = (body?: Buffer) => { + const send = timings.requestFinishAt! - startAt; + const dnsLookup = timings.dnsLookupAt ? startAt - timings.dnsLookupAt : undefined; + const tcpConnection = timings.tcpConnectionAt! - (timings.dnsLookupAt ?? startAt); + const tlsHandshake = timings.tlsHandshakeAt ? (timings.tlsHandshakeAt - timings.tcpConnectionAt!) : undefined; + const firstByte = timings.firstByteAt! - (timings.tlsHandshakeAt ?? timings.tcpConnectionAt!); + const contentTransfer = timings.endAt! - timings.firstByteAt!; + const requestFinishedEvent: APIRequestFinishedEvent = { requestEvent, httpVersion: response.httpVersion, @@ -317,7 +341,16 @@ export abstract class APIRequestContext extends SdkObject { headers: response.headers, rawHeaders: response.rawHeaders, cookies, - body + body, + timings: { + send, + wait: firstByte, + receive: contentTransfer, + dns: dnsLookup, + connect: tcpConnection, + ssl: tlsHandshake, + blocked: firstByte, + }, }; this.emit(APIRequestContext.Events.RequestFinished, requestFinishedEvent); }; @@ -463,6 +496,13 @@ export abstract class APIRequestContext extends SdkObject { this.on(APIRequestContext.Events.Dispose, disposeListener); request.on('close', () => this.off(APIRequestContext.Events.Dispose, disposeListener)); + request.on('socket', socket => { + socket.on('lookup', () => { timings.dnsLookupAt = monotonicTime(); }); + socket.on('connect', () => { timings.tcpConnectionAt = monotonicTime(); }); + socket.on('secureConnect', () => { timings.tlsHandshakeAt = monotonicTime(); }); + }); + request.on('finish', () => { timings.requestFinishAt = monotonicTime(); }); + progress.log(`→ ${options.method} ${url.toString()}`); if (options.headers) { for (const [name, value] of Object.entries(options.headers)) diff --git a/packages/playwright-core/src/server/har/harTracer.ts b/packages/playwright-core/src/server/har/harTracer.ts index e6330f3889eeb..077777ff3497b 100644 --- a/packages/playwright-core/src/server/har/harTracer.ts +++ b/packages/playwright-core/src/server/har/harTracer.ts @@ -212,6 +212,10 @@ export class HarTracer { harEntry.response.statusText = event.statusMessage; harEntry.response.httpVersion = event.httpVersion; harEntry.response.redirectURL = event.headers.location || ''; + + harEntry.timings = event.timings; + this._computeHarEntryTotalTime(harEntry); + for (let i = 0; i < event.rawHeaders.length; i += 2) { harEntry.response.headers.push({ name: event.rawHeaders[i], From 95ff76a95ce17349ff80cb01b932f94b977b474a Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 11:42:35 +0200 Subject: [PATCH 02/15] fix happy eyeballs --- packages/playwright-core/src/server/fetch.ts | 32 +++++++++---------- .../src/utils/happy-eyeballs.ts | 6 ++++ 2 files changed, 22 insertions(+), 16 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index cfec0b8b09243..826e265644076 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -313,10 +313,10 @@ export abstract class APIRequestContext extends SdkObject { const startAt = monotonicTime(); const timings: Record<'startAt' | 'requestFinishAt' | 'dnsLookupAt' | 'tcpConnectionAt' | 'tlsHandshakeAt' | 'firstByteAt' | 'endAt', number | undefined> = { startAt, - requestFinishAt: undefined, dnsLookupAt: undefined, tcpConnectionAt: undefined, tlsHandshakeAt: undefined, + requestFinishAt: undefined, firstByteAt: undefined, endAt: undefined }; @@ -326,12 +326,15 @@ export abstract class APIRequestContext extends SdkObject { response.once('end', () => { timings.endAt = monotonicTime(); }); const notifyRequestFinished = (body?: Buffer) => { - const send = timings.requestFinishAt! - startAt; - const dnsLookup = timings.dnsLookupAt ? startAt - timings.dnsLookupAt : undefined; - const tcpConnection = timings.tcpConnectionAt! - (timings.dnsLookupAt ?? startAt); - const tlsHandshake = timings.tlsHandshakeAt ? (timings.tlsHandshakeAt - timings.tcpConnectionAt!) : undefined; - const firstByte = timings.firstByteAt! - (timings.tlsHandshakeAt ?? timings.tcpConnectionAt!); - const contentTransfer = timings.endAt! - timings.firstByteAt!; + const harTimings: har.Timings = { + send: timings.requestFinishAt! - startAt, + wait: timings.firstByteAt! - timings.requestFinishAt!, + receive: timings.endAt! - timings.firstByteAt!, + dns: timings.dnsLookupAt ? timings.dnsLookupAt - startAt : -1, + connect: (timings.tlsHandshakeAt ?? timings.tcpConnectionAt!) - startAt, + ssl: timings.tlsHandshakeAt ? timings.tlsHandshakeAt - timings.tcpConnectionAt! : -1, + blocked: -1, // TODO: time spent in queue waiting for a network connection + }; const requestFinishedEvent: APIRequestFinishedEvent = { requestEvent, @@ -342,15 +345,7 @@ export abstract class APIRequestContext extends SdkObject { rawHeaders: response.rawHeaders, cookies, body, - timings: { - send, - wait: firstByte, - receive: contentTransfer, - dns: dnsLookup, - connect: tcpConnection, - ssl: tlsHandshake, - blocked: firstByte, - }, + timings: harTimings, }; this.emit(APIRequestContext.Events.RequestFinished, requestFinishedEvent); }; @@ -497,6 +492,11 @@ export abstract class APIRequestContext extends SdkObject { request.on('close', () => this.off(APIRequestContext.Events.Dispose, disposeListener)); request.on('socket', socket => { + // happy eyeballs don't emit lookup and connect events, so we use our custom ones + timings.dnsLookupAt = (socket as any).dnsLookupAt; + timings.tcpConnectionAt = (socket as any).tcpConnectionAt; + + // standard case socket.on('lookup', () => { timings.dnsLookupAt = monotonicTime(); }); socket.on('connect', () => { timings.tcpConnectionAt = monotonicTime(); }); socket.on('secureConnect', () => { timings.tlsHandshakeAt = monotonicTime(); }); diff --git a/packages/playwright-core/src/utils/happy-eyeballs.ts b/packages/playwright-core/src/utils/happy-eyeballs.ts index 12f082e5a17ca..72917cdc5c0de 100644 --- a/packages/playwright-core/src/utils/happy-eyeballs.ts +++ b/packages/playwright-core/src/utils/happy-eyeballs.ts @@ -21,6 +21,7 @@ import * as net from 'net'; import * as tls from 'tls'; import { ManualPromise } from './manualPromise'; import { assert } from './debug'; +import { monotonicTime } from './time'; // Implementation(partial) of Happy Eyeballs 2 algorithm described in // https://www.rfc-editor.org/rfc/rfc8305 @@ -107,6 +108,7 @@ export async function createConnectionAsync( const lookup = (options as any).__testHookLookup || lookupAddresses; const hostname = clientRequestArgsToHostName(options); const addresses = await lookup(hostname); + const dnsLookupAt = monotonicTime(); const sockets = new Set(); let firstError; let errorCount = 0; @@ -132,9 +134,13 @@ export async function createConnectionAsync( port: options.port as number, host: address }); + (socket as any).dnsLookupAt = dnsLookupAt; + // Each socket may fire only one of 'connect', 'timeout' or 'error' events. // None of these events are fired after socket.destroy() is called. socket.on('connect', () => { + (socket as any).tcpConnectionAt = monotonicTime(); + connected.resolve(); oncreate?.(null, socket); // TODO: Cache the result? From 1d061f8fcbffb1c5b3b5334bfe0d0bc1c4334fd9 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 11:54:12 +0200 Subject: [PATCH 03/15] add test --- tests/library/har.spec.ts | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/tests/library/har.spec.ts b/tests/library/har.spec.ts index 29ee7df2d1de5..1423ec4a1b104 100644 --- a/tests/library/har.spec.ts +++ b/tests/library/har.spec.ts @@ -820,6 +820,17 @@ it('should include API request', async ({ contextFactory, server }, testInfo) => expect(entry.response.headers.find(h => h.name.toLowerCase() === 'content-type')?.value).toContain('application/json'); expect(entry.response.content.size).toBe(15); expect(entry.response.content.text).toBe(responseBody.toString()); + + expect(entry.time).toBeGreaterThan(0); + expect(entry.timings).toEqual(expect.objectContaining({ + blocked: -1, + connect: expect.any(Number), + dns: expect.any(Number), + receive: expect.any(Number), + send: expect.any(Number), + ssl: expect.any(Number), + wait: expect.any(Number), + })); }); it('should not hang on resources served from cache', async ({ contextFactory, server, browserName }, testInfo) => { From e21822891df1fe7a787086b86f369ac11c3311f2 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 12:11:41 +0200 Subject: [PATCH 04/15] refactor --- packages/playwright-core/src/server/fetch.ts | 49 +++++++++----------- 1 file changed, 23 insertions(+), 26 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 826e265644076..9d7f12e6da5de 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -311,29 +311,26 @@ export abstract class APIRequestContext extends SdkObject { const requestOptions = { ...options, agent }; const startAt = monotonicTime(); - const timings: Record<'startAt' | 'requestFinishAt' | 'dnsLookupAt' | 'tcpConnectionAt' | 'tlsHandshakeAt' | 'firstByteAt' | 'endAt', number | undefined> = { - startAt, - dnsLookupAt: undefined, - tcpConnectionAt: undefined, - tlsHandshakeAt: undefined, - requestFinishAt: undefined, - firstByteAt: undefined, - endAt: undefined - }; + let dnsLookupAt: number | undefined; + let tcpConnectionAt: number | undefined; + let tlsHandshakeAt: number | undefined; + let requestFinishAt: number | undefined; + let firstByteAt: number | undefined; + let endAt: number | undefined; const request = requestConstructor(url, requestOptions as any, async response => { - response.once('readable', () => { timings.firstByteAt = monotonicTime(); }); - response.once('end', () => { timings.endAt = monotonicTime(); }); + response.once('readable', () => { firstByteAt = monotonicTime(); }); + response.once('end', () => { endAt = monotonicTime(); }); const notifyRequestFinished = (body?: Buffer) => { - const harTimings: har.Timings = { - send: timings.requestFinishAt! - startAt, - wait: timings.firstByteAt! - timings.requestFinishAt!, - receive: timings.endAt! - timings.firstByteAt!, - dns: timings.dnsLookupAt ? timings.dnsLookupAt - startAt : -1, - connect: (timings.tlsHandshakeAt ?? timings.tcpConnectionAt!) - startAt, - ssl: timings.tlsHandshakeAt ? timings.tlsHandshakeAt - timings.tcpConnectionAt! : -1, - blocked: -1, // TODO: time spent in queue waiting for a network connection + const timings: har.Timings = { + send: requestFinishAt! - startAt, + wait: firstByteAt! - requestFinishAt!, + receive: endAt! - firstByteAt!, + dns: dnsLookupAt ? dnsLookupAt - startAt : -1, + connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, + ssl: tlsHandshakeAt ? tlsHandshakeAt - tcpConnectionAt! : -1, + blocked: -1, }; const requestFinishedEvent: APIRequestFinishedEvent = { @@ -345,7 +342,7 @@ export abstract class APIRequestContext extends SdkObject { rawHeaders: response.rawHeaders, cookies, body, - timings: harTimings, + timings, }; this.emit(APIRequestContext.Events.RequestFinished, requestFinishedEvent); }; @@ -493,15 +490,15 @@ export abstract class APIRequestContext extends SdkObject { request.on('socket', socket => { // happy eyeballs don't emit lookup and connect events, so we use our custom ones - timings.dnsLookupAt = (socket as any).dnsLookupAt; - timings.tcpConnectionAt = (socket as any).tcpConnectionAt; + dnsLookupAt = (socket as any).dnsLookupAt; + tcpConnectionAt = (socket as any).tcpConnectionAt; // standard case - socket.on('lookup', () => { timings.dnsLookupAt = monotonicTime(); }); - socket.on('connect', () => { timings.tcpConnectionAt = monotonicTime(); }); - socket.on('secureConnect', () => { timings.tlsHandshakeAt = monotonicTime(); }); + socket.on('lookup', () => { dnsLookupAt = monotonicTime(); }); + socket.on('connect', () => { tcpConnectionAt = monotonicTime(); }); + socket.on('secureConnect', () => { tlsHandshakeAt = monotonicTime(); }); }); - request.on('finish', () => { timings.requestFinishAt = monotonicTime(); }); + request.on('finish', () => { requestFinishAt = monotonicTime(); }); progress.log(`→ ${options.method} ${url.toString()}`); if (options.headers) { From 513b1c2ab3e3613e5941fcc430f6efd7dd5bdb42 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 12:13:46 +0200 Subject: [PATCH 05/15] remove one listener --- packages/playwright-core/src/server/fetch.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 9d7f12e6da5de..8100e54a2f836 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -320,7 +320,6 @@ export abstract class APIRequestContext extends SdkObject { const request = requestConstructor(url, requestOptions as any, async response => { response.once('readable', () => { firstByteAt = monotonicTime(); }); - response.once('end', () => { endAt = monotonicTime(); }); const notifyRequestFinished = (body?: Buffer) => { const timings: har.Timings = { @@ -437,6 +436,7 @@ export abstract class APIRequestContext extends SdkObject { const chunks: Buffer[] = []; const notifyBodyFinished = () => { + endAt = monotonicTime(); const body = Buffer.concat(chunks); notifyRequestFinished(body); fulfill({ From 7e2acc513d833c868b4dba6c18cf6c463f5f753f Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 12:15:54 +0200 Subject: [PATCH 06/15] `readable` and `data` are mutually exclusive --- packages/playwright-core/src/server/fetch.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 8100e54a2f836..0206b47a5e5d9 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -319,8 +319,6 @@ export abstract class APIRequestContext extends SdkObject { let endAt: number | undefined; const request = requestConstructor(url, requestOptions as any, async response => { - response.once('readable', () => { firstByteAt = monotonicTime(); }); - const notifyRequestFinished = (body?: Buffer) => { const timings: har.Timings = { send: requestFinishAt! - startAt, @@ -476,7 +474,10 @@ export abstract class APIRequestContext extends SdkObject { body.on('error', reject); } - body.on('data', chunk => chunks.push(chunk)); + body.on('data', chunk => { + firstByteAt ??= monotonicTime(); + chunks.push(chunk); + }); body.on('end', notifyBodyFinished); }); request.on('error', error => reject(rewriteOpenSSLErrorIfNeeded(error))); From 23a0a53e1b988fe717e33704eb70b29f5a81582c Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 12:17:23 +0200 Subject: [PATCH 07/15] update comment --- packages/playwright-core/src/server/fetch.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 0206b47a5e5d9..f29dc3d01d3ad 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -494,7 +494,7 @@ export abstract class APIRequestContext extends SdkObject { dnsLookupAt = (socket as any).dnsLookupAt; tcpConnectionAt = (socket as any).tcpConnectionAt; - // standard case + // non-happy-eyeballs sockets socket.on('lookup', () => { dnsLookupAt = monotonicTime(); }); socket.on('connect', () => { tcpConnectionAt = monotonicTime(); }); socket.on('secureConnect', () => { tlsHandshakeAt = monotonicTime(); }); From c0c036b4807663b3e63ab2026426e77553593ac9 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Sat, 14 Sep 2024 12:18:09 +0200 Subject: [PATCH 08/15] remove demo test --- examples/github-api/tests/demo.spec.ts | 7 ------- 1 file changed, 7 deletions(-) delete mode 100644 examples/github-api/tests/demo.spec.ts diff --git a/examples/github-api/tests/demo.spec.ts b/examples/github-api/tests/demo.spec.ts deleted file mode 100644 index 3449819fab283..0000000000000 --- a/examples/github-api/tests/demo.spec.ts +++ /dev/null @@ -1,7 +0,0 @@ -import { test, expect } from "@playwright/test"; - -test('should get posts', async ({ request }) => { - const posts = await request.get(`https://jsonplaceholder.typicode.com/posts/1`); - expect(posts.ok()).toBeTruthy(); - expect(await posts.text()).toHaveLength(10) -}); \ No newline at end of file From 947942349aa4c08cb7942821ad4bf09984d0b332 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Mon, 16 Sep 2024 09:57:25 +0200 Subject: [PATCH 09/15] add comment about connect --- packages/playwright-core/src/server/fetch.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index f29dc3d01d3ad..b11b72a63b891 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -320,12 +320,13 @@ export abstract class APIRequestContext extends SdkObject { const request = requestConstructor(url, requestOptions as any, async response => { const notifyRequestFinished = (body?: Buffer) => { + // spec: http://www.softwareishard.com/blog/har-12-spec/#timings const timings: har.Timings = { send: requestFinishAt! - startAt, wait: firstByteAt! - requestFinishAt!, receive: endAt! - firstByteAt!, dns: dnsLookupAt ? dnsLookupAt - startAt : -1, - connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, + connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, // "If [ssl] is defined then the time is also included in the connect field " ssl: tlsHandshakeAt ? tlsHandshakeAt - tcpConnectionAt! : -1, blocked: -1, }; From 5d8ab8a33cde506ca1076fe349fd530870c17b69 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Mon, 16 Sep 2024 10:05:59 +0200 Subject: [PATCH 10/15] replace firstByteAdd with responseAt --- packages/playwright-core/src/server/fetch.ts | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index b11b72a63b891..2d4e46bdc9ccc 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -315,16 +315,16 @@ export abstract class APIRequestContext extends SdkObject { let tcpConnectionAt: number | undefined; let tlsHandshakeAt: number | undefined; let requestFinishAt: number | undefined; - let firstByteAt: number | undefined; let endAt: number | undefined; const request = requestConstructor(url, requestOptions as any, async response => { + const responseAt = monotonicTime(); const notifyRequestFinished = (body?: Buffer) => { // spec: http://www.softwareishard.com/blog/har-12-spec/#timings const timings: har.Timings = { send: requestFinishAt! - startAt, - wait: firstByteAt! - requestFinishAt!, - receive: endAt! - firstByteAt!, + wait: responseAt - requestFinishAt!, + receive: endAt! - responseAt, dns: dnsLookupAt ? dnsLookupAt - startAt : -1, connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, // "If [ssl] is defined then the time is also included in the connect field " ssl: tlsHandshakeAt ? tlsHandshakeAt - tcpConnectionAt! : -1, @@ -475,10 +475,7 @@ export abstract class APIRequestContext extends SdkObject { body.on('error', reject); } - body.on('data', chunk => { - firstByteAt ??= monotonicTime(); - chunks.push(chunk); - }); + body.on('data', chunk => chunks.push(chunk)); body.on('end', notifyBodyFinished); }); request.on('error', error => reject(rewriteOpenSSLErrorIfNeeded(error))); From dde4488ebbc3c3627e38e5825ed88d76303b5300 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Mon, 16 Sep 2024 10:07:57 +0200 Subject: [PATCH 11/15] refactor endAt --- packages/playwright-core/src/server/fetch.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 2d4e46bdc9ccc..794ec87ccdbcb 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -315,11 +315,11 @@ export abstract class APIRequestContext extends SdkObject { let tcpConnectionAt: number | undefined; let tlsHandshakeAt: number | undefined; let requestFinishAt: number | undefined; - let endAt: number | undefined; const request = requestConstructor(url, requestOptions as any, async response => { const responseAt = monotonicTime(); const notifyRequestFinished = (body?: Buffer) => { + const endAt = monotonicTime(); // spec: http://www.softwareishard.com/blog/har-12-spec/#timings const timings: har.Timings = { send: requestFinishAt! - startAt, @@ -435,7 +435,6 @@ export abstract class APIRequestContext extends SdkObject { const chunks: Buffer[] = []; const notifyBodyFinished = () => { - endAt = monotonicTime(); const body = Buffer.concat(chunks); notifyRequestFinished(body); fulfill({ From 2d0919c0f64b19eab53a2f0889e09e8a43f9b510 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Mon, 16 Sep 2024 10:27:21 +0200 Subject: [PATCH 12/15] add test for redirects --- tests/library/har.spec.ts | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/tests/library/har.spec.ts b/tests/library/har.spec.ts index 1423ec4a1b104..5f2865226f6ab 100644 --- a/tests/library/har.spec.ts +++ b/tests/library/har.spec.ts @@ -833,6 +833,23 @@ it('should include API request', async ({ contextFactory, server }, testInfo) => })); }); +it('should include redirects from API request', async ({ contextFactory, server }, testInfo) => { + server.setRedirect('/redirect-me', '/simple.json'); + const { page, getLog } = await pageWithHar(contextFactory, testInfo); + await page.request.post(server.PREFIX + '/redirect-me', { + headers: { cookie: 'a=b; c=d' }, + data: { foo: 'bar' } + }); + const log = await getLog(); + expect(log.entries.length).toBe(2); + const [redirect, json] = log.entries; + expect(redirect.request.url).toBe(server.PREFIX + '/redirect-me'); + expect(json.request.url).toBe(server.PREFIX + '/simple.json'); + + expect(redirect.timings).toBeDefined(); + expect(json.timings).toBeDefined(); +}); + it('should not hang on resources served from cache', async ({ contextFactory, server, browserName }, testInfo) => { it.info().annotations.push({ type: 'issue', description: 'https://github.com/microsoft/playwright/issues/11435' }); server.setRoute('/one-style.css', (req, res) => { From c29a5562e0f337550e6aa8dc4da1951df7ae44b8 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Tue, 17 Sep 2024 08:59:16 +0200 Subject: [PATCH 13/15] Update packages/playwright-core/src/server/fetch.ts Co-authored-by: Dmitry Gozman Signed-off-by: Simon Knott --- packages/playwright-core/src/server/fetch.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 794ec87ccdbcb..3aebb26d01bfe 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -324,7 +324,7 @@ export abstract class APIRequestContext extends SdkObject { const timings: har.Timings = { send: requestFinishAt! - startAt, wait: responseAt - requestFinishAt!, - receive: endAt! - responseAt, + receive: endAt - responseAt, dns: dnsLookupAt ? dnsLookupAt - startAt : -1, connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, // "If [ssl] is defined then the time is also included in the connect field " ssl: tlsHandshakeAt ? tlsHandshakeAt - tcpConnectionAt! : -1, From 5d4f149c64edd165308ad641018192d10ab096b2 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Tue, 17 Sep 2024 09:07:06 +0200 Subject: [PATCH 14/15] encapsulate details in happy-eyeballs --- packages/playwright-core/src/server/fetch.ts | 7 ++++--- .../playwright-core/src/utils/happy-eyeballs.ts | 13 +++++++++++-- 2 files changed, 15 insertions(+), 5 deletions(-) diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index 3aebb26d01bfe..6cefc87eb973d 100644 --- a/packages/playwright-core/src/server/fetch.ts +++ b/packages/playwright-core/src/server/fetch.ts @@ -30,7 +30,7 @@ import { HttpsProxyAgent, SocksProxyAgent } from '../utilsBundle'; import { BrowserContext, verifyClientCertificates } from './browserContext'; import { CookieStore, domainMatches } from './cookieStore'; import { MultipartFormData } from './formData'; -import { httpHappyEyeballsAgent, httpsHappyEyeballsAgent } from '../utils/happy-eyeballs'; +import { httpHappyEyeballsAgent, httpsHappyEyeballsAgent, timingForSocket } from '../utils/happy-eyeballs'; import type { CallMetadata } from './instrumentation'; import { SdkObject } from './instrumentation'; import type { Playwright } from './playwright'; @@ -488,8 +488,9 @@ export abstract class APIRequestContext extends SdkObject { request.on('socket', socket => { // happy eyeballs don't emit lookup and connect events, so we use our custom ones - dnsLookupAt = (socket as any).dnsLookupAt; - tcpConnectionAt = (socket as any).tcpConnectionAt; + const happyEyeBallsTimings = timingForSocket(socket); + dnsLookupAt = happyEyeBallsTimings.dnsLookupAt; + tcpConnectionAt = happyEyeBallsTimings.tcpConnectionAt; // non-happy-eyeballs sockets socket.on('lookup', () => { dnsLookupAt = monotonicTime(); }); diff --git a/packages/playwright-core/src/utils/happy-eyeballs.ts b/packages/playwright-core/src/utils/happy-eyeballs.ts index 72917cdc5c0de..18de1a938cad2 100644 --- a/packages/playwright-core/src/utils/happy-eyeballs.ts +++ b/packages/playwright-core/src/utils/happy-eyeballs.ts @@ -29,6 +29,9 @@ import { monotonicTime } from './time'; // Same as in Chromium (https://source.chromium.org/chromium/chromium/src/+/5666ff4f5077a7e2f72902f3a95f5d553ea0d88d:net/socket/transport_connect_job.cc;l=102) const connectionAttemptDelayMs = 300; +const kDNSLookupAt = Symbol('kDNSLookupAt') +const kTCPConnectionAt = Symbol('kTCPConnectionAt') + class HttpHappyEyeballsAgent extends http.Agent { createConnection(options: http.ClientRequestArgs, oncreate?: (err: Error | null, socket?: net.Socket) => void): net.Socket | undefined { // There is no ambiguity in case of IP address. @@ -134,12 +137,12 @@ export async function createConnectionAsync( port: options.port as number, host: address }); - (socket as any).dnsLookupAt = dnsLookupAt; + (socket as any)[kDNSLookupAt] = dnsLookupAt; // Each socket may fire only one of 'connect', 'timeout' or 'error' events. // None of these events are fired after socket.destroy() is called. socket.on('connect', () => { - (socket as any).tcpConnectionAt = monotonicTime(); + (socket as any)[kTCPConnectionAt] = monotonicTime(); connected.resolve(); oncreate?.(null, socket); @@ -195,3 +198,9 @@ function clientRequestArgsToHostName(options: http.ClientRequestArgs): string { throw new Error('Either options.hostname or options.host must be provided'); } +export function timingForSocket(socket: net.Socket | tls.TLSSocket) { + return { + dnsLookupAt: (socket as any)[kDNSLookupAt] as number | undefined, + tcpConnectionAt: (socket as any)[kTCPConnectionAt] as number | undefined, + } +} From f4a986e61afb67c9d9497c3132cc083a819d3ae6 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Tue, 17 Sep 2024 15:48:37 +0200 Subject: [PATCH 15/15] omit timings --- .../playwright-core/src/server/har/harTracer.ts | 6 ++++-- tests/library/har.spec.ts | 17 +++++++++++++++-- 2 files changed, 19 insertions(+), 4 deletions(-) diff --git a/packages/playwright-core/src/server/har/harTracer.ts b/packages/playwright-core/src/server/har/harTracer.ts index 077777ff3497b..76da6682d4651 100644 --- a/packages/playwright-core/src/server/har/harTracer.ts +++ b/packages/playwright-core/src/server/har/harTracer.ts @@ -213,8 +213,10 @@ export class HarTracer { harEntry.response.httpVersion = event.httpVersion; harEntry.response.redirectURL = event.headers.location || ''; - harEntry.timings = event.timings; - this._computeHarEntryTotalTime(harEntry); + if (!this._options.omitTiming) { + harEntry.timings = event.timings; + this._computeHarEntryTotalTime(harEntry); + } for (let i = 0; i < event.rawHeaders.length; i += 2) { harEntry.response.headers.push({ diff --git a/tests/library/har.spec.ts b/tests/library/har.spec.ts index 5f2865226f6ab..cc65127e3fdf0 100644 --- a/tests/library/har.spec.ts +++ b/tests/library/har.spec.ts @@ -24,9 +24,9 @@ import type { Log } from '../../packages/trace/src/har'; import { parseHar } from '../config/utils'; const { createHttp2Server } = require('../../packages/playwright-core/lib/utils'); -async function pageWithHar(contextFactory: (options?: BrowserContextOptions) => Promise, testInfo: any, options: { outputPath?: string, content?: 'embed' | 'attach' | 'omit', omitContent?: boolean } = {}) { +async function pageWithHar(contextFactory: (options?: BrowserContextOptions) => Promise, testInfo: any, options: { outputPath?: string } & Partial> = {}) { const harPath = testInfo.outputPath(options.outputPath || 'test.har'); - const context = await contextFactory({ recordHar: { path: harPath, content: options.content, omitContent: options.omitContent }, ignoreHTTPSErrors: true }); + const context = await contextFactory({ recordHar: { path: harPath, ...options }, ignoreHTTPSErrors: true }); const page = await context.newPage(); return { page, @@ -833,6 +833,19 @@ it('should include API request', async ({ contextFactory, server }, testInfo) => })); }); +it('should respect minimal mode for API Requests', async ({ contextFactory, server }, testInfo) => { + const { page, getLog } = await pageWithHar(contextFactory, testInfo, { mode: 'minimal' }); + const url = server.PREFIX + '/simple.json'; + await page.request.post(url, { + headers: { cookie: 'a=b; c=d' }, + data: { foo: 'bar' } + }); + const { entries } = await getLog(); + expect(entries).toHaveLength(1); + const [entry] = entries; + expect(entry.timings).toEqual({ receive: -1, send: -1, wait: -1 }); +}); + it('should include redirects from API request', async ({ contextFactory, server }, testInfo) => { server.setRedirect('/redirect-me', '/simple.json'); const { page, getLog } = await pageWithHar(contextFactory, testInfo);