diff --git a/src/run/handlers/cache.cts b/src/run/handlers/cache.cts index c00a4d5e14..e3ae6287f6 100644 --- a/src/run/handlers/cache.cts +++ b/src/run/handlers/cache.cts @@ -362,6 +362,7 @@ export class NetlifyCacheHandler implements CacheHandlerForMultipleVersions { .withError(error) .error(`[NetlifyCacheHandler]: Purging the cache for tag ${tag} failed`) }), + `cdn purge after page router .revalidate ${tag}`, ) } } @@ -374,7 +375,10 @@ export class NetlifyCacheHandler implements CacheHandlerForMultipleVersions { const requestContext = getRequestContext() if (requestContext) { - requestContext.trackBackgroundWork(revalidateTagPromise) + requestContext.trackBackgroundWork( + revalidateTagPromise, + `revalidateTag ${JSON.stringify(tagOrTags)}`, + ) } return revalidateTagPromise diff --git a/src/run/handlers/request-context.cts b/src/run/handlers/request-context.cts index cc67739242..5f2753dff1 100644 --- a/src/run/handlers/request-context.cts +++ b/src/run/handlers/request-context.cts @@ -26,7 +26,7 @@ export type RequestContext = { * Uses `context.waitUntil` if available, otherwise stores promises to * await on. */ - trackBackgroundWork: (promise: Promise) => void + trackBackgroundWork: (promise: Promise, description: string) => void /** * Promise that need to be executed even if response was already sent. * If `context.waitUntil` is available this promise will be always resolved @@ -41,13 +41,27 @@ type RequestContextAsyncLocalStorage = AsyncLocalStorage export function createRequestContext(request?: Request, context?: FutureContext): RequestContext { const backgroundWorkPromises: Promise[] = [] + let backgroundWorkCounter = 0 + return { captureServerTiming: request?.headers.has('x-next-debug-logging') ?? false, - trackBackgroundWork: (promise) => { + trackBackgroundWork: (promise, description) => { + backgroundWorkCounter += 1 + + const counter = backgroundWorkCounter + const label = `background #${counter} - ${description ?? 'unknown'} - ${context?.requestId}` + const start = Date.now() + + console.log(`Start ${label}`) + + const trackedPromise = promise.finally(() => { + console.log(`End ${label} - ${(Date.now() - start) / 1000}s`) + }) + if (context?.waitUntil) { - context.waitUntil(promise) + context.waitUntil(trackedPromise) } else { - backgroundWorkPromises.push(promise) + backgroundWorkPromises.push(trackedPromise) } }, get backgroundWorkPromise() { diff --git a/src/run/handlers/server.ts b/src/run/handlers/server.ts index 436411c812..dae3dbf6fc 100644 --- a/src/run/handlers/server.ts +++ b/src/run/handlers/server.ts @@ -1,6 +1,7 @@ import type { OutgoingHttpHeaders } from 'http' import { ComputeJsOutgoingMessage, toComputeResponse, toReqRes } from '@fastly/http-compute-js' +import type { Context } from '@netlify/functions' import type { NextConfigComplete } from 'next/dist/server/config-shared.js' import type { WorkerRequestHandler } from 'next/dist/server/lib/types.js' @@ -46,7 +47,11 @@ const disableFaultyTransferEncodingHandling = (res: ComputeJsOutgoingMessage) => } } -export default async (request: Request) => { +export default async (request: Request, context: Context) => { + const label = `response - ${request.url} - ${context.requestId}` + const start = Date.now() + console.log(`Start ${label}`) + const tracer = getTracer() if (!nextHandler) { @@ -128,6 +133,7 @@ export default async (request: Request) => { async flush() { // it's important to keep the stream open until the next handler has finished await nextHandlerPromise + console.log(`End ${label} - ${(Date.now() - start) / 1000}s`) // Next.js relies on `close` event emitted by response to trigger running callback variant of `next/after` // however @fastly/http-compute-js never actually emits that event - so we have to emit it ourselves, diff --git a/src/run/handlers/wait-until.cts b/src/run/handlers/wait-until.cts index 683196a47f..0e9293232b 100644 --- a/src/run/handlers/wait-until.cts +++ b/src/run/handlers/wait-until.cts @@ -20,7 +20,12 @@ export function setupWaitUntil() { // eslint-disable-next-line @typescript-eslint/no-extra-semi ;(globalThis as GlobalThisWithRequestContext)[NEXT_REQUEST_CONTEXT_SYMBOL] = { get() { - return { waitUntil: getRequestContext()?.trackBackgroundWork } + const trackBackgroundWork = getRequestContext()?.trackBackgroundWork + return { + waitUntil: trackBackgroundWork + ? (promise) => trackBackgroundWork(promise, 'after()') + : undefined, + } }, } } diff --git a/src/run/next.cts b/src/run/next.cts index 17859c4835..963a7edfb3 100644 --- a/src/run/next.cts +++ b/src/run/next.cts @@ -36,7 +36,10 @@ ResponseCache.prototype.get = function get(...getArgs: unknown[]) { const workPromise = fn(...workFnArgs) const requestContext = getRequestContext() if (requestContext && workPromise instanceof Promise) { - requestContext.trackBackgroundWork(workPromise) + requestContext.trackBackgroundWork( + workPromise, + `responseCache batcher ${JSON.stringify(key)}`, + ) } return await workPromise } @@ -54,7 +57,10 @@ ResponseCache.prototype.get = function get(...getArgs: unknown[]) { backgroundWork.set(key, _resolve) }) - requestContext.trackBackgroundWork(workPromise) + requestContext.trackBackgroundWork( + workPromise, + `responseCache pendingResponses ${JSON.stringify(key)}`, + ) } return originalPendingResponsesSet.call(this.pendingResponses, key, value) } diff --git a/src/run/revalidate.ts b/src/run/revalidate.ts index 25a5b86660..f1348f6346 100644 --- a/src/run/revalidate.ts +++ b/src/run/revalidate.ts @@ -25,7 +25,7 @@ export const nextResponseProxy = (res: ServerResponse, requestContext: RequestCo const result = originalValue.apply(target, args) if (result && isPromise(result)) { - requestContext.trackBackgroundWork(result) + requestContext.trackBackgroundWork(result, 'res.revalidate') } return result