feat: print more socket info on UND_ERR_CONNECT_TIMEOUT error (#477)

.gitignore

@@ -12,6 +12,7 @@ src/**/*.d.ts
 !src/formstream.d.ts
 .DS_Store
 test/fixtures/ts/*.js
+test/fixtures/ts-cjs-es2021/*.js
 test/fixtures/ts-esm/*.js
 .eslintcache
 .tshy*

examples/httpclient.cjs

@@ -12,7 +12,7 @@ function tryHttpclient(HttpClient, name) {
   urllib.on('response', function(info) {
     // console.log(name, httpAgent, httpAgent.getCurrentStatus());
     // console.log(name, httpsAgent, httpsAgent.getCurrentStatus());
-    console.log(name, info.res);
+    console.log('response', name, info.res);
   });
   urllib.request('https://nodejs.org', options)
     .then(function() {
@@ -22,6 +22,6 @@ function tryHttpclient(HttpClient, name) {
       return urllib.request('https://nodejs.org/en/', options);
     })
     .catch(function(err) {
-      console.error(err);
+      console.error('catch', err);
     });
 }

package.json

@@ -32,8 +32,9 @@
     "build:esm:test": "cd test/esm && rm -rf node_modules && npm link ../.. && node index.js",
     "build:mts:test": "cd test/mts && rm -rf node_modules && npm link ../.. && tsc",
     "build:test": "npm run build && npm run build:cjs:test && npm run build:esm:test && npm run build:mts:test && npm run test-tsc",
-    "test-tsc": "npm run test-tsc:cjs && npm run test-tsc:esm",
+    "test-tsc": "npm run test-tsc:cjs:es2021 && npm run test-tsc:cjs && npm run test-tsc:esm",
     "test-tsc:cjs": "cd test/fixtures/ts && rm -rf node_modules && npm link ../../.. && npm run build",
+    "test-tsc:cjs:es2021": "cd test/fixtures/ts-cjs-es2021 && rm -rf node_modules && npm link ../../.. && npm run build",
     "test-tsc:esm": "cd test/fixtures/ts-esm && rm -rf node_modules && npm link ../../.. && npm run build",
     "test": "npm run lint && vitest run",
     "test-keepalive": "cross-env TEST_KEEPALIVE_COUNT=50 vitest run --test-timeout 180000 keep-alive-header.test.ts",

src/HttpAgent.ts

@@ -77,7 +77,7 @@ export class HttpAgent extends Agent {
       }
       const family = isIP(hostname);
       if (family === 4 || family === 6) {
-        // if request hostname is ip, custom lookup won't excute
+        // if request hostname is ip, custom lookup won't execute
         if (!this.#checkAddress(hostname, family)) {
           throw new IllegalAddressError(hostname, hostname, family);
         }

src/HttpClient.ts

@@ -38,6 +38,7 @@ import { RawResponseWithMeta, HttpClientResponse, SocketInfo } from './Response.
 import { parseJSON, sleep, digestAuthHeader, globalId, performanceTime, isReadable } from './utils.js';
 import symbols from './symbols.js';
 import { initDiagnosticsChannel } from './diagnosticsChannel.js';
+import { HttpClientConnectTimeoutError, HttpClientRequestTimeoutError } from './HttpClientError.js';
 
 type Exists<T> = T extends undefined ? never : T;
 type UndiciRequestOption = Exists<Parameters<typeof undiciRequest>[1]>;
@@ -121,15 +122,6 @@ class BlobFromStream {
   }
 }
 
-class HttpClientRequestTimeoutError extends Error {
-  constructor(timeout: number, options: ErrorOptions) {
-    const message = `Request timeout for ${timeout} ms`;
-    super(message, options);
-    this.name = this.constructor.name;
-    Error.captureStackTrace(this, this.constructor);
-  }
-}
-
 export const HEADER_USER_AGENT = createUserAgent('node-urllib', 'VERSION');
 
 function getFileName(stream: Readable) {
@@ -653,13 +645,15 @@ export class HttpClient extends EventEmitter {
       }
 
       return clientResponse;
-    } catch (e: any) {
-      debug('Request#%d throw error: %s', requestId, e);
-      let err = e;
+    } catch (rawError: any) {
+      debug('Request#%d throw error: %s', requestId, rawError);
+      let err = rawError;
       if (err.name === 'HeadersTimeoutError') {
-        err = new HttpClientRequestTimeoutError(headersTimeout, { cause: e });
+        err = new HttpClientRequestTimeoutError(headersTimeout, { cause: err });
       } else if (err.name === 'BodyTimeoutError') {
-        err = new HttpClientRequestTimeoutError(bodyTimeout, { cause: e });
+        err = new HttpClientRequestTimeoutError(bodyTimeout, { cause: err });
+      } else if (err.code === 'UND_ERR_CONNECT_TIMEOUT') {
+        err = new HttpClientConnectTimeoutError(err.message, err.code, { cause: err });
       } 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.socketErrorRetry > 0 && requestContext.socketErrorRetries < args.socketErrorRetry) {
@@ -681,7 +675,7 @@ export class HttpClient extends EventEmitter {
         res.requestUrls.push(requestUrl.href);
       }
       res.rt = performanceTime(requestStartTime);
-      this.#updateSocketInfo(socketInfo, internalOpaque);
+      this.#updateSocketInfo(socketInfo, internalOpaque, rawError);
 
       channels.response.publish({
         request: reqMeta,
@@ -704,21 +698,38 @@ export class HttpClient extends EventEmitter {
     }
   }
 
-  #updateSocketInfo(socketInfo: SocketInfo, internalOpaque: any) {
-    const socket = internalOpaque[symbols.kRequestSocket];
+  #updateSocketInfo(socketInfo: SocketInfo, internalOpaque: any, err?: any) {
+    const socket = internalOpaque[symbols.kRequestSocket] ?? err?.[symbols.kErrorSocket];
     if (socket) {
       socketInfo.id = socket[symbols.kSocketId];
       socketInfo.handledRequests = socket[symbols.kHandledRequests];
       socketInfo.handledResponses = socket[symbols.kHandledResponses];
-      socketInfo.localAddress = socket[symbols.kSocketLocalAddress];
-      socketInfo.localPort = socket[symbols.kSocketLocalPort];
-      socketInfo.remoteAddress = socket.remoteAddress;
-      socketInfo.remotePort = socket.remotePort;
-      socketInfo.remoteFamily = socket.remoteFamily;
+      if (socket[symbols.kSocketLocalAddress]) {
+        socketInfo.localAddress = socket[symbols.kSocketLocalAddress];
+        socketInfo.localPort = socket[symbols.kSocketLocalPort];
+      }
+      if (socket.remoteAddress) {
+        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];
+      if (socket[symbols.kSocketConnectErrorTime]) {
+        socketInfo.connectErrorTime = socket[symbols.kSocketConnectErrorTime];
+        if (Array.isArray(socket.autoSelectFamilyAttemptedAddresses)) {
+          socketInfo.attemptedRemoteAddresses = socket.autoSelectFamilyAttemptedAddresses;
+        }
+        socketInfo.connectProtocol = socket[symbols.kSocketConnectProtocol];
+        socketInfo.connectHost = socket[symbols.kSocketConnectHost];
+        socketInfo.connectPort = socket[symbols.kSocketConnectPort];
+      }
+      if (socket[symbols.kSocketConnectedTime]) {
+        socketInfo.connectedTime = socket[symbols.kSocketConnectedTime];
+      }
+      if (socket[symbols.kSocketRequestEndTime]) {
+        socketInfo.lastRequestEndTime = socket[symbols.kSocketRequestEndTime];
+      }
       socket[symbols.kSocketRequestEndTime] = new Date();
     }
   }

src/HttpClientError.ts

@@ -0,0 +1,34 @@
+import type { RawResponseWithMeta, SocketInfo } from './Response.js';
+import type { IncomingHttpHeaders } from './IncomingHttpHeaders.js';
+
+// need to support ES2021
+interface ErrorOptions {
+  cause?: Error;
+}
+
+export class HttpClientRequestError extends Error {
+  status?: number;
+  headers?: IncomingHttpHeaders;
+  socket?: SocketInfo;
+  res?: RawResponseWithMeta;
+}
+
+export class HttpClientRequestTimeoutError extends HttpClientRequestError {
+  constructor(timeout: number, options: ErrorOptions) {
+    const message = `Request timeout for ${timeout} ms`;
+    super(message, options);
+    this.name = this.constructor.name;
+    Error.captureStackTrace(this, this.constructor);
+  }
+}
+
+export class HttpClientConnectTimeoutError extends HttpClientRequestError {
+  code: string;
+
+  constructor(message: string, code: string, options: ErrorOptions) {
+    super(message, options);
+    this.name = this.constructor.name;
+    this.code = code;
+    Error.captureStackTrace(this, this.constructor);
+  }
+}

src/Response.ts

@@ -13,7 +13,12 @@ export type SocketInfo = {
   handledRequests: number;
   handledResponses: number;
   connectedTime?: Date;
+  connectErrorTime?: Date;
   lastRequestEndTime?: Date;
+  attemptedRemoteAddresses?: string[];
+  connectProtocol?: string;
+  connectHost?: string;
+  connectPort?: string;
 };
 
 /**

src/diagnosticsChannel.ts

@@ -35,9 +35,25 @@ function formatSocket(socket: Socket) {
     localPort: socket[symbols.kSocketLocalPort],
     remoteAddress: socket.remoteAddress,
     remotePort: socket.remotePort,
+    attemptedAddresses: socket.autoSelectFamilyAttemptedAddresses,
+    connecting: socket.connecting,
   };
 }
 
+// make sure error contains socket info
+const kDestroy = Symbol('kDestroy');
+Socket.prototype[kDestroy] = Socket.prototype.destroy;
+Socket.prototype.destroy = function(err?: any) {
+  if (err) {
+    Object.defineProperty(err, symbols.kErrorSocket, {
+      // don't show on console log
+      enumerable: false,
+      value: this,
+    });
+  }
+  return this[kDestroy](err);
+};
+
 export function initDiagnosticsChannel() {
   // makre sure init global DiagnosticsChannel once
   if (initedDiagnosticsChannel) return;
@@ -67,10 +83,37 @@ export function initDiagnosticsChannel() {
   });
 
   // diagnosticsChannel.channel('undici:client:beforeConnect')
-  // diagnosticsChannel.channel('undici:client:connectError')
+
+  subscribe('undici:client:connectError', (message, name) => {
+    const { error, connectParams } = message as DiagnosticsChannel.ClientConnectErrorMessage & { error: any };
+    let { socket } = message as DiagnosticsChannel.ClientConnectErrorMessage;
+    if (!socket && error[symbols.kErrorSocket]) {
+      socket = error[symbols.kErrorSocket];
+    }
+    if (socket) {
+      socket[symbols.kSocketId] = globalId('UndiciSocket');
+      socket[symbols.kSocketConnectErrorTime] = new Date();
+      socket[symbols.kHandledRequests] = 0;
+      socket[symbols.kHandledResponses] = 0;
+      // copy local address to symbol, avoid them be reset after request error throw
+      if (socket.localAddress) {
+        socket[symbols.kSocketLocalAddress] = socket.localAddress;
+        socket[symbols.kSocketLocalPort] = socket.localPort;
+      }
+      socket[symbols.kSocketConnectProtocol] = connectParams.protocol;
+      socket[symbols.kSocketConnectHost] = connectParams.host;
+      socket[symbols.kSocketConnectPort] = connectParams.port;
+      debug('[%s] Socket#%d connectError, connectParams: %o, error: %s, (sock: %o)',
+        name, socket[symbols.kSocketId], connectParams, (error as Error).message, formatSocket(socket));
+    } else {
+      debug('[%s] connectError, connectParams: %o, error: %o',
+        name, connectParams, error);
+    }
+  });
+
   // This message is published after a connection is established.
   subscribe('undici:client:connected', (message, name) => {
-    const { socket } = message as DiagnosticsChannel.ClientConnectedMessage;
+    const { socket, connectParams } = message as DiagnosticsChannel.ClientConnectedMessage;
     socket[symbols.kSocketId] = globalId('UndiciSocket');
     socket[symbols.kSocketStartTime] = performance.now();
     socket[symbols.kSocketConnectedTime] = new Date();
@@ -79,6 +122,9 @@ export function initDiagnosticsChannel() {
     // copy local address to symbol, avoid them be reset after request error throw
     socket[symbols.kSocketLocalAddress] = socket.localAddress;
     socket[symbols.kSocketLocalPort] = socket.localPort;
+    socket[symbols.kSocketConnectProtocol] = connectParams.protocol;
+    socket[symbols.kSocketConnectHost] = connectParams.host;
+    socket[symbols.kSocketConnectPort] = connectParams.port;
     debug('[%s] Socket#%d connected (sock: %o)', name, socket[symbols.kSocketId], formatSocket(socket));
   });
 

src/index.ts

@@ -53,6 +53,7 @@ export {
 export {
   IncomingHttpHeaders,
 } from './IncomingHttpHeaders.js';
+export * from './HttpClientError.js';
 
 export default {
   request,

src/symbols.ts

@@ -2,9 +2,13 @@ export default {
   kSocketId: Symbol('socket id'),
   kSocketStartTime: Symbol('socket start time'),
   kSocketConnectedTime: Symbol('socket connected time'),
+  kSocketConnectErrorTime: Symbol('socket connectError time'),
   kSocketRequestEndTime: Symbol('socket request end time'),
   kSocketLocalAddress: Symbol('socket local address'),
   kSocketLocalPort: Symbol('socket local port'),
+  kSocketConnectHost: Symbol('socket connect params: host'),
+  kSocketConnectPort: Symbol('socket connect params: port'),
+  kSocketConnectProtocol: Symbol('socket connect params: protocol'),
   kHandledRequests: Symbol('handled requests per socket'),
   kHandledResponses: Symbol('handled responses per socket'),
   kRequestSocket: Symbol('request on the socket'),
@@ -13,4 +17,5 @@ export default {
   kEnableRequestTiming: Symbol('enable request timing or not'),
   kRequestTiming: Symbol('request timing'),
   kRequestOriginalOpaque: Symbol('request original opaque'),
+  kErrorSocket: Symbol('socket of error'),
 };

test/fixtures/ts-cjs-es2021/hello.ts

@@ -0,0 +1,14 @@
+import { RequestURL, RequestOptions2, RequestOptions } from 'urllib';
+import { HttpClientResponse } from 'urllib';
+import urllib from 'urllib';
+import * as urllib2 from 'urllib';
+
+async function request(url: RequestURL, options: RequestOptions): Promise<HttpClientResponse> {
+  return await urllib.request(url, options);
+}
+
+async function request2(url: RequestURL, options: RequestOptions2): Promise<HttpClientResponse> {
+  return await urllib2.curl(url, options);
+}
+
+console.log(request, request2);

test/fixtures/ts-cjs-es2021/package.json

@@ -0,0 +1,6 @@
+{
+  "name": "ts-cjs-demo",
+  "scripts": {
+    "build": "tsc && node hello.js"
+  }
+}

test/fixtures/ts-cjs-es2021/tsconfig.json

@@ -0,0 +1,12 @@
+{
+  "compilerOptions": {
+    "strict": true,
+    "target": "ES2021",
+    "module": "CommonJS",
+    "moduleResolution": "Node",
+    "baseUrl": "./",
+    "paths": {
+      "urllib": ["../../.."]
+    }
+  }
+}

test/fixtures/ts-esm/tsconfig.json

@@ -1,7 +1,7 @@
 {
   "compilerOptions": {
     "strict": true,
-    "target": "ES2021",
+    "target": "ES2022",
     "module": "NodeNext",
     "moduleResolution": "NodeNext",
     "baseUrl": "./",

test/fixtures/ts/tsconfig.json

@@ -1,7 +1,7 @@
 {
   "compilerOptions": {
     "strict": true,
-    "target": "ES2021",
+    "target": "ES2022",
     "module": "CommonJS",
     "moduleResolution": "Node",
     "baseUrl": "./",

test/keep-alive-header.test.ts

@@ -22,7 +22,7 @@ describe('keep-alive-header.test.ts', () => {
 
   it('should handle Keep-Alive header and not throw reset error on 1s keepalive agent', async () => {
     let count = 0;
-    const max = process.env.TEST_KEEPALIVE_COUNT ? parseInt(process.env.TEST_KEEPALIVE_COUNT) : 10;
+    const max = process.env.TEST_KEEPALIVE_COUNT ? parseInt(process.env.TEST_KEEPALIVE_COUNT) : 3;
     let otherSideClosed = 0;
     let readECONNRESET = 0;
     while (count < max) {

test/options.streaming.test.ts

@@ -153,7 +153,8 @@ describe('options.streaming.test.ts', () => {
     const bytes1 = await readableToBytes(response1.res);
     assert.equal(bytes1.length, size);
     const use1 = Date.now() - start;
-    console.log('highWaterMark 64KB use %dms', use1);
+    // console.log('highWaterMark 64KB use %dms', use1);
+    assert(use1 > 0);
 
     start = Date.now();
     const response2 = await urllib.request(`${_url}mock-bytes?size=${size}`, {
@@ -165,7 +166,8 @@ describe('options.streaming.test.ts', () => {
     const bytes2 = await readableToBytes(response2.res);
     assert.equal(bytes2.length, size);
     const use2 = Date.now() - start;
-    console.log('highWaterMark 128KB use %dms', use2);
+    // console.log('highWaterMark 128KB use %dms', use2);
     // assert(use2 < use1);
+    assert(use2 > 0);
   });
 });