From ca667f69bdeed38157013116058c1e2b751d8fcf Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sun, 12 Apr 2026 12:04:48 +0000 Subject: [PATCH 1/5] Initial plan From aaf6a2af6a160ad755d4daf4417e4b87e819f6cc Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sun, 12 Apr 2026 12:19:05 +0000 Subject: [PATCH 2/5] feat: populate dnslookup timing by capturing DNS resolution time on sockets Captures DNS lookup time via Socket.prototype.emit monkey-patch for the 'lookup' event. When the first request is sent on a socket, the DNS lookup time is calculated relative to the request start time and stored in the timing object. Closes node-modules/urllib#577 Agent-Logs-Url: https://github.com/node-modules/urllib/sessions/efde376e-b12f-42f6-9490-2ce39519fe7c Co-authored-by: fengmk2 <156269+fengmk2@users.noreply.github.com> --- src/diagnosticsChannel.ts | 16 ++++++++++++++++ src/symbols.ts | 2 ++ test/options.timing.test.ts | 3 +++ 3 files changed, 21 insertions(+) diff --git a/src/diagnosticsChannel.ts b/src/diagnosticsChannel.ts index 2b07a75e..e96fce2b 100644 --- a/src/diagnosticsChannel.ts +++ b/src/diagnosticsChannel.ts @@ -67,6 +67,15 @@ Socket.prototype.destroy = function (err?: any) { return destroySocket.call(this, err); }; +// capture DNS lookup time on socket via 'lookup' event +const originalSocketEmit = Socket.prototype.emit; +Socket.prototype.emit = function (this: SocketExtend, event: string, ...args: any[]) { + if (event === 'lookup') { + this[symbols.kSocketDnsLookupTime] = performance.now(); + } + return originalSocketEmit.apply(this, [event, ...args] as any); +} as typeof originalSocketEmit; + function getRequestOpaque(request: DiagnosticsChannel.Request, kHandler?: symbol) { if (!kHandler) return; const handler = Reflect.get(request, kHandler); @@ -201,6 +210,13 @@ export function initDiagnosticsChannel(): void { opaque[symbols.kRequestStartTime], socket[symbols.kSocketStartTime] as number, ); + // kSocketDnsLookupTime - kRequestStartTime = dns lookup time + if (socket[symbols.kSocketDnsLookupTime]) { + opaque[symbols.kRequestTiming].dnslookup = performanceTime( + opaque[symbols.kRequestStartTime], + socket[symbols.kSocketDnsLookupTime] as number, + ); + } } }); diff --git a/src/symbols.ts b/src/symbols.ts index 27774b82..aa2374c0 100644 --- a/src/symbols.ts +++ b/src/symbols.ts @@ -9,6 +9,7 @@ const symbols: { kSocketConnectHost: symbol; kSocketConnectPort: symbol; kSocketConnectProtocol: symbol; + kSocketDnsLookupTime: symbol; kHandledRequests: symbol; kHandledResponses: symbol; kRequestSocket: symbol; @@ -30,6 +31,7 @@ const symbols: { kSocketConnectHost: Symbol('socket connect params: host'), kSocketConnectPort: Symbol('socket connect params: port'), kSocketConnectProtocol: Symbol('socket connect params: protocol'), + kSocketDnsLookupTime: Symbol('socket dns lookup time'), kHandledRequests: Symbol('handled requests per socket'), kHandledResponses: Symbol('handled responses per socket'), kRequestSocket: Symbol('request on the socket'), diff --git a/test/options.timing.test.ts b/test/options.timing.test.ts index f99e5817..b7c61c33 100644 --- a/test/options.timing.test.ts +++ b/test/options.timing.test.ts @@ -30,6 +30,8 @@ describe('options.timing.test.ts', () => { assert(res.timing.waiting > 0); assert(res.timing.queuing > 0); assert(res.timing.connected > 0); + assert(res.timing.dnslookup > 0); + assert(res.timing.dnslookup <= res.timing.connected); assert(res.timing.requestHeadersSent > 0); assert(res.timing.requestSent > 0); assert(res.timing.contentDownload > 0); @@ -49,6 +51,7 @@ describe('options.timing.test.ts', () => { assert(res.timing.waiting > 0); assert(res.timing.queuing > 0); assert.equal(res.timing.connected, 0); + assert.equal(res.timing.dnslookup, 0); assert(res.timing.requestHeadersSent > 0); assert(res.timing.requestSent > 0); assert(res.timing.contentDownload > 0); From 73cc285299457b1da6c3351a981baf66fc7f10a5 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 16 Apr 2026 13:58:52 +0000 Subject: [PATCH 3/5] refactor: use net.client.socket diagnostics channel instead of Socket.prototype.emit monkey-patch Replace the global Socket.prototype.emit monkey-patch with a subscription to Node.js's net.client.socket diagnostics channel. This channel fires when a new TCP/IPC connection is initiated, giving us access to the socket before the 'lookup' event fires, so we can attach a targeted per-socket one-time listener instead of patching the global prototype. Agent-Logs-Url: https://github.com/node-modules/urllib/sessions/d5603429-8e76-46db-bd88-7a315ea660ba Co-authored-by: fengmk2 <156269+fengmk2@users.noreply.github.com> --- src/diagnosticsChannel.ts | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/src/diagnosticsChannel.ts b/src/diagnosticsChannel.ts index e96fce2b..16ed7a6a 100644 --- a/src/diagnosticsChannel.ts +++ b/src/diagnosticsChannel.ts @@ -67,14 +67,17 @@ Socket.prototype.destroy = function (err?: any) { return destroySocket.call(this, err); }; -// capture DNS lookup time on socket via 'lookup' event -const originalSocketEmit = Socket.prototype.emit; -Socket.prototype.emit = function (this: SocketExtend, event: string, ...args: any[]) { - if (event === 'lookup') { - this[symbols.kSocketDnsLookupTime] = performance.now(); +// capture DNS lookup time on socket via net.client.socket diagnostics channel +// this channel fires when a new TCP/IPC connection is initiated, giving us +// access to the socket before the 'lookup' event fires +diagnosticsChannel.subscribe('net.client.socket', (message: unknown) => { + const socket = (message as { socket: SocketExtend }).socket; + if (socket) { + socket.once('lookup', () => { + socket[symbols.kSocketDnsLookupTime] = performance.now(); + }); } - return originalSocketEmit.apply(this, [event, ...args] as any); -} as typeof originalSocketEmit; +}); function getRequestOpaque(request: DiagnosticsChannel.Request, kHandler?: symbol) { if (!kHandler) return; From 161c48e8d51cbfc3907f2a803cfdbea888a8fc8f Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 16 Apr 2026 14:23:35 +0000 Subject: [PATCH 4/5] docs: add timing fields documentation with text diagram to README Agent-Logs-Url: https://github.com/node-modules/urllib/sessions/7bc7fa06-09b7-40ca-aec2-e897a34a4933 Co-authored-by: fengmk2 <156269+fengmk2@users.noreply.github.com> --- README.md | 39 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/README.md b/README.md index 3147212a..b24e17fb 100644 --- a/README.md +++ b/README.md @@ -203,6 +203,45 @@ Response is normal object, it contains: - `timing`: timing object if timing enable. - `socket`: socket info +### Timing + +All timing values are milliseconds elapsed from the start of the request. Enable via `options.timing = true` (default). + +``` + ┌──────────┬──────────┬──────────┬─────────────────┬─────────────┬─────────┬─────────────────┐ + │ Queuing │ DNS │ TCP │ Request │ Request │ Waiting │ Content │ + │ │ Lookup │ Connect │ Headers Sent │ Body Sent │ (TTFB) │ Download │ + └──────────┴──────────┴──────────┴─────────────────┴─────────────┴─────────┴─────────────────┘ + | | | | | | | | + 0 queuing dnslookup connected requestHeadersSent requestSent waiting contentDownload +``` + +| Field | Description | +| --- | --- | +| `queuing` | Socket pool queuing time. The socket has been assigned to the request. | +| `dnslookup` | DNS lookup completed (only on first request of a new socket, `0` on reused sockets). | +| `connected` | TCP (or TLS) connection is established. | +| `requestHeadersSent` | Request headers have been written to the socket. | +| `requestSent` | Full request (headers + body) has been sent. | +| `waiting` | Time to First Byte (TTFB). Response headers have been received. | +| `contentDownload` | Response body and trailers have been fully received. | + +Example: + +```json +{ + "queuing": 2.8, + "dnslookup": 9.0, + "connected": 12.7, + "requestHeadersSent": 13.4, + "requestSent": 13.6, + "waiting": 24.0, + "contentDownload": 25.1 +} +``` + +> **Note**: `dnslookup` is `0` when the socket is reused from the pool (keep-alive), since no DNS resolution occurs. + ## Run test with debug log ```bash From b7028645c1a402779c674e2b7244f3b8d2260cef Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 16 Apr 2026 14:34:31 +0000 Subject: [PATCH 5/5] fix: format README table, move net.client.socket subscription into initDiagnosticsChannel, use explicit undefined check, relax dnslookup assertion Agent-Logs-Url: https://github.com/node-modules/urllib/sessions/5980bc15-0896-428f-8709-7929c8055eb5 Co-authored-by: fengmk2 <156269+fengmk2@users.noreply.github.com> --- README.md | 18 +++++++++--------- src/diagnosticsChannel.ts | 26 +++++++++++++------------- test/options.timing.test.ts | 2 +- 3 files changed, 23 insertions(+), 23 deletions(-) diff --git a/README.md b/README.md index b24e17fb..6f8c130c 100644 --- a/README.md +++ b/README.md @@ -216,15 +216,15 @@ All timing values are milliseconds elapsed from the start of the request. Enable 0 queuing dnslookup connected requestHeadersSent requestSent waiting contentDownload ``` -| Field | Description | -| --- | --- | -| `queuing` | Socket pool queuing time. The socket has been assigned to the request. | -| `dnslookup` | DNS lookup completed (only on first request of a new socket, `0` on reused sockets). | -| `connected` | TCP (or TLS) connection is established. | -| `requestHeadersSent` | Request headers have been written to the socket. | -| `requestSent` | Full request (headers + body) has been sent. | -| `waiting` | Time to First Byte (TTFB). Response headers have been received. | -| `contentDownload` | Response body and trailers have been fully received. | +| Field | Description | +| -------------------- | ------------------------------------------------------------------------------------ | +| `queuing` | Socket pool queuing time. The socket has been assigned to the request. | +| `dnslookup` | DNS lookup completed (only on first request of a new socket, `0` on reused sockets). | +| `connected` | TCP (or TLS) connection is established. | +| `requestHeadersSent` | Request headers have been written to the socket. | +| `requestSent` | Full request (headers + body) has been sent. | +| `waiting` | Time to First Byte (TTFB). Response headers have been received. | +| `contentDownload` | Response body and trailers have been fully received. | Example: diff --git a/src/diagnosticsChannel.ts b/src/diagnosticsChannel.ts index 16ed7a6a..b813a565 100644 --- a/src/diagnosticsChannel.ts +++ b/src/diagnosticsChannel.ts @@ -67,18 +67,6 @@ Socket.prototype.destroy = function (err?: any) { return destroySocket.call(this, err); }; -// capture DNS lookup time on socket via net.client.socket diagnostics channel -// this channel fires when a new TCP/IPC connection is initiated, giving us -// access to the socket before the 'lookup' event fires -diagnosticsChannel.subscribe('net.client.socket', (message: unknown) => { - const socket = (message as { socket: SocketExtend }).socket; - if (socket) { - socket.once('lookup', () => { - socket[symbols.kSocketDnsLookupTime] = performance.now(); - }); - } -}); - function getRequestOpaque(request: DiagnosticsChannel.Request, kHandler?: symbol) { if (!kHandler) return; const handler = Reflect.get(request, kHandler); @@ -99,6 +87,18 @@ export function initDiagnosticsChannel(): void { if (initedDiagnosticsChannel) return; initedDiagnosticsChannel = true; + // capture DNS lookup time on socket via net.client.socket diagnostics channel + // this channel fires when a new TCP/IPC connection is initiated, giving us + // access to the socket before the 'lookup' event fires + subscribe('net.client.socket', (message: unknown) => { + const socket = (message as { socket: SocketExtend }).socket; + if (socket) { + socket.once('lookup', () => { + socket[symbols.kSocketDnsLookupTime] = performance.now(); + }); + } + }); + let kHandler: symbol; // This message is published when a new outgoing request is created. // Note: a request is only loosely completed to a given socket. @@ -214,7 +214,7 @@ export function initDiagnosticsChannel(): void { socket[symbols.kSocketStartTime] as number, ); // kSocketDnsLookupTime - kRequestStartTime = dns lookup time - if (socket[symbols.kSocketDnsLookupTime]) { + if (socket[symbols.kSocketDnsLookupTime] !== undefined) { opaque[symbols.kRequestTiming].dnslookup = performanceTime( opaque[symbols.kRequestStartTime], socket[symbols.kSocketDnsLookupTime] as number, diff --git a/test/options.timing.test.ts b/test/options.timing.test.ts index b7c61c33..69214ff2 100644 --- a/test/options.timing.test.ts +++ b/test/options.timing.test.ts @@ -30,7 +30,7 @@ describe('options.timing.test.ts', () => { assert(res.timing.waiting > 0); assert(res.timing.queuing > 0); assert(res.timing.connected > 0); - assert(res.timing.dnslookup > 0); + assert(res.timing.dnslookup >= 0); assert(res.timing.dnslookup <= res.timing.connected); assert(res.timing.requestHeadersSent > 0); assert(res.timing.requestSent > 0);