Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Feb 19, 2024
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions .changeset/lazy-elephants-hope.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
---
"@smithy/node-http-handler": minor
"@smithy/types": minor
---

add socket exhaustion checked warning to node-http-handler
33 changes: 33 additions & 0 deletions packages/node-http-handler/src/node-http-handler.spec.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
kuhe marked this conversation as resolved.
Show resolved Hide resolved
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"
);
});
});
});
63 changes: 62 additions & 1 deletion packages/node-http-handler/src/node-http-handler.ts
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ export { NodeHttpHandlerOptions };
interface ResolvedNodeHttpHandlerConfig {
requestTimeout?: number;
connectionTimeout?: number;
socketAcquisitionWarningTimeout?: number;
syall marked this conversation as resolved.
Show resolved Hide resolved
httpAgent: hAgent;
httpsAgent: hsAgent;
}
Expand All @@ -26,6 +27,8 @@ export const DEFAULT_REQUEST_TIMEOUT = 0;
export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
private config?: ResolvedNodeHttpHandlerConfig;
private configProvider: Promise<ResolvedNodeHttpHandlerConfig>;
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" };
Expand All @@ -45,6 +48,53 @@ 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;
}

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<NodeHttpHandlerOptions | void>) {
this.configProvider = new Promise((resolve, reject) => {
if (typeof options === "function") {
Expand Down Expand Up @@ -81,10 +131,13 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
if (!this.config) {
this.config = await this.configProvider;
}

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(this.socketCheckTimeoutId);
_resolve(arg);
};
const reject = async (arg: unknown) => {
Expand All @@ -106,6 +159,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.
this.socketCheckTimeoutId = setTimeout(() => {
kuhe marked this conversation as resolved.
Show resolved Hide resolved
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) {
Expand All @@ -126,7 +187,7 @@ export class NodeHttpHandler implements HttpHandler<NodeHttpHandlerOptions> {
method: request.method,
path,
port: request.port,
agent: isSSL ? this.config.httpsAgent : this.config.httpAgent,
agent,
auth,
};

Expand Down
9 changes: 9 additions & 0 deletions packages/types/src/http/httpHandlerInitialization.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Comment on lines +37 to +44
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same comment as before, can we mark this with @internal?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alternatives are to not let this timeout be configurable, or have a different opt-in to the warning.

Since users are dealing with a mysterious process exit, having the log output without opt-in I think would be better for their debugging experience.


/**
* @deprecated Use {@link requestTimeout}
*
Expand Down
Loading