diff --git a/packages/playwright-core/src/server/fetch.ts b/packages/playwright-core/src/server/fetch.ts index fc4e2c027d..2aa7f27fee 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, parseRawCookie } 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'; @@ -40,6 +40,7 @@ import { Tracing } from './trace/recorder/tracing'; import type * as types from './types'; import type { HeadersArray, ProxySettings } from './types'; import { getMatchingTLSOptionsForOrigin, rewriteOpenSSLErrorIfNeeded } from './socksClientCertificatesInterceptor'; +import type * as har from '@trace/har'; type FetchRequestOptions = { userAgent: string; @@ -71,6 +72,7 @@ export type APIRequestFinishedEvent = { statusCode: number; statusMessage: string; body?: Buffer; + timings: har.Timings; }; type SendRequestOptions = https.RequestOptions & { @@ -294,8 +296,28 @@ 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(); + let dnsLookupAt: number | undefined; + let tcpConnectionAt: number | undefined; + let tlsHandshakeAt: number | undefined; + let requestFinishAt: 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, + 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, + blocked: -1, + }; + const requestFinishedEvent: APIRequestFinishedEvent = { requestEvent, httpVersion: response.httpVersion, @@ -304,7 +326,8 @@ export abstract class APIRequestContext extends SdkObject { headers: response.headers, rawHeaders: response.rawHeaders, cookies, - body + body, + timings, }; this.emit(APIRequestContext.Events.RequestFinished, requestFinishedEvent); }; @@ -450,6 +473,19 @@ 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 => { + // happy eyeballs don't emit lookup and connect events, so we use our custom ones + const happyEyeBallsTimings = timingForSocket(socket); + dnsLookupAt = happyEyeBallsTimings.dnsLookupAt; + tcpConnectionAt = happyEyeBallsTimings.tcpConnectionAt; + + // non-happy-eyeballs sockets + socket.on('lookup', () => { dnsLookupAt = monotonicTime(); }); + socket.on('connect', () => { tcpConnectionAt = monotonicTime(); }); + socket.on('secureConnect', () => { tlsHandshakeAt = monotonicTime(); }); + }); + request.on('finish', () => { 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 e6330f3889..76da6682d4 100644 --- a/packages/playwright-core/src/server/har/harTracer.ts +++ b/packages/playwright-core/src/server/har/harTracer.ts @@ -212,6 +212,12 @@ export class HarTracer { harEntry.response.statusText = event.statusMessage; harEntry.response.httpVersion = event.httpVersion; harEntry.response.redirectURL = event.headers.location || ''; + + 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({ name: event.rawHeaders[i], diff --git a/packages/playwright-core/src/utils/happy-eyeballs.ts b/packages/playwright-core/src/utils/happy-eyeballs.ts index 12f082e5a1..18de1a938c 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 @@ -28,6 +29,9 @@ import { assert } from './debug'; // 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. @@ -107,6 +111,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 +137,13 @@ export async function createConnectionAsync( port: options.port as number, host: address }); + (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)[kTCPConnectionAt] = monotonicTime(); + connected.resolve(); oncreate?.(null, socket); // TODO: Cache the result? @@ -189,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, + } +} diff --git a/tests/library/har.spec.ts b/tests/library/har.spec.ts index 29ee7df2d1..cc65127e3f 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, @@ -820,6 +820,47 @@ 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 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); + 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) => {