From b340be49cedd2c7a0f85121471e34d8683a60c0c Mon Sep 17 00:00:00 2001 From: Konstantin Wohlwend Date: Sun, 2 Mar 2025 16:38:47 -0800 Subject: [PATCH] Log concurrent requests per process in OpenTelemetry --- .../route-handlers/smart-route-handler.tsx | 159 +++++++++--------- 1 file changed, 83 insertions(+), 76 deletions(-) diff --git a/apps/backend/src/route-handlers/smart-route-handler.tsx b/apps/backend/src/route-handlers/smart-route-handler.tsx index 33f10ed41..fc188c9da 100644 --- a/apps/backend/src/route-handlers/smart-route-handler.tsx +++ b/apps/backend/src/route-handlers/smart-route-handler.tsx @@ -57,6 +57,7 @@ function catchError(error: unknown, requestId: string): StatusError { * multiple concurrent requests to be handled by the same instance. */ const processId = generateSecureRandomString(80); +let concurrentRequestsInProcess = 0; /** * Catches any errors thrown in the handler and returns a 500 response with the thrown error message. Also logs the @@ -64,87 +65,93 @@ const processId = generateSecureRandomString(80); */ export function handleApiRequest(handler: (req: NextRequest, options: any, requestId: string) => Promise): (req: NextRequest, options: any) => Promise { return async (req: NextRequest, options: any) => { - const requestId = generateSecureRandomString(80); - return await traceSpan({ - description: 'handling API request', - attributes: { - "stack.request.request-id": requestId, - "stack.request.method": req.method, - "stack.request.url": req.url, - "stack.process-id": processId, - }, - }, async (span) => { - // Set Sentry scope to include request details - Sentry.setContext("stack-request", { - requestId: requestId, - method: req.method, - url: req.url, - query: Object.fromEntries(req.nextUrl.searchParams), - headers: Object.fromEntries(req.headers), - }); - - // During development, don't trash the console with logs from E2E tests - const disableExtendedLogging = getNodeEnvironment().includes('dev') && !!req.headers.get("x-stack-development-disable-extended-logging"); - - let hasRequestFinished = false; - try { - // censor long query parameters because they might contain sensitive data - const censoredUrl = new URL(req.url); - for (const [key, value] of censoredUrl.searchParams.entries()) { - if (value.length <= 8) { - continue; - } - censoredUrl.searchParams.set(key, value.slice(0, 4) + "--REDACTED--" + value.slice(-4)); - } - - // request duration warning - const warnAfterSeconds = 12; - runAsynchronously(async () => { - await wait(warnAfterSeconds * 1000); - if (!hasRequestFinished) { - captureError("request-timeout-watcher", new Error(`Request with ID ${requestId} to endpoint ${req.nextUrl.pathname} has been running for ${warnAfterSeconds} seconds. Try to keep requests short. The request may be cancelled by the serverless provider if it takes too long.`)); - } + concurrentRequestsInProcess++; + try { + const requestId = generateSecureRandomString(80); + return await traceSpan({ + description: 'handling API request', + attributes: { + "stack.request.request-id": requestId, + "stack.request.method": req.method, + "stack.request.url": req.url, + "stack.process.id": processId, + "stack.process.concurrent-requests": concurrentRequestsInProcess, + }, + }, async (span) => { + // Set Sentry scope to include request details + Sentry.setContext("stack-request", { + requestId: requestId, + method: req.method, + url: req.url, + query: Object.fromEntries(req.nextUrl.searchParams), + headers: Object.fromEntries(req.headers), }); - if (!disableExtendedLogging) console.log(`[API REQ] [${requestId}] ${req.method} ${censoredUrl}`); - const timeStart = performance.now(); - const res = await handler(req, options, requestId); - const time = (performance.now() - timeStart); - if ([301, 302].includes(res.status)) { - throw new StackAssertionError("HTTP status codes 301 and 302 should not be returned by our APIs because the behavior for non-GET methods is inconsistent across implementations. Use 303 (to rewrite method to GET) or 307/308 (to preserve the original method and data) instead.", { status: res.status, url: req.nextUrl, req, res }); - } - if (!disableExtendedLogging) console.log(`[ RES] [${requestId}] ${req.method} ${censoredUrl}: ${res.status} (in ${time.toFixed(0)}ms)`); - return res; - } catch (e) { - let statusError: StatusError; + // During development, don't trash the console with logs from E2E tests + const disableExtendedLogging = getNodeEnvironment().includes('dev') && !!req.headers.get("x-stack-development-disable-extended-logging"); + + let hasRequestFinished = false; try { - statusError = catchError(e, requestId); + // censor long query parameters because they might contain sensitive data + const censoredUrl = new URL(req.url); + for (const [key, value] of censoredUrl.searchParams.entries()) { + if (value.length <= 8) { + continue; + } + censoredUrl.searchParams.set(key, value.slice(0, 4) + "--REDACTED--" + value.slice(-4)); + } + + // request duration warning + const warnAfterSeconds = 12; + runAsynchronously(async () => { + await wait(warnAfterSeconds * 1000); + if (!hasRequestFinished) { + captureError("request-timeout-watcher", new Error(`Request with ID ${requestId} to endpoint ${req.nextUrl.pathname} has been running for ${warnAfterSeconds} seconds. Try to keep requests short. The request may be cancelled by the serverless provider if it takes too long.`)); + } + }); + + if (!disableExtendedLogging) console.log(`[API REQ] [${requestId}] ${req.method} ${censoredUrl}`); + const timeStart = performance.now(); + const res = await handler(req, options, requestId); + const time = (performance.now() - timeStart); + if ([301, 302].includes(res.status)) { + throw new StackAssertionError("HTTP status codes 301 and 302 should not be returned by our APIs because the behavior for non-GET methods is inconsistent across implementations. Use 303 (to rewrite method to GET) or 307/308 (to preserve the original method and data) instead.", { status: res.status, url: req.nextUrl, req, res }); + } + if (!disableExtendedLogging) console.log(`[ RES] [${requestId}] ${req.method} ${censoredUrl}: ${res.status} (in ${time.toFixed(0)}ms)`); + return res; } catch (e) { - if (!disableExtendedLogging) console.log(`[ EXC] [${requestId}] ${req.method} ${req.url}: Non-error caught (such as a redirect), will be re-thrown. Digest: ${(e as any)?.digest}`); - throw e; + let statusError: StatusError; + try { + statusError = catchError(e, requestId); + } catch (e) { + if (!disableExtendedLogging) console.log(`[ EXC] [${requestId}] ${req.method} ${req.url}: Non-error caught (such as a redirect), will be re-thrown. Digest: ${(e as any)?.digest}`); + throw e; + } + + if (!disableExtendedLogging) console.log(`[ ERR] [${requestId}] ${req.method} ${req.url}: ${statusError.message}`); + + if (!commonErrors.some(e => statusError instanceof e)) { + // HACK: Log a nicified version of the error instead of statusError to get around buggy Next.js pretty-printing + // https://www.reddit.com/r/nextjs/comments/1gkxdqe/comment/m19kxgn/?utm_source=share&utm_medium=web3x&utm_name=web3xcss&utm_term=1&utm_content=share_button + if (!disableExtendedLogging) console.debug(`For the error above with request ID ${requestId}, the full error is:`, errorToNiceString(statusError)); + } + + const res = await createResponse(req, requestId, { + statusCode: statusError.statusCode, + bodyType: "binary", + body: statusError.getBody(), + headers: { + ...statusError.getHeaders(), + }, + }); + return res; + } finally { + hasRequestFinished = true; } - - if (!disableExtendedLogging) console.log(`[ ERR] [${requestId}] ${req.method} ${req.url}: ${statusError.message}`); - - if (!commonErrors.some(e => statusError instanceof e)) { - // HACK: Log a nicified version of the error instead of statusError to get around buggy Next.js pretty-printing - // https://www.reddit.com/r/nextjs/comments/1gkxdqe/comment/m19kxgn/?utm_source=share&utm_medium=web3x&utm_name=web3xcss&utm_term=1&utm_content=share_button - if (!disableExtendedLogging) console.debug(`For the error above with request ID ${requestId}, the full error is:`, errorToNiceString(statusError)); - } - - const res = await createResponse(req, requestId, { - statusCode: statusError.statusCode, - bodyType: "binary", - body: statusError.getBody(), - headers: { - ...statusError.getHeaders(), - }, - }); - return res; - } finally { - hasRequestFinished = true; - } - }); + }); + } finally { + concurrentRequestsInProcess--; + } }; };