feat: Add resource timing entries for connection, request and response (#2481)

Author: ToshB

docs/api/Dispatcher.md

@@ -209,6 +209,7 @@ Returns: `Boolean` - `false` if dispatcher is busy and further dispatch calls wo
 * **onConnect** `(abort: () => void, context: object) => void` - Invoked before request is dispatched on socket. May be invoked multiple times when a request is retried when the request at the head of the pipeline fails.
 * **onError** `(error: Error) => void` - Invoked when an error has occurred. May not throw.
 * **onUpgrade** `(statusCode: number, headers: Buffer[], socket: Duplex) => void` (optional) - Invoked when request is upgraded. Required if `DispatchOptions.upgrade` is defined or `DispatchOptions.method === 'CONNECT'`.
+* **onResponseStarted** `() => void` (optional) - Invoked when response is received, before headers have been read.
 * **onHeaders** `(statusCode: number, headers: Buffer[], resume: () => void, statusText: string) => boolean` - Invoked when statusCode and headers have been received. May be invoked multiple times due to 1xx informational headers. Not required for `upgrade` requests.
 * **onData** `(chunk: Buffer) => boolean` - Invoked when response payload data is received. Not required for `upgrade` requests.
 * **onComplete** `(trailers: Buffer[]) => void` - Invoked when response payload and trailers have been received and the request has completed. Not required for `upgrade` requests.

lib/client.js

@@ -740,6 +740,7 @@ class Parser {
     if (!request) {
       return -1
     }
+    request.onResponseStarted()
   }
 
   onHeaderField (buf) {
@@ -1786,6 +1787,7 @@ function writeH2 (client, session, request) {
 
   stream.once('response', headers => {
     const { [HTTP2_HEADER_STATUS]: statusCode, ...realHeaders } = headers
+    request.onResponseStarted()
 
     if (request.onHeaders(Number(statusCode), realHeaders, stream.resume.bind(stream), '') === false) {
       stream.pause()

lib/core/request.js

@@ -253,6 +253,10 @@ class Request {
     }
   }
 
+  onResponseStarted () {
+    return this[kHandler].onResponseStarted?.()
+  }
+
   onHeaders (statusCode, headers, resume, statusText) {
     assert(!this.aborted)
     assert(!this.completed)

lib/fetch/index.js

@@ -41,6 +41,7 @@ const {
   urlIsLocal,
   urlIsHttpHttpsScheme,
   urlHasHttpsScheme,
+  clampAndCoursenConnectionTimingInfo,
   simpleRangeHeaderValue,
   buildContentRange
 } = require('./util')
@@ -2098,12 +2099,30 @@ async function httpNetworkFetch (
           // TODO (fix): Do we need connection here?
           const { connection } = fetchParams.controller
 
+          // Set timingInfo’s final connection timing info to the result of calling clamp and coarsen
+          // connection timing info with connection’s timing info, timingInfo’s post-redirect start
+          // time, and fetchParams’s cross-origin isolated capability.
+          // TODO: implement connection timing
+          timingInfo.finalConnectionTimingInfo = clampAndCoursenConnectionTimingInfo(undefined, timingInfo.postRedirectStartTime, fetchParams.crossOriginIsolatedCapability)
+
           if (connection.destroyed) {
             abort(new DOMException('The operation was aborted.', 'AbortError'))
           } else {
             fetchParams.controller.on('terminated', abort)
             this.abort = connection.abort = abort
           }
+
+          // Set timingInfo’s final network-request start time to the coarsened shared current time given
+          // fetchParams’s cross-origin isolated capability.
+          timingInfo.finalNetworkRequestStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability)
+        },
+
+        onResponseStarted () {
+          // Set timingInfo’s final network-response start time to the coarsened shared current
+          // time given fetchParams’s cross-origin isolated capability, immediately after the
+          // user agent’s HTTP parser receives the first byte of the response (e.g., frame header
+          // bytes for HTTP/2 or response status line for HTTP/1.x).
+          timingInfo.finalNetworkResponseStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability)
         },
 
         onHeaders (status, rawHeaders, resume, statusText) {

lib/fetch/util.js

@@ -265,9 +265,38 @@ function appendRequestOriginHeader (request) {
   }
 }
 
-function coarsenedSharedCurrentTime (crossOriginIsolatedCapability) {
+// https://w3c.github.io/hr-time/#dfn-coarsen-time
+function coarsenTime (timestamp, crossOriginIsolatedCapability) {
   // TODO
-  return performance.now()
+  return timestamp
+}
+
+// https://fetch.spec.whatwg.org/#clamp-and-coarsen-connection-timing-info
+function clampAndCoursenConnectionTimingInfo (connectionTimingInfo, defaultStartTime, crossOriginIsolatedCapability) {
+  if (!connectionTimingInfo?.startTime || connectionTimingInfo.startTime < defaultStartTime) {
+    return {
+      domainLookupStartTime: defaultStartTime,
+      domainLookupEndTime: defaultStartTime,
+      connectionStartTime: defaultStartTime,
+      connectionEndTime: defaultStartTime,
+      secureConnectionStartTime: defaultStartTime,
+      ALPNNegotiatedProtocol: connectionTimingInfo?.ALPNNegotiatedProtocol
+    }
+  }
+
+  return {
+    domainLookupStartTime: coarsenTime(connectionTimingInfo.domainLookupStartTime, crossOriginIsolatedCapability),
+    domainLookupEndTime: coarsenTime(connectionTimingInfo.domainLookupEndTime, crossOriginIsolatedCapability),
+    connectionStartTime: coarsenTime(connectionTimingInfo.connectionStartTime, crossOriginIsolatedCapability),
+    connectionEndTime: coarsenTime(connectionTimingInfo.connectionEndTime, crossOriginIsolatedCapability),
+    secureConnectionStartTime: coarsenTime(connectionTimingInfo.secureConnectionStartTime, crossOriginIsolatedCapability),
+    ALPNNegotiatedProtocol: connectionTimingInfo.ALPNNegotiatedProtocol
+  }
+}
+
+// https://w3c.github.io/hr-time/#dfn-coarsened-shared-current-time
+function coarsenedSharedCurrentTime (crossOriginIsolatedCapability) {
+  return coarsenTime(performance.now(), crossOriginIsolatedCapability)
 }
 
 // https://fetch.spec.whatwg.org/#create-an-opaque-timing-info
@@ -1145,6 +1174,7 @@ module.exports = {
   ReadableStreamFrom,
   toUSVString,
   tryUpgradeRequestToAPotentiallyTrustworthyURL,
+  clampAndCoursenConnectionTimingInfo,
   coarsenedSharedCurrentTime,
   determineRequestsReferrer,
   makePolicyContainer,

test/client-dispatch.js

@@ -4,6 +4,8 @@ const { test } = require('tap')
 const http = require('http')
 const { Client, Pool, errors } = require('..')
 const stream = require('stream')
+const { createSecureServer } = require('node:http2')
+const pem = require('https-pem')
 
 test('dispatch invalid opts', (t) => {
   t.plan(14)
@@ -813,3 +815,104 @@ test('dispatch onBodySent throws error', (t) => {
     })
   })
 })
+
+test('dispatches in expected order', (t) => {
+  const server = http.createServer((req, res) => {
+    res.end('ended')
+  })
+  t.teardown(server.close.bind(server))
+
+  server.listen(0, () => {
+    const client = new Pool(`http://localhost:${server.address().port}`)
+
+    t.plan(1)
+    t.teardown(client.close.bind(client))
+
+    const dispatches = []
+
+    client.dispatch({
+      path: '/',
+      method: 'POST',
+      body: 'body'
+    }, {
+      onConnect () {
+        dispatches.push('onConnect')
+      },
+      onBodySent () {
+        dispatches.push('onBodySent')
+      },
+      onResponseStarted () {
+        dispatches.push('onResponseStarted')
+      },
+      onHeaders () {
+        dispatches.push('onHeaders')
+      },
+      onData () {
+        dispatches.push('onData')
+      },
+      onComplete () {
+        dispatches.push('onComplete')
+        t.same(dispatches, ['onConnect', 'onBodySent', 'onResponseStarted', 'onHeaders', 'onData', 'onComplete'])
+      },
+      onError (err) {
+        t.error(err)
+      }
+    })
+  })
+})
+
+test('dispatches in expected order for http2', (t) => {
+  const server = createSecureServer(pem)
+  server.on('stream', (stream) => {
+    stream.respond({
+      'content-type': 'text/plain; charset=utf-8',
+      ':status': 200
+    })
+    stream.end('ended')
+  })
+
+  t.teardown(server.close.bind(server))
+
+  server.listen(0, () => {
+    const client = new Pool(`https://localhost:${server.address().port}`, {
+      connect: {
+        rejectUnauthorized: false
+      },
+      allowH2: true
+    })
+
+    t.plan(1)
+    t.teardown(client.close.bind(client))
+
+    const dispatches = []
+
+    client.dispatch({
+      path: '/',
+      method: 'POST',
+      body: 'body'
+    }, {
+      onConnect () {
+        dispatches.push('onConnect')
+      },
+      onBodySent () {
+        dispatches.push('onBodySent')
+      },
+      onResponseStarted () {
+        dispatches.push('onResponseStarted')
+      },
+      onHeaders () {
+        dispatches.push('onHeaders')
+      },
+      onData () {
+        dispatches.push('onData')
+      },
+      onComplete () {
+        dispatches.push('onComplete')
+        t.same(dispatches, ['onConnect', 'onBodySent', 'onResponseStarted', 'onHeaders', 'onData', 'onComplete'])
+      },
+      onError (err) {
+        t.error(err)
+      }
+    })
+  })
+})

test/fetch/resource-timing.js

@@ -70,3 +70,69 @@ test('should include encodedBodySize in performance entry', { skip }, (t) => {
 
   t.teardown(server.close.bind(server))
 })
+
+test('timing entries should be in order', { skip }, (t) => {
+  t.plan(13)
+  const obs = new PerformanceObserver(list => {
+    const [entry] = list.getEntries()
+
+    t.ok(entry.startTime > 0)
+    t.ok(entry.fetchStart >= entry.startTime)
+    t.ok(entry.domainLookupStart >= entry.fetchStart)
+    t.ok(entry.domainLookupEnd >= entry.domainLookupStart)
+    t.ok(entry.connectStart >= entry.domainLookupEnd)
+    t.ok(entry.connectEnd >= entry.connectStart)
+    t.ok(entry.requestStart >= entry.connectEnd)
+    t.ok(entry.responseStart >= entry.requestStart)
+    t.ok(entry.responseEnd >= entry.responseStart)
+    t.ok(entry.duration > 0)
+
+    t.ok(entry.redirectStart === 0)
+    t.ok(entry.redirectEnd === 0)
+
+    obs.disconnect()
+    performance.clearResourceTimings()
+  })
+
+  obs.observe({ entryTypes: ['resource'] })
+
+  const server = createServer((req, res) => {
+    res.end('ok')
+  }).listen(0, async () => {
+    const body = await fetch(`http://localhost:${server.address().port}/redirect`)
+    t.strictSame('ok', await body.text())
+  })
+
+  t.teardown(server.close.bind(server))
+})
+
+test('redirect timing entries should be included when redirecting', { skip }, (t) => {
+  t.plan(4)
+  const obs = new PerformanceObserver(list => {
+    const [entry] = list.getEntries()
+
+    t.ok(entry.redirectStart >= entry.startTime)
+    t.ok(entry.redirectEnd >= entry.redirectStart)
+    t.ok(entry.connectStart >= entry.redirectEnd)
+
+    obs.disconnect()
+    performance.clearResourceTimings()
+  })
+
+  obs.observe({ entryTypes: ['resource'] })
+
+  const server = createServer((req, res) => {
+    if (req.url === '/redirect') {
+      res.statusCode = 307
+      res.setHeader('location', '/redirect/')
+      res.end()
+      return
+    }
+    res.end('ok')
+  }).listen(0, async () => {
+    const body = await fetch(`http://localhost:${server.address().port}/redirect`)
+    t.strictSame('ok', await body.text())
+  })
+
+  t.teardown(server.close.bind(server))
+})

types/dispatcher.d.ts

@@ -210,6 +210,8 @@ declare namespace Dispatcher {
     onError?(err: Error): void;
     /** Invoked when request is upgraded either due to a `Upgrade` header or `CONNECT` method. */
     onUpgrade?(statusCode: number, headers: Buffer[] | string[] | null, socket: Duplex): void;
+    /** Invoked when response is received, before headers have been read. **/
+    onResponseStarted?(): void;
     /** Invoked when statusCode and headers have been received. May be invoked multiple times due to 1xx informational headers. */
     onHeaders?(statusCode: number, headers: Buffer[] | string[] | null, resume: () => void, statusText: string): boolean;
     /** Invoked when response payload data is received. */