8000 debug: verbose logging for background work tracking · opennextjs/opennextjs-netlify@c14f3a6 · GitHub
[go: up one dir, main page]
Skip to content

Commit c14f3a6

Browse files
piehpieh
committed
debug: verbose logging for background work tracking
1 parent c3e328c commit c14f3a6

File tree

6 files changed

+45
-10
lines changed

6 files changed

+45
-10
lines changed

‎src/run/handlers/cache.cts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -362,6 +362,7 @@ export class NetlifyCacheHandler implements CacheHandlerForMultipleVersions {
362362
.withError(error)
363363
.error(`[NetlifyCacheHandler]: Purging the cache for tag ${tag} failed`)
364364
}),
365+
`cdn purge after page router .revalidate ${tag}`,
365366
)
366367
}
367368
}
@@ -374,7 +375,10 @@ export class NetlifyCacheHandler implements CacheHandlerForMultipleVersions {
374375

375376
const requestContext = getRequestContext()
376377
if (requestContext) {
377-
requestContext.trackBackgroundWork(revalidateTagPromise)
378+
requestContext.trackBackgroundWork(
379+
revalidateTagPromise,
380+
`revalidateTag ${JSON.stringify(tagOrTags)}`,
381+
)
378382
}
379383

380384
return revalidateTagPromise

‎src/run/handlers/request-context.cts

Lines changed: 18 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,7 @@ export type RequestContext = {
2626
* Uses `context.waitUntil` if available, otherwise stores promises to
2727
* await on.
2828
*/
29-
trackBackgroundWork: (promise: Promise<unknown>) => void
29+
trackBackgroundWork: (promise: Promise<unknown>, description: string) => void
3030
/**
3131
* Promise that need to be executed even if response was already sent.
3232
* If `context.waitUntil` is available this promise will be always resolved
@@ -41,13 +41,27 @@ type RequestContextAsyncLocalStorage = AsyncLocalStorage<RequestContext>
4141
export function createRequestContext(request?: Request, context?: FutureContext): RequestContext {
4242
const backgroundWorkPromises: Promise<unknown>[] = []
4343

44+
let backgroundWorkCounter = 0
45+
4446
return {
4547
captureServerTiming: request?.headers.has('x-next-debug-logging') ?? false,
46-
trackBackgroundWork: (promise) => {
48+
trackBackgroundWork: (promise, description) => {
49+
backgroundWorkCounter += 1
50+
51+
const counter = backgroundWorkCounter
52+
const label = `background #${counter} - ${description ?? 'unknown'} - ${context?.requestId}`
53+
const start = Date.now()
54+
55+
console.log(`Start ${label}`)
56+
57+
const trackedPromise = promise.finally(() => {
58+
console.log(`End ${label} - ${(Date.now() - start) / 1000}s`)
59+
})
60+
4761
if (context?.waitUntil) {
48-
context.waitUntil(promise)
62+
context.waitUntil(trackedPromise)
4963
} else {
50-
backgroundWorkPromises.push(promise)
64+
backgroundWorkPromises.push(trackedPromise)
5165
}
5266
},
5367
get backgroundWorkPromise() {

‎src/run/handlers/server.ts

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import type { OutgoingHttpHeaders } from 'http'
22

33
import { ComputeJsOutgoingMessage, toComputeResponse, toReqRes } from '@fastly/http-compute-js'
4+
import type { Context } from '@netlify/functions'
45
import type { NextConfigComplete } from 'next/dist/server/config-shared.js'
56
import type { WorkerRequestHandler } from 'next/dist/server/lib/types.js'
67

@@ -46,7 +47,11 @@ const disableFaultyTransferEncodingHandling = (res: ComputeJsOutgoingMessage) =>
4647
}
4748
}
4849

49-
export default async (request: Request) => {
50+
export default async (request: Request, context: Context) => {
51+
const label = `response - ${request.url} - ${context.requestId}`
52+
const start = Date.now()
53+
console.log(`Start ${label}`)
54+
5055
const tracer = getTracer()
5156

5257
if (!nextHandler) {
@@ -128,6 +133,7 @@ export default async (request: Request) => {
128133
async flush() {
129134
// it's important to keep the stream open until the next handler has finished
130135
await nextHandlerPromise
136+
console.log(`End ${label} - ${(Date.now() - start) / 1000}s`)
131137

132138
// Next.js relies on `close` event emitted by response to trigger running callback variant of `next/after`
133139
// however @fastly/http-compute-js never actually emits that event - so we have to emit it ourselves,

‎src/run/handlers/wait-until.cts

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,12 @@ export function setupWaitUntil() {
2020
// eslint-disable-next-line @typescript-eslint/no-extra-semi
2121
;(globalThis as GlobalThisWithRequestContext)[NEXT_REQUEST_CONTEXT_SYMBOL] = {
2222
get() {
23-
return { waitUntil: getRequestContext()?.trackBackgroundWork }
23+
const trackBackgroundWork = getRequestContext()?.trackBackgroundWork
24+
return {
25+
waitUntil: trackBackgroundWork
26+
? (promise) => trackBackgroundWork(promise, 'after()')
27+
: undefined,
28+
}
2429
},
2530
}
2631
}

‎src/run/next.cts

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,10 @@ ResponseCache.prototype.get = function get(...getArgs: unknown[]) {
3636
const workPromise = fn(...workFnArgs)
3737
const requestContext = getRequestContext()
3838
if (requestContext && workPromise instanceof Promise) {
39-
requestContext.trackBackgroundWork(workPromise)
39+
requestContext.trackBackgroundWork(
40+
workPromise,
41+
`responseCache batcher ${JSON.stringify(key)}`,
42+
)
4043
}
4144
return await workPromise
4245
}
@@ -54,7 +57,10 @@ ResponseCache.prototype.get = function get(...getArgs: unknown[]) {
5457
backgroundWork.set(key, _resolve)
5558
})
5659

57-
requestContext.trackBackgroundWork(workPromise)
60+
requestContext.trackBackgroundWork(
61+
workPromise,
62+
`responseCache pendingResponses ${JSON.stringify(key)}`,
63+
)
5864
}
5965
return originalPendingResponsesSet.call(this.pendingResponses, key, value)
6066
}

‎src/run/revalidate.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ export const nextResponseProxy = (res: ServerResponse, requestContext: RequestCo
2525

2626
const result = originalValue.apply(target, args)
2727
if (result && isPromise(result)) {
28-
requestContext.trackBackgroundWork(result)
28+
requestContext.trackBackgroundWork(result, 'res.revalidate')
2929
}
3030

3131
return result

0 commit comments

Comments
 (0)
0