From 012ad991be310c2655b797a23c0ac1f29a798e41 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Thu, 30 Nov 2023 23:29:44 +0100 Subject: [PATCH 1/9] Add resource timing entries for connection, request and response --- lib/client.js | 1 + lib/core/request.js | 4 +++ lib/fetch/index.js | 14 +++++++- lib/fetch/util.js | 33 +++++++++++++++++- test/fetch/resource-timing.js | 66 +++++++++++++++++++++++++++++++++++ 5 files changed, 116 insertions(+), 2 deletions(-) diff --git a/lib/client.js b/lib/client.js index 22cb39039da..093417de357 100644 --- a/lib/client.js +++ b/lib/client.js @@ -740,6 +740,7 @@ class Parser { if (!request) { return -1 } + request.onMessageBegin() } onHeaderField (buf) { diff --git a/lib/core/request.js b/lib/core/request.js index 3697e6a3acc..d264e233acd 100644 --- a/lib/core/request.js +++ b/lib/core/request.js @@ -263,6 +263,10 @@ class Request { } } + onMessageBegin () { + return this[kHandler].onMessageBegin?.() + } + onHeaders (statusCode, headers, resume, statusText) { assert(!this.aborted) assert(!this.completed) diff --git a/lib/fetch/index.js b/lib/fetch/index.js index 17c3d87ea62..b96dc0aa0ea 100644 --- a/lib/fetch/index.js +++ b/lib/fetch/index.js @@ -40,7 +40,8 @@ const { isomorphicEncode, urlIsLocal, urlIsHttpHttpsScheme, - urlHasHttpsScheme + urlHasHttpsScheme, + clampAndCoursenConnectionTimingInfo } = require('./util') const { kState, kHeaders, kGuard, kRealm } = require('./symbols') const assert = require('assert') @@ -1970,6 +1971,9 @@ async function httpNetworkFetch ( // TODO (fix): Do we need connection here? const { connection } = fetchParams.controller + // TODO: pass connection timing info + timingInfo.finalConnectionTimingInfo = clampAndCoursenConnectionTimingInfo(undefined, timingInfo.postRedirectStartTime, fetchParams.crossOriginIsolatedCapability) + if (connection.destroyed) { abort(new DOMException('The operation was aborted.', 'AbortError')) } else { @@ -1978,6 +1982,14 @@ async function httpNetworkFetch ( } }, + onRequestSent () { + timingInfo.finalNetworkRequestStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) + }, + + onMessageBegin () { + timingInfo.finalNetworkResponseStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) + }, + onHeaders (status, headersList, resume, statusText) { if (status < 200) { return diff --git a/lib/fetch/util.js b/lib/fetch/util.js index b12142c7f42..a02e46cc39e 100644 --- a/lib/fetch/util.js +++ b/lib/fetch/util.js @@ -311,9 +311,39 @@ function appendRequestOriginHeader (request) { } } +// https://w3c.github.io/hr-time/#dfn-coarsen-time +function coarsenTime (timestamp, crossOriginIsolatedCapability) { + // TODO + 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) { // TODO - return performance.now() + return coarsenTime(performance.now(), crossOriginIsolatedCapability) } // https://fetch.spec.whatwg.org/#create-an-opaque-timing-info @@ -1030,6 +1060,7 @@ module.exports = { ReadableStreamFrom, toUSVString, tryUpgradeRequestToAPotentiallyTrustworthyURL, + clampAndCoursenConnectionTimingInfo, coarsenedSharedCurrentTime, determineRequestsReferrer, makePolicyContainer, diff --git a/test/fetch/resource-timing.js b/test/fetch/resource-timing.js index d266f28bdc8..c79733abb5a 100644 --- a/test/fetch/resource-timing.js +++ b/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)) +}) From a20724f17dbabbc34c0fbee180b0f6fc1db2bc34 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Sat, 2 Dec 2023 08:57:35 +0100 Subject: [PATCH 2/9] Extend Dispatcher API with onMessageBegin --- docs/api/Dispatcher.md | 1 + types/dispatcher.d.ts | 2 ++ 2 files changed, 3 insertions(+) diff --git a/docs/api/Dispatcher.md b/docs/api/Dispatcher.md index fd463bfea16..df21e08bb39 100644 --- a/docs/api/Dispatcher.md +++ b/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'`. +* **onMessageBegin** `() => 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. diff --git a/types/dispatcher.d.ts b/types/dispatcher.d.ts index efc53eea791..83b74e461d0 100644 --- a/types/dispatcher.d.ts +++ b/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. **/ + onMessageBegin?(): 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. */ From f18d5eaa0c499ed354c79cebcde32ef26001824f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Sun, 3 Dec 2023 14:31:12 +0100 Subject: [PATCH 3/9] Change onMessageBegin to onResponseStarted --- docs/api/Dispatcher.md | 2 +- lib/client.js | 2 +- lib/core/request.js | 4 ++-- lib/fetch/index.js | 2 +- types/dispatcher.d.ts | 2 +- 5 files changed, 6 insertions(+), 6 deletions(-) diff --git a/docs/api/Dispatcher.md b/docs/api/Dispatcher.md index df21e08bb39..0c678fc8623 100644 --- a/docs/api/Dispatcher.md +++ b/docs/api/Dispatcher.md @@ -209,7 +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'`. -* **onMessageBegin** `() => void` (optional) - Invoked when response is received, before headers have been read. +* **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. diff --git a/lib/client.js b/lib/client.js index 6ce1f4e487b..fbf20dc8341 100644 --- a/lib/client.js +++ b/lib/client.js @@ -740,7 +740,7 @@ class Parser { if (!request) { return -1 } - request.onMessageBegin() + request.onResponseStarted() } onHeaderField (buf) { diff --git a/lib/core/request.js b/lib/core/request.js index 2532912ef00..35bb47735bf 100644 --- a/lib/core/request.js +++ b/lib/core/request.js @@ -259,8 +259,8 @@ class Request { } } - onMessageBegin () { - return this[kHandler].onMessageBegin?.() + onResponseStarted () { + return this[kHandler].onResponseStarted?.() } onHeaders (statusCode, headers, resume, statusText) { diff --git a/lib/fetch/index.js b/lib/fetch/index.js index 30990acb6b3..8623c991639 100644 --- a/lib/fetch/index.js +++ b/lib/fetch/index.js @@ -2114,7 +2114,7 @@ async function httpNetworkFetch ( timingInfo.finalNetworkRequestStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) }, - onMessageBegin () { + onResponseStarted () { timingInfo.finalNetworkResponseStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) }, diff --git a/types/dispatcher.d.ts b/types/dispatcher.d.ts index 83b74e461d0..24bf1519a25 100644 --- a/types/dispatcher.d.ts +++ b/types/dispatcher.d.ts @@ -211,7 +211,7 @@ declare namespace Dispatcher { /** 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. **/ - onMessageBegin?(): void; + 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. */ From 5eebad70e1c018321f646364bdf59afd4daf5a97 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Sun, 3 Dec 2023 18:02:26 +0100 Subject: [PATCH 4/9] Log requestStart at start of request --- lib/fetch/index.js | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/lib/fetch/index.js b/lib/fetch/index.js index 8623c991639..2cfffbf32ff 100644 --- a/lib/fetch/index.js +++ b/lib/fetch/index.js @@ -2108,9 +2108,7 @@ async function httpNetworkFetch ( fetchParams.controller.on('terminated', abort) this.abort = connection.abort = abort } - }, - - onRequestSent () { + timingInfo.finalNetworkRequestStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) }, From 6d1811767ceaedb5efd7bbd880ae0ee861be8ffd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Sun, 3 Dec 2023 18:06:43 +0100 Subject: [PATCH 5/9] Lint --- lib/fetch/index.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/fetch/index.js b/lib/fetch/index.js index 2cfffbf32ff..65c4f588083 100644 --- a/lib/fetch/index.js +++ b/lib/fetch/index.js @@ -2108,7 +2108,7 @@ async function httpNetworkFetch ( fetchParams.controller.on('terminated', abort) this.abort = connection.abort = abort } - + timingInfo.finalNetworkRequestStartTime = coarsenedSharedCurrentTime(fetchParams.crossOriginIsolatedCapability) }, From 72308818c4548ada86b16d4cdf92dd0b45c56212 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Tue, 5 Dec 2023 10:14:19 +0100 Subject: [PATCH 6/9] Add call to request.onResponseStarted for http2 --- lib/client.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/client.js b/lib/client.js index fbf20dc8341..fd2defd567c 100644 --- a/lib/client.js +++ b/lib/client.js @@ -1784,6 +1784,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() From 8d4b7863bc894fb4da3f70035ce5d09bc65cba12 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Tue, 5 Dec 2023 19:59:41 +0100 Subject: [PATCH 7/9] Remove TODO --- lib/fetch/util.js | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/fetch/util.js b/lib/fetch/util.js index 751dfa81744..046141aa5ae 100644 --- a/lib/fetch/util.js +++ b/lib/fetch/util.js @@ -342,7 +342,6 @@ function clampAndCoursenConnectionTimingInfo (connectionTimingInfo, defaultStart // https://w3c.github.io/hr-time/#dfn-coarsened-shared-current-time function coarsenedSharedCurrentTime (crossOriginIsolatedCapability) { - // TODO return coarsenTime(performance.now(), crossOriginIsolatedCapability) } From f43fa9d0ce7ee0cb81876285c755a80de882355d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Tue, 5 Dec 2023 22:13:11 +0100 Subject: [PATCH 8/9] Add tests ensuring order of client-dispatches --- test/client-dispatch.js | 103 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 103 insertions(+) diff --git a/test/client-dispatch.js b/test/client-dispatch.js index c3de37ae2a9..781118cc058 100644 --- a/test/client-dispatch.js +++ b/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) + } + }) + }) +}) From b255acdbc89027d1134ce91b1a744d1388bfbe54 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torstein=20Bj=C3=B8rnstad?= Date: Tue, 5 Dec 2023 22:23:44 +0100 Subject: [PATCH 9/9] Add comments for timinginfo entries --- lib/fetch/index.js | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/lib/fetch/index.js b/lib/fetch/index.js index 65c4f588083..c59440178a1 100644 --- a/lib/fetch/index.js +++ b/lib/fetch/index.js @@ -2099,7 +2099,10 @@ async function httpNetworkFetch ( // TODO (fix): Do we need connection here? const { connection } = fetchParams.controller - // TODO: pass connection timing info + // 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) { @@ -2109,10 +2112,16 @@ async function httpNetworkFetch ( 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) },