From 366de1df2ecdef71bcc927000f346d0cd08fe4cb Mon Sep 17 00:00:00 2001 From: fengmk2 Date: Mon, 4 Dec 2023 20:27:37 +0800 Subject: [PATCH] feat: print more socket info on UND_ERR_CONNECT_TIMEOUT error (#477) --- .gitignore | 1 + examples/httpclient.cjs | 4 +- package.json | 3 +- src/HttpAgent.ts | 2 +- src/HttpClient.ts | 59 ++++++++++++++--------- src/HttpClientError.ts | 34 +++++++++++++ src/Response.ts | 5 ++ src/diagnosticsChannel.ts | 50 ++++++++++++++++++- src/index.ts | 1 + src/symbols.ts | 5 ++ test/fixtures/ts-cjs-es2021/hello.ts | 14 ++++++ test/fixtures/ts-cjs-es2021/package.json | 6 +++ test/fixtures/ts-cjs-es2021/tsconfig.json | 12 +++++ test/fixtures/ts-esm/tsconfig.json | 2 +- test/fixtures/ts/tsconfig.json | 2 +- test/keep-alive-header.test.ts | 2 +- test/options.streaming.test.ts | 6 ++- test/options.timeout.test.ts | 14 +++--- tsconfig.json | 2 +- vite.config.ts | 5 ++ 20 files changed, 187 insertions(+), 42 deletions(-) create mode 100644 src/HttpClientError.ts create mode 100644 test/fixtures/ts-cjs-es2021/hello.ts create mode 100644 test/fixtures/ts-cjs-es2021/package.json create mode 100644 test/fixtures/ts-cjs-es2021/tsconfig.json diff --git a/.gitignore b/.gitignore index c4c651a1..872636c1 100644 --- a/.gitignore +++ b/.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* diff --git a/examples/httpclient.cjs b/examples/httpclient.cjs index f2313fb3..f3c6c704 100644 --- a/examples/httpclient.cjs +++ b/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); }); } diff --git a/package.json b/package.json index 59de4d23..2f90fde9 100644 --- a/package.json +++ b/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", diff --git a/src/HttpAgent.ts b/src/HttpAgent.ts index e24fa912..0fff0886 100644 --- a/src/HttpAgent.ts +++ b/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); } diff --git a/src/HttpClient.ts b/src/HttpClient.ts index 58264f75..5e9a3bdd 100644 --- a/src/HttpClient.ts +++ b/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 extends undefined ? never : T; type UndiciRequestOption = Exists[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(); } } diff --git a/src/HttpClientError.ts b/src/HttpClientError.ts new file mode 100644 index 00000000..3a15e3bf --- /dev/null +++ b/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); + } +} diff --git a/src/Response.ts b/src/Response.ts index a59e16b4..c588af1b 100644 --- a/src/Response.ts +++ b/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; }; /** diff --git a/src/diagnosticsChannel.ts b/src/diagnosticsChannel.ts index dea9e80c..e9731d19 100644 --- a/src/diagnosticsChannel.ts +++ b/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)); }); diff --git a/src/index.ts b/src/index.ts index 7842b8be..3f6832ee 100644 --- a/src/index.ts +++ b/src/index.ts @@ -53,6 +53,7 @@ export { export { IncomingHttpHeaders, } from './IncomingHttpHeaders.js'; +export * from './HttpClientError.js'; export default { request, diff --git a/src/symbols.ts b/src/symbols.ts index a474faa0..406a6636 100644 --- a/src/symbols.ts +++ b/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'), }; diff --git a/test/fixtures/ts-cjs-es2021/hello.ts b/test/fixtures/ts-cjs-es2021/hello.ts new file mode 100644 index 00000000..1090ef1a --- /dev/null +++ b/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 { + return await urllib.request(url, options); +} + +async function request2(url: RequestURL, options: RequestOptions2): Promise { + return await urllib2.curl(url, options); +} + +console.log(request, request2); diff --git a/test/fixtures/ts-cjs-es2021/package.json b/test/fixtures/ts-cjs-es2021/package.json new file mode 100644 index 00000000..23607c7a --- /dev/null +++ b/test/fixtures/ts-cjs-es2021/package.json @@ -0,0 +1,6 @@ +{ + "name": "ts-cjs-demo", + "scripts": { + "build": "tsc && node hello.js" + } +} diff --git a/test/fixtures/ts-cjs-es2021/tsconfig.json b/test/fixtures/ts-cjs-es2021/tsconfig.json new file mode 100644 index 00000000..2f2baadd --- /dev/null +++ b/test/fixtures/ts-cjs-es2021/tsconfig.json @@ -0,0 +1,12 @@ +{ + "compilerOptions": { + "strict": true, + "target": "ES2021", + "module": "CommonJS", + "moduleResolution": "Node", + "baseUrl": "./", + "paths": { + "urllib": ["../../.."] + } + } +} diff --git a/test/fixtures/ts-esm/tsconfig.json b/test/fixtures/ts-esm/tsconfig.json index 5a83e59b..c7a99cb1 100644 --- a/test/fixtures/ts-esm/tsconfig.json +++ b/test/fixtures/ts-esm/tsconfig.json @@ -1,7 +1,7 @@ { "compilerOptions": { "strict": true, - "target": "ES2021", + "target": "ES2022", "module": "NodeNext", "moduleResolution": "NodeNext", "baseUrl": "./", diff --git a/test/fixtures/ts/tsconfig.json b/test/fixtures/ts/tsconfig.json index 2f2baadd..5d8c56c9 100644 --- a/test/fixtures/ts/tsconfig.json +++ b/test/fixtures/ts/tsconfig.json @@ -1,7 +1,7 @@ { "compilerOptions": { "strict": true, - "target": "ES2021", + "target": "ES2022", "module": "CommonJS", "moduleResolution": "Node", "baseUrl": "./", diff --git a/test/keep-alive-header.test.ts b/test/keep-alive-header.test.ts index 78129173..3e45b4de 100644 --- a/test/keep-alive-header.test.ts +++ b/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) { diff --git a/test/options.streaming.test.ts b/test/options.streaming.test.ts index cd5d5eaf..a98f998a 100644 --- a/test/options.streaming.test.ts +++ b/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); }); }); diff --git a/test/options.timeout.test.ts b/test/options.timeout.test.ts index 5ca54000..64bf5a59 100644 --- a/test/options.timeout.test.ts +++ b/test/options.timeout.test.ts @@ -1,6 +1,6 @@ import { strict as assert } from 'node:assert'; import { describe, it, beforeAll, afterAll } from 'vitest'; -import urllib from '../src'; +import urllib, { HttpClientRequestTimeoutError } from '../src'; import { startServer } from './fixtures/server'; describe('options.timeout.test.ts', () => { @@ -58,16 +58,16 @@ describe('options.timeout.test.ts', () => { }); }); - it('should timeout 50ms throw error', async () => { + it('should timeout 500ms throw error', async () => { await assert.rejects(async () => { const response = await urllib.request(`${_url}mock-bytes?timeout=1000`, { - timeout: [ 10, 50 ], + timeout: [ 100, 500 ], }); console.log(response.status, response.headers, response.data); }, (err: any) => { // console.log(err); assert.equal(err.name, 'HttpClientRequestTimeoutError'); - assert.equal(err.message, 'Request timeout for 50 ms'); + assert.equal(err.message, 'Request timeout for 500 ms'); assert.equal(err.res.status, 200); err.cause && assert.equal(err.cause.name, 'BodyTimeoutError'); return true; @@ -79,11 +79,13 @@ describe('options.timeout.test.ts', () => { await urllib.request(`${_url}block`, { timeout: 100, }); - }, (err: any) => { + }, (err: HttpClientRequestTimeoutError) => { // console.log(err); assert.equal(err.name, 'HttpClientRequestTimeoutError'); assert.equal(err.message, 'Request timeout for 100 ms'); - assert.equal(err.res.status, -1); + assert.equal(err.res!.status, -1); + assert(err.headers); + assert.equal(err.status, -1); err.cause && assert.equal(err.cause.name, 'HeadersTimeoutError'); return true; }); diff --git a/tsconfig.json b/tsconfig.json index 51c9027f..241f0504 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -21,7 +21,7 @@ "esModuleInterop": true, "stripInternal": true, "lib": [ - "ESNext" + "ES2022" ], "composite": true, "types": [ diff --git a/vite.config.ts b/vite.config.ts index 4f9437eb..a1ec9e1b 100644 --- a/vite.config.ts +++ b/vite.config.ts @@ -12,5 +12,10 @@ export default defineConfig({ ], }, pool: 'forks', + poolOptions: { + forks: { + isolate: false, + }, + }, }, });