diff --git a/apps/api/package.json b/apps/api/package.json index 0988c9962..bfaed4071 100644 --- a/apps/api/package.json +++ b/apps/api/package.json @@ -125,6 +125,7 @@ "rate-limiter-flexible": "2.4.2", "redlock": "5.0.0-beta.2", "resend": "^3.4.0", + "response-time": "^2.3.4", "robots-parser": "^3.0.1", "stripe": "^16.1.0", "systeminformation": "^5.27.8", diff --git a/apps/api/pnpm-lock.yaml b/apps/api/pnpm-lock.yaml index 9d29c14f7..33dfa2983 100644 --- a/apps/api/pnpm-lock.yaml +++ b/apps/api/pnpm-lock.yaml @@ -3,7 +3,6 @@ lockfileVersion: '9.0' settings: autoInstallPeers: true excludeLinksFromLockfile: false - injectWorkspacePackages: true overrides: brace-expansion@>=2.0.0 <=2.0.1: 2.0.2 @@ -204,6 +203,9 @@ importers: resend: specifier: ^3.4.0 version: 3.4.0 + response-time: + specifier: ^2.3.4 + version: 2.3.4 robots-parser: specifier: ^3.0.1 version: 3.0.1 @@ -1415,49 +1417,42 @@ packages: engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [glibc] '@napi-rs/lzma-linux-arm64-musl@1.4.5': resolution: {integrity: sha512-yWjcPDgJ2nIL3KNvi4536dlT/CcCWO0DUyEOlBs/SacG7BeD6IjGh6yYzd3/X1Y3JItCbZoDoLUH8iB1lTXo3w==} engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [musl] '@napi-rs/lzma-linux-ppc64-gnu@1.4.5': resolution: {integrity: sha512-0XRhKuIU/9ZjT4WDIG/qnX7Xz7mSQHYZo9Gb3MP2gcvBgr6BA4zywQ9k3gmQaPn9ECE+CZg2V7DV7kT+x2pUMQ==} engines: {node: '>= 10'} cpu: [ppc64] os: [linux] - libc: [glibc] '@napi-rs/lzma-linux-riscv64-gnu@1.4.5': resolution: {integrity: sha512-QrqDIPEUUB23GCpyQj/QFyMlr8SGxxyExeZz9OWFnHfb70kXdTLWrHS/hEI1Ru+lSbQ/6xRqeoGyQ4Aqdg+/RA==} engines: {node: '>= 10'} cpu: [riscv64] os: [linux] - libc: [glibc] '@napi-rs/lzma-linux-s390x-gnu@1.4.5': resolution: {integrity: sha512-k8RVM5aMhW86E9H0QXdquwojew4H3SwPxbRVbl49/COJQWCUjGi79X6mYruMnMPEznZinUiT1jgKbFo2A00NdA==} engines: {node: '>= 10'} cpu: [s390x] os: [linux] - libc: [glibc] '@napi-rs/lzma-linux-x64-gnu@1.4.5': resolution: {integrity: sha512-6rMtBgnIq2Wcl1rQdZsnM+rtCcVCbws1nF8S2NzaUsVaZv8bjrPiAa0lwg4Eqnn1d9lgwqT+cZgm5m+//K08Kw==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [glibc] '@napi-rs/lzma-linux-x64-musl@1.4.5': resolution: {integrity: sha512-eiadGBKi7Vd0bCArBUOO/qqRYPHt/VQVvGyYvDFt6C2ZSIjlD+HuOl+2oS1sjf4CFjK4eDIog6EdXnL0NE6iyQ==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [musl] '@napi-rs/lzma-wasm32-wasi@1.4.5': resolution: {integrity: sha512-+VyHHlr68dvey6fXc2hehw9gHVFIW3TtGF1XkcbAu65qVXsA9D/T+uuoRVqhE+JCyFHFrO0ixRbZDRK1XJt1sA==} @@ -1527,42 +1522,36 @@ packages: engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [glibc] '@napi-rs/tar-linux-arm64-musl@1.1.0': resolution: {integrity: sha512-L/y1/26q9L/uBqiW/JdOb/Dc94egFvNALUZV2WCGKQXc6UByPBMgdiEyW2dtoYxYYYYc+AKD+jr+wQPcvX2vrQ==} engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [musl] '@napi-rs/tar-linux-ppc64-gnu@1.1.0': resolution: {integrity: sha512-EPE1K/80RQvPbLRJDJs1QmCIcH+7WRi0F73+oTe1582y9RtfGRuzAkzeBuAGRXAQEjRQw/RjtNqr6UTJ+8UuWQ==} engines: {node: '>= 10'} cpu: [ppc64] os: [linux] - libc: [glibc] '@napi-rs/tar-linux-s390x-gnu@1.1.0': resolution: {integrity: sha512-B2jhWiB1ffw1nQBqLUP1h4+J1ovAxBOoe5N2IqDMOc63fsPZKNqF1PvO/dIem8z7LL4U4bsfmhy3gBfu547oNQ==} engines: {node: '>= 10'} cpu: [s390x] os: [linux] - libc: [glibc] '@napi-rs/tar-linux-x64-gnu@1.1.0': resolution: {integrity: sha512-tbZDHnb9617lTnsDMGo/eAMZxnsQFnaRe+MszRqHguKfMwkisc9CCJnks/r1o84u5fECI+J/HOrKXgczq/3Oww==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [glibc] '@napi-rs/tar-linux-x64-musl@1.1.0': resolution: {integrity: sha512-dV6cODlzbO8u6Anmv2N/ilQHq/AWz0xyltuXoLU3yUyXbZcnWYZuB2rL8OBGPmqNcD+x9NdScBNXh7vWN0naSQ==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [musl] '@napi-rs/tar-wasm32-wasi@1.1.0': resolution: {integrity: sha512-jIa9nb2HzOrfH0F8QQ9g3WE4aMH5vSI5/1NYVNm9ysCmNjCCtMXCAhlI3WKCdm/DwHf0zLqdrrtDFXODcNaqMw==} @@ -1629,28 +1618,24 @@ packages: engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [glibc] '@napi-rs/wasm-tools-linux-arm64-musl@1.0.1': resolution: {integrity: sha512-jAasbIvjZXCgX0TCuEFQr+4D6Lla/3AAVx2LmDuMjgG4xoIXzjKWl7c4chuaD+TI+prWT0X6LJcdzFT+ROKGHQ==} engines: {node: '>= 10'} cpu: [arm64] os: [linux] - libc: [musl] '@napi-rs/wasm-tools-linux-x64-gnu@1.0.1': resolution: {integrity: sha512-Plgk5rPqqK2nocBGajkMVbGm010Z7dnUgq0wtnYRZbzWWxwWcXfZMPa8EYxrK4eE8SzpI7VlZP1tdVsdjgGwMw==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [glibc] '@napi-rs/wasm-tools-linux-x64-musl@1.0.1': resolution: {integrity: sha512-GW7AzGuWxtQkyHknHWYFdR0CHmW6is8rG2Rf4V6GNmMpmwtXt/ItWYWtBe4zqJWycMNazpfZKSw/BpT7/MVCXQ==} engines: {node: '>= 10'} cpu: [x64] os: [linux] - libc: [musl] '@napi-rs/wasm-tools-wasm32-wasi@1.0.1': resolution: {integrity: sha512-/nQVSTrqSsn7YdAc2R7Ips/tnw5SPUcl3D7QrXCNGPqjbatIspnaexvaOYNyKMU6xPu+pc0BTnKVmqhlJJCPLA==} @@ -2469,49 +2454,41 @@ packages: resolution: {integrity: sha512-ukHZp9Vm07AlxqdOLFf8Bj4inzpt+ISbbODvwwHxX32GfcMLWYYJGAYWc13IGhWoElvWnI7D1M9ifDGyTNRGzg==} cpu: [arm64] os: [linux] - libc: [glibc] '@oxc-resolver/binding-linux-arm64-musl@11.7.1': resolution: {integrity: sha512-atkZ1OIt6t90kjQz1iqq6cN3OpfPG5zUJlO64Vd1ieYeqHRkOFeRgnWEobTePUHi34NlYr7mNZqIaAg7gjPUFg==} cpu: [arm64] os: [linux] - libc: [musl] '@oxc-resolver/binding-linux-ppc64-gnu@11.7.1': resolution: {integrity: sha512-HGgV4z3JwVF4Qvg2a1GhDnqn8mKLihy5Gp4rMfqNIAlERPSyIxo8oPQIL1XQKLYyyrkEEO99uwM+4cQGwhtbpQ==} cpu: [ppc64] os: [linux] - libc: [glibc] '@oxc-resolver/binding-linux-riscv64-gnu@11.7.1': resolution: {integrity: sha512-+vCO7iOR1s6VGefV02R2a702IASNWhSNm/MrR8RcWjKChmU0G+d1iC0oToUrGC4ovAEfstx2/O8EkROnfcLgrA==} cpu: [riscv64] os: [linux] - libc: [glibc] '@oxc-resolver/binding-linux-riscv64-musl@11.7.1': resolution: {integrity: sha512-3folNmS5gYNFy/9HYzLcdeThqAGvDJU0gQKrhHn7RPWQa58yZ0ZPpBMk6KRSSO61+wkchkL+0sdcLsoe5wZW8g==} cpu: [riscv64] os: [linux] - libc: [musl] '@oxc-resolver/binding-linux-s390x-gnu@11.7.1': resolution: {integrity: sha512-Ceo4z6g8vqPUKADROFL0b7MoyXlUdOBYCxTDu/fhd/5I3Ydk2S6bxkjJdzpBdlu+h2Z+eS9lTHFvkwkaORMPzw==} cpu: [s390x] os: [linux] - libc: [glibc] '@oxc-resolver/binding-linux-x64-gnu@11.7.1': resolution: {integrity: sha512-QyFW5e43imQLxiBpCImhOiP4hY9coWGjroEm8elDqGNNaA7vXooaMQS2N3avMQawSaKhsb/3RemxaZ852XG38Q==} cpu: [x64] os: [linux] - libc: [glibc] '@oxc-resolver/binding-linux-x64-musl@11.7.1': resolution: {integrity: sha512-JhuCqCqktqQyQVc37V+eDiP3buCIuyCLpb92tUEyAP8nY3dy2b/ojMrH1ZNnJUlfY/67AqoZPL6nQGAB2WA3Sg==} cpu: [x64] os: [linux] - libc: [musl] '@oxc-resolver/binding-wasm32-wasi@11.7.1': resolution: {integrity: sha512-sMXm5Z2rfBwkCUespZBJCPhCVbgh/fpYQ23BQs0PmnvWoXrGQHWvnvg1p/GYmleN+nwe8strBjfutirZFiC5lA==} @@ -2547,25 +2524,21 @@ packages: resolution: {integrity: sha512-N1FqdKfwhVWPpMElv8qlGqdEefTbDYaRVhdGWOjs/2f7FESa5vX0cvA7ToqzkoXyXZI5DqByWiPML33njK30Kg==} cpu: [arm64] os: [linux] - libc: [glibc] '@oxlint/linux-arm64-musl@1.14.0': resolution: {integrity: sha512-v/BPuiateLBb7Gz1STb69EWjkgKdlPQ1NM56z+QQur21ly2hiMkBX2n0zEhqfu9PQVRUizu6AlsYuzcPY/zsIQ==} cpu: [arm64] os: [linux] - libc: [musl] '@oxlint/linux-x64-gnu@1.14.0': resolution: {integrity: sha512-gUTp8KIrSYt97dn+tRRC3LKnH4xlHKCwrPwiDcGmLbCxojuN9/H5mnIhPKEfwNuZNdoKGS/ABuq3neVyvRCRtQ==} cpu: [x64] os: [linux] - libc: [glibc] '@oxlint/linux-x64-musl@1.14.0': resolution: {integrity: sha512-DpN6cW2HPjYXeENG0JBbmubO8LtfKt6qJqEMBw9gUevbyBaX+k+Jn7sYgh6S23wGOkzmTNphBsf/7ulj4nIVYA==} cpu: [x64] os: [linux] - libc: [musl] '@oxlint/win32-arm64@1.14.0': resolution: {integrity: sha512-oXxJksnUTUMgJ0NvjKS1mrCXAy1ttPgIVacRSlxQ+1XHy+aJDMM7I8fsCtoKoEcTIpPaD98eqUqlLYs0H2MGjA==} @@ -5504,6 +5477,10 @@ packages: resolution: {integrity: sha512-oVlzkg3ENAhCk2zdv7IJwd/QUD4z2RxRwpkcGY8psCVcCYZNq4wYnVWALHM+brtuJjePWiYF/ClmuDr8Ch5+kg==} engines: {node: '>= 0.8'} + on-headers@1.1.0: + resolution: {integrity: sha512-737ZY3yNnXy37FHkQxPzt4UZ2UWPWiCZWLvFZ4fu5cueciegX0zGPnrlY6bwRg4FdQOe9YU8MkmJwGhoMybl8A==} + engines: {node: '>= 0.8'} + once@1.4.0: resolution: {integrity: sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w==} @@ -5983,6 +5960,10 @@ packages: resolution: {integrity: sha512-oKWePCxqpd6FlLvGV1VU0x7bkPmmCNolxzjMf4NczoDnQcIWrAF+cPtZn5i6n+RfD2d9i0tzpKnG6Yk168yIyw==} hasBin: true + response-time@2.3.4: + resolution: {integrity: sha512-fiyq1RvW5/Br6iAtT8jN1XrNY8WPu2+yEypLbaijWry8WDZmn12azG9p/+c+qpEebURLlQmqCB8BNSu7ji+xQQ==} + engines: {node: '>= 0.8.0'} + restore-cursor@5.1.0: resolution: {integrity: sha512-oMA2dcrw6u0YfxJQXm342bFKX/E4sG9rbTzO9ptUcR/e8A33cHuvStiYOwH7fszkZlZ1z/ta9AAoPk2F4qIOHA==} engines: {node: '>=18'} @@ -13806,6 +13787,8 @@ snapshots: dependencies: ee-first: 1.1.1 + on-headers@1.1.0: {} + once@1.4.0: dependencies: wrappy: 1.0.2 @@ -14344,6 +14327,11 @@ snapshots: path-parse: 1.0.7 supports-preserve-symlinks-flag: 1.0.0 + response-time@2.3.4: + dependencies: + depd: 2.0.0 + on-headers: 1.1.0 + restore-cursor@5.1.0: dependencies: onetime: 7.0.0 diff --git a/apps/api/src/controllers/v1/scrape.ts b/apps/api/src/controllers/v1/scrape.ts index 615a6537c..26dac68c1 100644 --- a/apps/api/src/controllers/v1/scrape.ts +++ b/apps/api/src/controllers/v1/scrape.ts @@ -19,6 +19,11 @@ export async function scrapeController( req: RequestWithAuth<{}, ScrapeResponse, ScrapeRequest>, res: Response, ) { + // Get timing data from middleware (includes all middleware processing time) + const middlewareStartTime = + (req as any).requestTiming?.startTime || new Date().getTime(); + const controllerStartTime = new Date().getTime(); + const jobId: string = uuidv4(); const preNormalizedBody = { ...req.body }; req.body = scrapeRequestSchema.parse(req.body); @@ -43,7 +48,10 @@ export async function scrapeController( zeroDataRetention, }); + const middlewareTime = controllerStartTime - middlewareStartTime; + logger.debug("Scrape " + jobId + " starting", { + version: "v1", scrapeId: jobId, request: req.body, originalRequest: preNormalizedBody, @@ -89,7 +97,7 @@ export async function scrapeController( }, origin, integration: req.body.integration, - startTime, + startTime: controllerStartTime, zeroDataRetention: zeroDataRetention ?? false, apiKeyId: req.acuc?.api_key_id ?? null, }, @@ -118,7 +126,7 @@ export async function scrapeController( ); } catch (e) { logger.error(`Error in scrapeController`, { - startTime, + version: "v1", error: e, }); @@ -153,6 +161,18 @@ export async function scrapeController( } } + const totalRequestTime = new Date().getTime() - middlewareStartTime; + const controllerTime = new Date().getTime() - controllerStartTime; + logger.info("Request metrics", { + version: "v1", + scrapeId: jobId, + middlewareStartTime, + controllerStartTime, + middlewareTime, + controllerTime, + totalRequestTime, + }); + return res.status(200).json({ success: true, data: doc, diff --git a/apps/api/src/controllers/v1/search.ts b/apps/api/src/controllers/v1/search.ts index b4d3dd6e0..26917217c 100644 --- a/apps/api/src/controllers/v1/search.ts +++ b/apps/api/src/controllers/v1/search.ts @@ -223,6 +223,10 @@ export async function searchController( req: RequestWithAuth<{}, SearchResponse, SearchRequest>, res: Response, ) { + // Get timing data from middleware (includes all middleware processing time) + const middlewareStartTime = (req as any).requestTiming?.startTime || new Date().getTime(); + const controllerStartTime = new Date().getTime(); + const jobId = uuidv4(); let logger = _logger.child({ jobId, @@ -245,7 +249,7 @@ export async function searchController( success: true, data: [], }; - const startTime = new Date().getTime(); + const middlewareTime = controllerStartTime - middlewareStartTime; const isSearchPreview = process.env.SEARCH_PREVIEW_TOKEN !== undefined && process.env.SEARCH_PREVIEW_TOKEN === req.body.__searchPreviewToken; @@ -257,6 +261,7 @@ export async function searchController( req.body = searchRequestSchema.parse(req.body); logger = logger.child({ + version: "v1", query: req.body.query, origin: req.body.origin, }); @@ -411,7 +416,7 @@ export async function searchController( } const endTime = new Date().getTime(); - const timeTakenInSeconds = (endTime - startTime) / 1000; + const timeTakenInSeconds = (endTime - middlewareStartTime) / 1000; logger.info("Logging job", { num_docs: responseData.data.length, @@ -443,6 +448,20 @@ export async function searchController( isSearchPreview, ); + // Log final timing information + const totalRequestTime = new Date().getTime() - middlewareStartTime; + const controllerTime = new Date().getTime() - controllerStartTime; + logger.info("Search completed successfully", { + version: "v1", + jobId, + middlewareStartTime, + controllerStartTime, + middlewareTime, + controllerTime, + totalRequestTime, + creditsUsed: credits_billed, + }); + return res.status(200).json(responseData); } catch (error) { if (error instanceof ScrapeJobTimeoutError) { @@ -454,7 +473,10 @@ export async function searchController( } Sentry.captureException(error); - logger.error("Unhandled error occurred in search", { error }); + logger.error("Unhandled error occurred in search", { + version: "v1", + error + }); return res.status(500).json({ success: false, error: error.message, diff --git a/apps/api/src/controllers/v2/scrape.ts b/apps/api/src/controllers/v2/scrape.ts index 1eff281e4..2bdb1ccbf 100644 --- a/apps/api/src/controllers/v2/scrape.ts +++ b/apps/api/src/controllers/v2/scrape.ts @@ -19,6 +19,10 @@ export async function scrapeController( req: RequestWithAuth<{}, ScrapeResponse, ScrapeRequest>, res: Response, ) { + // Get timing data from middleware (includes all middleware processing time) + const middlewareStartTime = (req as any).requestTiming?.startTime || new Date().getTime(); + const controllerStartTime = new Date().getTime(); + const jobId = uuidv4(); const preNormalizedBody = { ...req.body }; req.body = scrapeRequestSchema.parse(req.body); @@ -43,7 +47,10 @@ export async function scrapeController( zeroDataRetention, }); + const middlewareTime = controllerStartTime - middlewareStartTime; + logger.debug("Scrape " + jobId + " starting", { + version: "v2", scrapeId: jobId, request: req.body, originalRequest: preNormalizedBody, @@ -53,7 +60,6 @@ export async function scrapeController( const origin = req.body.origin; const timeout = req.body.timeout; - const startTime = new Date().getTime(); const isDirectToBullMQ = process.env.SEARCH_PREVIEW_TOKEN !== undefined && @@ -89,7 +95,7 @@ export async function scrapeController( }, origin, integration: req.body.integration, - startTime, + startTime: controllerStartTime, zeroDataRetention, apiKeyId: req.acuc?.api_key_id ?? null, }, @@ -115,7 +121,7 @@ export async function scrapeController( ); } catch (e) { logger.error(`Error in scrapeController`, { - startTime, + version: "v2", error: e, }); @@ -138,6 +144,7 @@ export async function scrapeController( } await scrapeQueue.removeJob(jobId, logger); + if (!hasFormatOfType(req.body.formats, "rawHtml")) { if (doc && doc.rawHtml) { @@ -145,6 +152,19 @@ export async function scrapeController( } } + const totalRequestTime = new Date().getTime() - middlewareStartTime; + const controllerTime = new Date().getTime() - controllerStartTime; + logger.info("Request metrics", { + version: "v2", + scrapeId: jobId, + middlewareStartTime, + controllerStartTime, + middlewareTime, + controllerTime, + totalRequestTime, + }); + + return res.status(200).json({ success: true, data: doc, diff --git a/apps/api/src/controllers/v2/search.ts b/apps/api/src/controllers/v2/search.ts index c7bb77835..6e90d0d8f 100644 --- a/apps/api/src/controllers/v2/search.ts +++ b/apps/api/src/controllers/v2/search.ts @@ -200,6 +200,11 @@ export async function searchController( req: RequestWithAuth<{}, SearchResponse, SearchRequest>, res: Response, ) { + // Get timing data from middleware (includes all middleware processing time) + const middlewareStartTime = + (req as any).requestTiming?.startTime || new Date().getTime(); + const controllerStartTime = new Date().getTime(); + const jobId = uuidv4(); let logger = _logger.child({ jobId, @@ -217,7 +222,7 @@ export async function searchController( }); } - const startTime = new Date().getTime(); + const middlewareTime = controllerStartTime - middlewareStartTime; const isSearchPreview = process.env.SEARCH_PREVIEW_TOKEN !== undefined && process.env.SEARCH_PREVIEW_TOKEN === req.body.__searchPreviewToken; @@ -228,6 +233,7 @@ export async function searchController( req.body = searchRequestSchema.parse(req.body); logger = logger.child({ + version: "v2", query: req.body.query, origin: req.body.origin, }); @@ -469,7 +475,7 @@ export async function searchController( credits_billed = allJobIds.length; // Just for reporting, not billing const endTime = new Date().getTime(); - const timeTakenInSeconds = (endTime - startTime) / 1000; + const timeTakenInSeconds = (endTime - middlewareStartTime) / 1000; logger.info("Logging job (async scraping)", { num_docs: credits_billed, @@ -505,6 +511,20 @@ export async function searchController( isSearchPreview, ); + // Log final timing information for async mode + const totalRequestTime = new Date().getTime() - middlewareStartTime; + const controllerTime = new Date().getTime() - controllerStartTime; + logger.info("Search completed successfully (async)", { + version: "v2", + jobId, + middlewareStartTime, + controllerStartTime, + middlewareTime, + controllerTime, + totalRequestTime, + creditsUsed: credits_billed, + }); + return res.status(200).json({ success: true, data: searchResponse, @@ -612,7 +632,7 @@ export async function searchController( } const endTime = new Date().getTime(); - const timeTakenInSeconds = (endTime - startTime) / 1000; + const timeTakenInSeconds = (endTime - middlewareStartTime) / 1000; logger.info("Logging job", { num_docs: credits_billed, @@ -648,6 +668,21 @@ export async function searchController( isSearchPreview, ); + // Log final timing information + const totalRequestTime = new Date().getTime() - middlewareStartTime; + const controllerTime = new Date().getTime() - controllerStartTime; + + logger.info("Request metrics", { + version: "v2", + jobId, + middlewareStartTime, + controllerStartTime, + middlewareTime, + controllerTime, + totalRequestTime, + creditsUsed: credits_billed, + }); + // For sync scraping or no scraping, don't include scrapeIds return res.status(200).json({ success: true, @@ -673,7 +708,10 @@ export async function searchController( } Sentry.captureException(error); - logger.error("Unhandled error occurred in search", { error }); + logger.error("Unhandled error occurred in search", { + version: "v2", + error, + }); return res.status(500).json({ success: false, error: error.message, diff --git a/apps/api/src/index.ts b/apps/api/src/index.ts index 9eb6822a3..7818205bb 100644 --- a/apps/api/src/index.ts +++ b/apps/api/src/index.ts @@ -40,6 +40,7 @@ import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-grpc"; import { nuqShutdown } from "./services/worker/nuq"; import { getErrorContactMessage } from "./lib/deployment"; import { initializeBlocklist } from "./scraper/WebScraper/utils/blocklist"; +import responseTime from "response-time"; const { createBullBoard } = require("@bull-board/api"); const { BullMQAdapter } = require("@bull-board/api/bullMQAdapter"); @@ -97,6 +98,8 @@ app.use(bodyParser.json({ limit: "10mb" })); app.use(cors()); // Add this line to enable CORS +app.use(responseTime()); + if (process.env.EXPRESS_TRUST_PROXY) { app.set("trust proxy", parseInt(process.env.EXPRESS_TRUST_PROXY, 10)); } diff --git a/apps/api/src/routes/shared.ts b/apps/api/src/routes/shared.ts index fd6ee7306..97e80223e 100644 --- a/apps/api/src/routes/shared.ts +++ b/apps/api/src/routes/shared.ts @@ -243,6 +243,40 @@ export function countryCheck( next(); } +export function requestTimingMiddleware(version: string) { + return (req: Request, res: Response, next: NextFunction) => { + const startTime = new Date().getTime(); + + // Attach timing data to request + (req as any).requestTiming = { + startTime, + version + }; + + // Override res.json to log timing when response is sent + const originalJson = res.json.bind(res); + res.json = function(body: any) { + const requestTime = new Date().getTime() - startTime; + + // Only log for successful responses to avoid duplicate error logs + if (body?.success !== false) { + logger.info(`${version} request completed`, { + version, + path: req.path, + method: req.method, + startTime, + requestTime, + statusCode: res.statusCode, + }); + } + + return originalJson(body); + }; + + next(); + }; +} + export function wrap( controller: (req: Request, res: Response) => Promise, ): (req: Request, res: Response, next: NextFunction) => any { diff --git a/apps/api/src/routes/v1.ts b/apps/api/src/routes/v1.ts index 502787928..770624b45 100644 --- a/apps/api/src/routes/v1.ts +++ b/apps/api/src/routes/v1.ts @@ -30,6 +30,7 @@ import { blocklistMiddleware, countryCheck, idempotencyMiddleware, + requestTimingMiddleware, wrap, } from "./shared"; import { paymentMiddleware } from "x402-express"; @@ -42,6 +43,9 @@ expressWs(express()); export const v1Router = express.Router(); +// Add timing middleware to all v1 routes +v1Router.use(requestTimingMiddleware("v1")); + // Configure payment middleware to enable micropayment-protected endpoints // This middleware handles payment verification and processing for premium API features // x402 payments protocol - https://github.com/coinbase/x402 diff --git a/apps/api/src/routes/v2.ts b/apps/api/src/routes/v2.ts index 78afcb14f..d0365bebf 100644 --- a/apps/api/src/routes/v2.ts +++ b/apps/api/src/routes/v2.ts @@ -24,6 +24,7 @@ import { blocklistMiddleware, countryCheck, idempotencyMiddleware, + requestTimingMiddleware, wrap, } from "./shared"; import { queueStatusController } from "../controllers/v2/queue-status"; @@ -34,6 +35,9 @@ expressWs(express()); export const v2Router = express.Router(); +// Add timing middleware to all v2 routes +v2Router.use(requestTimingMiddleware("v2")); + v2Router.post( "/search", authMiddleware(RateLimiterMode.Search),