feat: add checked socket exhaustion warning when throughput is slow (#1164)

* feat: add checked socket exhaustion warning when throughput is slow

* test: update socket check and unit test

* feat: use promise-local timeout id

* feat: add reference to socketAcquisitionWarningTimeout in warning msg

Author: kuhe

.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

packages/node-http-handler/src/node-http-handler.spec.ts

@@ -704,4 +704,46 @@ 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: [],
+            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: 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
+      );
+
+      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",
+        "or increase socketAcquisitionWarningTimeout=(millis) in the NodeHttpHandler config."
+      );
+    });
+  });
 });

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,7 @@ export const DEFAULT_REQUEST_TIMEOUT = 0;
 export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
   private config?: ResolvedNodeHttpHandlerConfig;
   private configProvider: Promise<ResolvedNodeHttpHandlerConfig>;
+  private socketWarningTimestamp = 0;
 
   // 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 +47,55 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
     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;
+    }
+
+    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",
+            "or increase socketAcquisitionWarningTimeout=(millis) in the NodeHttpHandler config."
+          );
+          return Date.now();
+        }
+      }
+    }
+
+    return socketWarningTimestamp;
+  }
+
   constructor(options?: NodeHttpHandlerOptions | Provider<NodeHttpHandlerOptions | void>) {
     this.configProvider = new Promise((resolve, reject) => {
       if (typeof options === "function") {
@@ -81,10 +132,15 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
     if (!this.config) {
       this.config = await this.configProvider;
     }
+
+    let socketCheckTimeoutId: NodeJS.Timeout;
+
     return new Promise((_resolve, _reject) => {
       let writeRequestBodyPromise: Promise<void> | undefined = undefined;
       const resolve = async (arg: { response: HttpResponse }) => {
         await writeRequestBodyPromise;
+        // if requests are still resolving, cancel the socket usage check.
+        clearTimeout(socketCheckTimeoutId);
         _resolve(arg);
       };
       const reject = async (arg: unknown) => {
@@ -106,6 +162,14 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
 
       // 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.
+      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 +190,7 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
         method: request.method,
         path,
         port: request.port,
-        agent: isSSL ? this.config.httpsAgent : this.config.httpAgent,
+        agent,
         auth,
       };
 

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}
    *