From 8ce85870113815f9b58fe3200a06888b145ee41e Mon Sep 17 00:00:00 2001 From: Xin Zhang Date: Thu, 30 Jan 2025 15:07:15 -0500 Subject: [PATCH 1/4] Classify more long response to timeout instead of 499 --- .../services-utils/src/morganLoggerMiddleware.ts | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts index 98f064b63b73..7c5f372c8d2b 100644 --- a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts +++ b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts @@ -119,6 +119,7 @@ export function jsonMorganLoggerMiddleware( }); }) : undefined; + // HTTP Metric durationInMs should only track internal server time, so manually set it before waiting for response close. const startTime = performance.now(); const httpMetric = Lumberjack.newLumberMetric(LumberEventName.HttpRequest); morgan((tokens, req, res) => { @@ -126,9 +127,13 @@ export function jsonMorganLoggerMiddleware( if (computeAdditionalProperties) { additionalProperties = computeAdditionalProperties(tokens, req, res); } + const durationInMs = performance.now() - startTime; let statusCode = tokens.status(req, res); if (!statusCode) { - if (res.locals.serverTimeout) { + // The effort of trying to distinguish client close vs server close can be tricky when it reaches proxy timeout. + // If proxy timeout happen a little before server timeout, it is actually more due to a server timeout issue. + // Therefore, we can assume it is server timeout if duration is longer than 20s without a valid status code + if (res.locals.serverTimeout || durationInMs > 20000) { statusCode = "Server Timeout"; } else if (res.locals.clientDisconnected) { statusCode = "499"; @@ -171,9 +176,7 @@ export function jsonMorganLoggerMiddleware( // Morgan middleware logs using the [on-finished](https://www.npmjs.com/package/on-finished) package, meaning that it will log // request duration immediately on response 'finish' event. However, the gap between 'finish' and 'close' can be helpful for // understanding response latency. - const endTime = performance.now(); - // HTTP Metric durationInMs should only track internal server time, so manually set it before waiting for response close. - httpMetric.setProperty("durationInMs", endTime - startTime); + httpMetric.setProperty("durationInMs", durationInMs); // Wait for response 'close' event to signal that the response is completed. responseLatencyP ?.then((responseLatency) => { From 31971c8f863c60ea93d048519202524a498cabd8 Mon Sep 17 00:00:00 2001 From: Xin Zhang Date: Thu, 30 Jan 2025 17:23:51 -0500 Subject: [PATCH 2/4] Make the classifed status more detail. --- .../packages/services-utils/src/morganLoggerMiddleware.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts index 7c5f372c8d2b..856741e6caeb 100644 --- a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts +++ b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts @@ -132,11 +132,12 @@ export function jsonMorganLoggerMiddleware( if (!statusCode) { // The effort of trying to distinguish client close vs server close can be tricky when it reaches proxy timeout. // If proxy timeout happen a little before server timeout, it is actually more due to a server timeout issue. - // Therefore, we can assume it is server timeout if duration is longer than 20s without a valid status code - if (res.locals.serverTimeout || durationInMs > 20000) { + // Therefore, we can assume it is server timeout (triggered by client) if duration is longer than 20s without + // a valid status code + if (res.locals.serverTimeout) { statusCode = "Server Timeout"; } else if (res.locals.clientDisconnected) { - statusCode = "499"; + statusCode = durationInMs > 20_000 ? "Client Timeout" : "499"; } else { statusCode = "STATUS_UNAVAILABLE"; } From afc8fdc02191db489eb9dc36ba6f24c875b3de4a Mon Sep 17 00:00:00 2001 From: Xin Zhang Date: Mon, 3 Feb 2025 13:02:57 -0500 Subject: [PATCH 3/4] Classify the error message --- .../packages/services-utils/src/morganLoggerMiddleware.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts index 856741e6caeb..8aac4f3cf9b2 100644 --- a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts +++ b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts @@ -137,7 +137,7 @@ export function jsonMorganLoggerMiddleware( if (res.locals.serverTimeout) { statusCode = "Server Timeout"; } else if (res.locals.clientDisconnected) { - statusCode = durationInMs > 20_000 ? "Client Timeout" : "499"; + statusCode = durationInMs > 20_000 ? "Server Timeout - Client Disconnect" : "499"; } else { statusCode = "STATUS_UNAVAILABLE"; } From 98441eb8cb3caf1717b31d77c0d33042470d3d54 Mon Sep 17 00:00:00 2001 From: Xin Zhang Date: Mon, 3 Feb 2025 13:05:58 -0500 Subject: [PATCH 4/4] Run lint --- .../packages/services-utils/src/morganLoggerMiddleware.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts index 8aac4f3cf9b2..873fbbe16625 100644 --- a/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts +++ b/server/routerlicious/packages/services-utils/src/morganLoggerMiddleware.ts @@ -137,7 +137,8 @@ export function jsonMorganLoggerMiddleware( if (res.locals.serverTimeout) { statusCode = "Server Timeout"; } else if (res.locals.clientDisconnected) { - statusCode = durationInMs > 20_000 ? "Server Timeout - Client Disconnect" : "499"; + statusCode = + durationInMs > 20_000 ? "Server Timeout - Client Disconnect" : "499"; } else { statusCode = "STATUS_UNAVAILABLE"; }