feat: support tracing on diagnostics_channel

.github/workflows/codeql-analysis.yml

@@ -17,8 +17,6 @@ on:
   pull_request:
     # The branches below must be a subset of the branches above
     branches: [ "master" ]
-  schedule:
-    - cron: '42 5 * * 2'
 
 jobs:
   analyze:

.github/workflows/nodejs.yml

@@ -12,7 +12,7 @@ on:
 jobs:
   Job:
     name: Node.js
-    uses: artusjs/github-actions/.github/workflows/node-test.yml@v1
+    uses: node-modules/github-actions/.github/workflows/node-test.yml@master
     with:
       os: 'ubuntu-latest, macos-latest, windows-latest'
-      version: '14.19.3, 14, 16, 18, 20.1.0'
+      version: '14.19.3, 14, 16, 18, 20'

.github/workflows/release.yml

@@ -4,12 +4,10 @@ on:
   push:
     branches: [ master ]
 
-  workflow_dispatch: {}
-
 jobs:
   release:
     name: Node.js
-    uses: artusjs/github-actions/.github/workflows/node-release.yml@v1
+    uses: node-modules/github-actions/.github/workflows/node-release.yml@master
     secrets:
       NPM_TOKEN: ${{ secrets.NPM_TOKEN }}
       GIT_TOKEN: ${{ secrets.GIT_TOKEN }}

README.md

@@ -200,10 +200,7 @@ Response is normal object, it contains:
 - `aborted`: response was aborted or not
 - `rt`: total request and response time in ms.
 - `timing`: timing object if timing enable.
-- `remoteAddress`: http server ip address
-- `remotePort`: http server ip port
-- `socketHandledRequests`: socket already handled request count
-- `socketHandledResponses`: socket already handled response count
+- `socket`: socket info
 
 ## Run test with debug log
 

examples/timing.cjs

@@ -0,0 +1,23 @@
+const urllib = require('..');
+
+const url = process.argv[2] || 'https://cnodejs.org';
+console.log('timing: %s', url);
+
+const count = 10000;
+
+async function request(index) {
+  if (index === count) {
+    return;
+  }
+  const res = await urllib.request(url, {
+    // data: { wd: 'nodejs' },
+  });
+  console.log('---------------------------');
+  console.log('No#%d: %s, content size: %d, requestUrls: %o, socket: %o, rt: %o',
+    index, res.statusCode, res.data.length, res.res.requestUrls, res.res.socket, res.res.rt);
+  console.log(res.res.timing, res.headers);
+  index++;
+  setImmediate(request.bind(null, index));
+}
+
+request(1);

package.json

@@ -53,6 +53,7 @@
     "build:test": "npm run build && npm run build:cjs:test && npm run build:esm:test && npm run test-tsc",
     "test-tsc": "tsc -p ./test/fixtures/ts/tsconfig.json",
     "test": "npm run lint && vitest run",
+    "test-keepalive": "cross-env TEST_KEEPALIVE_COUNT=50 vitest run --test-timeout 120000 keep-alive-header.test.ts",
     "cov": "vitest run --coverage",
     "ci": "npm run lint && npm run cov && npm run build:test",
     "contributor": "git-contributor",
@@ -78,8 +79,9 @@
     "@types/pump": "^1.1.1",
     "@types/selfsigned": "^2.0.1",
     "@types/tar-stream": "^2.2.2",
-    "@vitest/coverage-c8": "^0.29.7",
+    "@vitest/coverage-v8": "^0.32.0",
     "busboy": "^1.6.0",
+    "cross-env": "^7.0.3",
     "eslint": "^8.25.0",
     "eslint-config-egg": "^12.1.0",
     "git-contributor": "^2.0.0",
@@ -88,7 +90,7 @@
     "selfsigned": "^2.0.1",
     "tar-stream": "^2.2.0",
     "typescript": "^5.0.4",
