From 6810dba622eeab83af06517317bb73753efef671 Mon Sep 17 00:00:00 2001 From: George Fu Date: Thu, 15 Feb 2024 19:27:41 +0000 Subject: [PATCH 1/4] feat: add checked socket exhaustion warning when throughput is slow --- .changeset/lazy-elephants-hope.md | 6 ++ .../src/node-http-handler.spec.ts | 33 ++++++++++ .../src/node-http-handler.ts | 63 ++++++++++++++++++- .../src/http/httpHandlerInitialization.ts | 9 +++ 4 files changed, 110 insertions(+), 1 deletion(-) create mode 100644 .changeset/lazy-elephants-hope.md diff --git a/.changeset/lazy-elephants-hope.md b/.changeset/lazy-elephants-hope.md new file mode 100644 index 00000000000..e69e76763bf --- /dev/null +++ b/.changeset/lazy-elephants-hope.md @@ -0,0 +1,6 @@ +--- +"@smithy/node-http-handler": minor +"@smithy/types": minor +--- + +add socket exhaustion checked warning to node-http-handler diff --git a/packages/node-http-handler/src/node-http-handler.spec.ts b/packages/node-http-handler/src/node-http-handler.spec.ts index 66e7f7a5a62..7d75d1deb47 100644 --- a/packages/node-http-handler/src/node-http-handler.spec.ts +++ b/packages/node-http-handler/src/node-http-handler.spec.ts @@ -704,4 +704,37 @@ describe("NodeHttpHandler", () => { expect(nodeHttpHandler.httpHandlerConfigs()).toEqual({}); }); }); + + describe("checkSocketUsage", () => { + beforeEach(() => { + jest.spyOn(console, "warn").mockImplementation(jest.fn()); + }); + + afterEach(() => { + jest.resetAllMocks(); + }); + + it("warns when socket exhaustion is detected", async () => { + const lastTimestamp = Date.now() - 30_000; + const warningTimestamp = NodeHttpHandler.checkSocketUsage( + { + maxSockets: 2, + sockets: { + addr: [null, null], + }, + requests: { + addr: [null, null, null, null], + }, + } as any, + lastTimestamp + ); + + expect(warningTimestamp).toBeGreaterThan(lastTimestamp); + expect(console.warn).toHaveBeenCalledWith( + "@smithy/node-http-handler:WARN", + "socket usage at capacity=2 and 4 additional requests are enqueued.", + "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" + ); + }); + }); }); diff --git a/packages/node-http-handler/src/node-http-handler.ts b/packages/node-http-handler/src/node-http-handler.ts index ed3f7ee2ed3..bd1e258f2a6 100644 --- a/packages/node-http-handler/src/node-http-handler.ts +++ b/packages/node-http-handler/src/node-http-handler.ts @@ -17,6 +17,7 @@ export { NodeHttpHandlerOptions }; interface ResolvedNodeHttpHandlerConfig { requestTimeout?: number; connectionTimeout?: number; + socketAcquisitionWarningTimeout?: number; httpAgent: hAgent; httpsAgent: hsAgent; } @@ -26,6 +27,8 @@ export const DEFAULT_REQUEST_TIMEOUT = 0; export class NodeHttpHandler implements HttpHandler { private config?: ResolvedNodeHttpHandlerConfig; private configProvider: Promise; + private socketWarningTimestamp = 0; + private socketCheckTimeoutId = (null as unknown) as NodeJS.Timeout; // Node http handler is hard-coded to http/1.1: https://github.com/nodejs/node/blob/ff5664b83b89c55e4ab5d5f60068fb457f1f5872/lib/_http_server.js#L286 public readonly metadata = { handlerProtocol: "http/1.1" }; @@ -45,6 +48,53 @@ export class NodeHttpHandler implements HttpHandler { return new NodeHttpHandler(instanceOrOptions as NodeHttpHandlerOptions); } + /** + * @internal + * + * @param agent - http(s) agent in use by the NodeHttpHandler instance. + * @returns timestamp of last emitted warning. + */ + public static checkSocketUsage(agent: hAgent | hsAgent, socketWarningTimestamp: number): number { + // note, maxSockets is per origin. + const { sockets, requests, maxSockets } = agent; + + if (typeof maxSockets !== "number" || maxSockets === Infinity) { + return socketWarningTimestamp; + } + + const interval = 15_000; + if (Date.now() - interval < socketWarningTimestamp) { + return socketWarningTimestamp; + } + + let socketsInUse = 0; + let requestsEnqueued = 0; + + if (sockets) { + for (const key in sockets) { + socketsInUse = Math.max(socketsInUse, sockets[key]?.length ?? 0); + } + } + + if (requests) { + for (const key in requests) { + requestsEnqueued = Math.max(requestsEnqueued, requests[key]?.length ?? 0); + } + } + + // This threshold is somewhat arbitrary. + // A few enqueued requests is not worth warning about. + if (socketsInUse >= maxSockets && requestsEnqueued >= 2 * maxSockets) { + console.warn( + "@smithy/node-http-handler:WARN", + `socket usage at capacity=${socketsInUse} and ${requestsEnqueued} additional requests are enqueued.`, + "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" + ); + return Date.now(); + } + return socketWarningTimestamp; + } + constructor(options?: NodeHttpHandlerOptions | Provider) { this.configProvider = new Promise((resolve, reject) => { if (typeof options === "function") { @@ -81,10 +131,13 @@ export class NodeHttpHandler implements HttpHandler { if (!this.config) { this.config = await this.configProvider; } + return new Promise((_resolve, _reject) => { let writeRequestBodyPromise: Promise | undefined = undefined; const resolve = async (arg: { response: HttpResponse }) => { await writeRequestBodyPromise; + // if requests are still resolving, cancel the socket usage check. + clearTimeout(this.socketCheckTimeoutId); _resolve(arg); }; const reject = async (arg: unknown) => { @@ -106,6 +159,14 @@ export class NodeHttpHandler implements HttpHandler { // determine which http(s) client to use const isSSL = request.protocol === "https:"; + const agent = isSSL ? this.config.httpsAgent : this.config.httpAgent; + + // If the request is taking a long time, check socket usage and potentially warn. + // This warning will be cancelled if the request resolves. + this.socketCheckTimeoutId = setTimeout(() => { + this.socketWarningTimestamp = NodeHttpHandler.checkSocketUsage(agent, this.socketWarningTimestamp); + }, this.config.socketAcquisitionWarningTimeout ?? (this.config.requestTimeout ?? 2000) + (this.config.connectionTimeout ?? 1000)); + const queryString = buildQueryString(request.query || {}); let auth = undefined; if (request.username != null || request.password != null) { @@ -126,7 +187,7 @@ export class NodeHttpHandler implements HttpHandler { method: request.method, path, port: request.port, - agent: isSSL ? this.config.httpsAgent : this.config.httpAgent, + agent, auth, }; diff --git a/packages/types/src/http/httpHandlerInitialization.ts b/packages/types/src/http/httpHandlerInitialization.ts index b9b3d1daf38..9671d548523 100644 --- a/packages/types/src/http/httpHandlerInitialization.ts +++ b/packages/types/src/http/httpHandlerInitialization.ts @@ -34,6 +34,15 @@ export interface NodeHttpHandlerOptions { */ requestTimeout?: number; + /** + * Delay before the NodeHttpHandler checks for socket exhaustion, + * and emits a warning if the active sockets and enqueued request count is greater than + * 2x the maxSockets count. + * + * Defaults to connectionTimeout + requestTimeout or 3000ms if those are not set. + */ + socketAcquisitionWarningTimeout?: number; + /** * @deprecated Use {@link requestTimeout} * From bbfb0486f77eff984c158ab3cea46461a0df213c Mon Sep 17 00:00:00 2001 From: George Fu Date: Fri, 16 Feb 2024 18:20:36 +0000 Subject: [PATCH 2/4] test: update socket check and unit test --- .../src/node-http-handler.spec.ts | 12 ++++- .../src/node-http-handler.ts | 45 ++++++++++--------- 2 files changed, 33 insertions(+), 24 deletions(-) diff --git a/packages/node-http-handler/src/node-http-handler.spec.ts b/packages/node-http-handler/src/node-http-handler.spec.ts index 7d75d1deb47..693a341b254 100644 --- a/packages/node-http-handler/src/node-http-handler.spec.ts +++ b/packages/node-http-handler/src/node-http-handler.spec.ts @@ -720,10 +720,18 @@ describe("NodeHttpHandler", () => { { maxSockets: 2, sockets: { - addr: [null, null], + addr: [], + addr2: [null], + addr3: [null, null], + // this is not checked because an earlier addr causes the warning to be emitted. + addr4: Array.from({ length: 400 }), }, requests: { - addr: [null, null, null, null], + addr: Array.from({ length: 0 }), + addr2: Array.from({ length: 3 }), + addr3: Array.from({ length: 4 }), + // this is not checked because an earlier addr causes the warning to be emitted. + addr4: Array.from({ length: 800 }), }, } as any, lastTimestamp diff --git a/packages/node-http-handler/src/node-http-handler.ts b/packages/node-http-handler/src/node-http-handler.ts index bd1e258f2a6..413358fd9d7 100644 --- a/packages/node-http-handler/src/node-http-handler.ts +++ b/packages/node-http-handler/src/node-http-handler.ts @@ -67,31 +67,32 @@ export class NodeHttpHandler implements HttpHandler { return socketWarningTimestamp; } - let socketsInUse = 0; - let requestsEnqueued = 0; - - if (sockets) { - for (const key in sockets) { - socketsInUse = Math.max(socketsInUse, sockets[key]?.length ?? 0); - } - } - - if (requests) { - for (const key in requests) { - requestsEnqueued = Math.max(requestsEnqueued, requests[key]?.length ?? 0); + if (sockets && requests) { + for (const origin in sockets) { + const socketsInUse = sockets[origin]?.length ?? 0; + const requestsEnqueued = requests[origin]?.length ?? 0; + + /** + * Running at maximum socket usage can be intentional and normal. + * That is why this warning emits at a delay which can be seen + * at the call site's setTimeout wrapper. The warning will be cancelled + * if the request finishes in a reasonable amount of time regardless + * of socket saturation. + * + * Additionally, when the warning is emitted, there is an interval + * lockout. + */ + if (socketsInUse >= maxSockets && requestsEnqueued >= 2 * maxSockets) { + console.warn( + "@smithy/node-http-handler:WARN", + `socket usage at capacity=${socketsInUse} and ${requestsEnqueued} additional requests are enqueued.`, + "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" + ); + return Date.now(); + } } } - // This threshold is somewhat arbitrary. - // A few enqueued requests is not worth warning about. - if (socketsInUse >= maxSockets && requestsEnqueued >= 2 * maxSockets) { - console.warn( - "@smithy/node-http-handler:WARN", - `socket usage at capacity=${socketsInUse} and ${requestsEnqueued} additional requests are enqueued.`, - "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" - ); - return Date.now(); - } return socketWarningTimestamp; } From 2e194566ae06809f0bec6fe16b9a231d8e968ee2 Mon Sep 17 00:00:00 2001 From: George Fu Date: Mon, 19 Feb 2024 16:29:50 +0000 Subject: [PATCH 3/4] feat: use promise-local timeout id --- packages/node-http-handler/src/node-http-handler.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/packages/node-http-handler/src/node-http-handler.ts b/packages/node-http-handler/src/node-http-handler.ts index 413358fd9d7..61df4250f3e 100644 --- a/packages/node-http-handler/src/node-http-handler.ts +++ b/packages/node-http-handler/src/node-http-handler.ts @@ -28,7 +28,6 @@ export class NodeHttpHandler implements HttpHandler { private config?: ResolvedNodeHttpHandlerConfig; private configProvider: Promise; private socketWarningTimestamp = 0; - private socketCheckTimeoutId = (null as unknown) as NodeJS.Timeout; // Node http handler is hard-coded to http/1.1: https://github.com/nodejs/node/blob/ff5664b83b89c55e4ab5d5f60068fb457f1f5872/lib/_http_server.js#L286 public readonly metadata = { handlerProtocol: "http/1.1" }; @@ -133,12 +132,14 @@ export class NodeHttpHandler implements HttpHandler { this.config = await this.configProvider; } + let socketCheckTimeoutId: NodeJS.Timeout; + return new Promise((_resolve, _reject) => { let writeRequestBodyPromise: Promise | undefined = undefined; const resolve = async (arg: { response: HttpResponse }) => { await writeRequestBodyPromise; // if requests are still resolving, cancel the socket usage check. - clearTimeout(this.socketCheckTimeoutId); + clearTimeout(socketCheckTimeoutId); _resolve(arg); }; const reject = async (arg: unknown) => { @@ -164,7 +165,7 @@ export class NodeHttpHandler implements HttpHandler { // If the request is taking a long time, check socket usage and potentially warn. // This warning will be cancelled if the request resolves. - this.socketCheckTimeoutId = setTimeout(() => { + socketCheckTimeoutId = setTimeout(() => { this.socketWarningTimestamp = NodeHttpHandler.checkSocketUsage(agent, this.socketWarningTimestamp); }, this.config.socketAcquisitionWarningTimeout ?? (this.config.requestTimeout ?? 2000) + (this.config.connectionTimeout ?? 1000)); From 6fbe1db85e140df366115193a82ecc841f6f9d04 Mon Sep 17 00:00:00 2001 From: George Fu Date: Mon, 19 Feb 2024 16:44:38 +0000 Subject: [PATCH 4/4] feat: add reference to socketAcquisitionWarningTimeout in warning msg --- packages/node-http-handler/src/node-http-handler.spec.ts | 3 ++- packages/node-http-handler/src/node-http-handler.ts | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/packages/node-http-handler/src/node-http-handler.spec.ts b/packages/node-http-handler/src/node-http-handler.spec.ts index 693a341b254..9fd8a43a4a1 100644 --- a/packages/node-http-handler/src/node-http-handler.spec.ts +++ b/packages/node-http-handler/src/node-http-handler.spec.ts @@ -741,7 +741,8 @@ describe("NodeHttpHandler", () => { expect(console.warn).toHaveBeenCalledWith( "@smithy/node-http-handler:WARN", "socket usage at capacity=2 and 4 additional requests are enqueued.", - "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" + "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html", + "or increase socketAcquisitionWarningTimeout=(millis) in the NodeHttpHandler config." ); }); }); diff --git a/packages/node-http-handler/src/node-http-handler.ts b/packages/node-http-handler/src/node-http-handler.ts index 61df4250f3e..b4d6b7eb9ed 100644 --- a/packages/node-http-handler/src/node-http-handler.ts +++ b/packages/node-http-handler/src/node-http-handler.ts @@ -85,7 +85,8 @@ export class NodeHttpHandler implements HttpHandler { console.warn( "@smithy/node-http-handler:WARN", `socket usage at capacity=${socketsInUse} and ${requestsEnqueued} additional requests are enqueued.`, - "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html" + "See https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-configuring-maxsockets.html", + "or increase socketAcquisitionWarningTimeout=(millis) in the NodeHttpHandler config." ); return Date.now(); }