feat(fetch): record timings (#32613)

Related to #19621

Adds some instrumentation to collect timings for `APIRequestContext`
requests and adds them to the HAR trace. Doesn't yet expose them via an
API, but makes our `Duration` field in the trace viewer show a nice
duration:

<img width="1392" alt="Screenshot 2024-09-14 at 11 46 04"
src="https://github.com/user-attachments/assets/8020382d-9494-4634-9cfd-22b6f4a1d770">


I'm gonna add it to our API in a separate PR.

---------

Signed-off-by: Simon Knott <info@simonknott.de>
Co-authored-by: Dmitry Gozman <dgozman@gmail.com>

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))

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],

packages/playwright-core/src/utils/happy-eyeballs.ts

@@ -21,13 +21,17 @@ 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
 
 // 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<net.Socket>();
   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,
+  }
+}

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<BrowserContext>, testInfo: any, options: { outputPath?: string, content?: 'embed' | 'attach' | 'omit', omitContent?: boolean } = {}) {
+async function pageWithHar(contextFactory: (options?: BrowserContextOptions) => Promise<BrowserContext>, testInfo: any, options: { outputPath?: string } & Partial<Pick<BrowserContextOptions['recordHar'], 'content' | 'omitContent' | 'mode'>> = {}) {
   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) => {