-    "vitest": "^0.31.1"
+    "vitest": "^0.32.0"
   },
   "engines": {
     "node": ">= 14.19.3"

src/HttpClient.ts

@@ -1,3 +1,4 @@
+import diagnosticsChannel from 'node:diagnostics_channel';
 import { EventEmitter } from 'node:events';
 import { LookupFunction } from 'node:net';
 import { STATUS_CODES } from 'node:http';
@@ -29,7 +30,7 @@ import pump from 'pump';
 // Compatible with old style formstream
 import FormStream from 'formstream';
 import { HttpAgent, CheckAddressFunction } from './HttpAgent';
-import { RequestURL, RequestOptions, HttpMethod } from './Request';
+import { RequestURL, RequestOptions, HttpMethod, RequestMeta } from './Request';
 import { RawResponseWithMeta, HttpClientResponse, SocketInfo } from './Response';
 import { parseJSON, sleep, digestAuthHeader, globalId, performanceTime, isReadable } from './utils';
 import symbols from './symbols';
@@ -137,8 +138,25 @@ function defaultIsRetry(response: HttpClientResponse) {
 
 type RequestContext = {
   retries: number;
+  requestStartTime?: number;
 };
 
+const channels = {
+  request: diagnosticsChannel.channel('urllib:request'),
+  response: diagnosticsChannel.channel('urllib:response'),
+};
+
+export type RequestDiagnosticsMessage = {
+  request: RequestMeta;
+};
+
+export type ResponseDiagnosticsMessage = {
+  request: RequestMeta;
+  response: RawResponseWithMeta;
+  error?: Error;
+};
+
+
 export class HttpClient extends EventEmitter {
   #defaultArgs?: RequestOptions;
   #dispatcher?: Dispatcher;
@@ -188,6 +206,7 @@ export class HttpClient extends EventEmitter {
     const headers: IncomingHttpHeaders = {};
     const args = {
       retry: 0,
+      timing: true,
       ...this.#defaultArgs,
       ...options,
       // keep method and headers exists on args for request event handler to easy use
@@ -198,7 +217,10 @@ export class HttpClient extends EventEmitter {
       retries: 0,
       ...requestContext,
     };
-    const requestStartTime = performance.now();
+    if (!requestContext.requestStartTime) {
+      requestContext.requestStartTime = performance.now();
+    }
+    const requestStartTime = requestContext.requestStartTime;
 
     // https://developer.chrome.com/docs/devtools/network/reference/?utm_source=devtools#timing-explanation
     const timing = {
@@ -232,8 +254,8 @@ export class HttpClient extends EventEmitter {
       args,
       ctx: args.ctx,
       retries: requestContext.retries,
-    };
-    const socketInfo = {
+    } as RequestMeta;
+    const socketInfo: SocketInfo = {
       id: 0,
       localAddress: '',
       localPort: 0,
@@ -438,6 +460,9 @@ export class HttpClient extends EventEmitter {
       debug('Request#%d %s %s, headers: %j, headersTimeout: %s, bodyTimeout: %s',
         requestId, requestOptions.method, requestUrl.href, headers, headersTimeout, bodyTimeout);
       requestOptions.headers = headers;
+      channels.request.publish({
+        request: reqMeta,
+      } as RequestDiagnosticsMessage);
       if (this.listenerCount('request') > 0) {
         this.emit('request', reqMeta);
       }
@@ -556,6 +581,10 @@ export class HttpClient extends EventEmitter {
         }
       }
 
+      channels.response.publish({
+        request: reqMeta,
+        response: res,
+      } as ResponseDiagnosticsMessage);
       if (this.listenerCount('response') > 0) {
         this.emit('response', {
           requestId,
@@ -577,18 +606,37 @@ export class HttpClient extends EventEmitter {
         err = new HttpClientRequestTimeoutError(headersTimeout, { cause: e });
       } else if (err.name === 'BodyTimeoutError') {
         err = new HttpClientRequestTimeoutError(bodyTimeout, { cause: e });
+      } else if (err.code === 'UND_ERR_SOCKET' || err.code === 'ECONNRESET') {
+        // auto retry on socket error, https://github.com/node-modules/urllib/issues/454
+        if (args.retry > 0 && requestContext.retries < args.retry) {
+          if (args.retryDelay) {
+            await sleep(args.retryDelay);
+          }
+          requestContext.retries++;
+          return await this.#requestInternal(url, options, requestContext);
+        }
       }
       err.opaque = orginalOpaque;
       err.status = res.status;
       err.headers = res.headers;
       err.res = res;
+      if (err.socket) {
+        // store rawSocket
+        err._rawSocket = err.socket;
+      }
+      err.socket = socketInfo;
       // make sure requestUrls not empty
       if (res.requestUrls.length === 0) {
         res.requestUrls.push(requestUrl.href);
       }
       res.rt = performanceTime(requestStartTime);
       this.#updateSocketInfo(socketInfo, internalOpaque);
 
+      channels.response.publish({
+        request: reqMeta,
+        response: res,
+        error: err,
+      } as ResponseDiagnosticsMessage);
       if (this.listenerCount('response') > 0) {
         this.emit('response', {
           requestId,
@@ -611,13 +659,16 @@ export class HttpClient extends EventEmitter {
       socketInfo.id = socket[symbols.kSocketId];
       socketInfo.handledRequests = socket[symbols.kHandledRequests];
       socketInfo.handledResponses = socket[symbols.kHandledResponses];
-      socketInfo.localAddress = socket.localAddress;
-      socketInfo.localPort = socket.localPort;
+      socketInfo.localAddress = socket[symbols.kSocketLocalAddress];
+      socketInfo.localPort = socket[symbols.kSocketLocalPort];
       socketInfo.remoteAddress = socket.remoteAddress;
       socketInfo.remotePort = socket.remotePort;
       socketInfo.remoteFamily = socket.remoteFamily;
       socketInfo.bytesRead = socket.bytesRead;
       socketInfo.bytesWritten = socket.bytesWritten;
+      socketInfo.connectedTime = socket[symbols.kSocketConnectedTime];
+      socketInfo.lastRequestEndTime = socket[symbols.kSocketRequestEndTime];
+      socket[symbols.kSocketRequestEndTime] = new Date();
     }
   }
 }

src/Request.ts

@@ -99,7 +99,7 @@ export type RequestOptions = {
    * */
   gzip?: boolean;
   /**
-   * Enable timing or not, default is false.
+   * Enable timing or not, default is true.
    * */
   timing?: boolean;
   /**
@@ -134,3 +134,11 @@ export type RequestOptions = {
   /** Default: `64 KiB` */
   highWaterMark?: number;
 };
+
+export type RequestMeta = {
+  requestId: number;
+  url: string;
+  args: RequestOptions;
+  ctx?: unknown;
+  retries: number;
+};

src/Response.ts

@@ -12,6 +12,8 @@ export type SocketInfo = {
   bytesRead: number;
   handledRequests: number;
   handledResponses: number;
+  connectedTime?: Date;
+  lastRequestEndTime?: Date;
 };
 
 /**