fix: set systemlogger debug log level for debug requests (#571)

Author: pieh

src/build/content/server.ts

@@ -19,7 +19,6 @@ import glob from 'fast-glob'
 import { prerelease, lt as semverLowerThan, lte as semverLowerThanOrEqual } from 'semver'
 
 import { RUN_CONFIG } from '../../run/constants.js'
-import { logger } from '../../run/systemlog.cjs'
 import { PluginContext } from '../plugin-context.js'
 import { verifyNextVersion } from '../verification.js'
 
@@ -342,7 +341,7 @@ export const writeTagsManifest = async (ctx: PluginContext): Promise<void> => {
       } catch {
         // Parallel route default layout has no prerendered page, so don't warn about it
         if (!definition.dataRoute?.endsWith('/default.rsc')) {
-          logger.log(`Unable to read cache tags for: ${path}`)
+          console.log(`Unable to read cache tags for: ${path}`)
         }
       }
     }

src/build/templates/handler-monorepo.tmpl.js

@@ -16,7 +16,7 @@ export default async function (req, context) {
     tracing.start()
   }
 
-  const requestContext = createRequestContext(req.headers.get('x-next-debug-logging'))
+  const requestContext = createRequestContext(req)
   const tracer = getTracer()
 
   const handlerResponse = await runWithRequestContext(requestContext, () => {

src/build/templates/handler.tmpl.js

@@ -13,7 +13,7 @@ export default async function handler(req, context) {
   if (process.env.NETLIFY_OTLP_TRACE_EXPORTER_URL) {
     tracing.start()
   }
-  const requestContext = createRequestContext(req.headers.get('x-next-debug-logging'))
+  const requestContext = createRequestContext(req)
   const tracer = getTracer()
 
   const handlerResponse = await runWithRequestContext(requestContext, () => {

src/run/handlers/cache.cts

@@ -17,9 +17,8 @@ import type {
   NetlifyIncrementalCacheValue,
 } from '../../shared/cache-types.cjs'
 import { getRegionalBlobStore } from '../regional-blob-store.cjs'
-import { logger } from '../systemlog.cjs'
 
-import { getRequestContext } from './request-context.cjs'
+import { getLogger, getRequestContext } from './request-context.cjs'
 import { getTracer } from './tracer.cjs'
 
 type TagManifest = { revalidatedAt: number }
@@ -109,7 +108,7 @@ export class NetlifyCacheHandler implements CacheHandler {
   async get(...args: Parameters<CacheHandler['get']>): ReturnType<CacheHandler['get']> {
     return this.tracer.withActiveSpan('get cache key', async (span) => {
       const [key, ctx = {}] = args
-      logger.debug(`[NetlifyCacheHandler.get]: ${key}`)
+      getLogger().debug(`[NetlifyCacheHandler.get]: ${key}`)
 
       const blobKey = await this.encodeBlobKey(key)
       span.setAttributes({ key, blobKey })
@@ -177,7 +176,7 @@ export class NetlifyCacheHandler implements CacheHandler {
       const lastModified = Date.now()
       span.setAttributes({ key, lastModified, blobKey })
 
-      logger.debug(`[NetlifyCacheHandler.set]: ${key}`)
+      getLogger().debug(`[NetlifyCacheHandler.set]: ${key}`)
 
       const value: NetlifyIncrementalCacheValue | null =
         data?.kind === 'ROUTE'
@@ -198,10 +197,10 @@ export class NetlifyCacheHandler implements CacheHandler {
         const requestContext = getRequestContext()
         if (requestContext?.didPagesRouterOnDemandRevalidate) {
           const tag = `_N_T_${key === '/index' ? '/' : key}`
-          logger.debug(`Purging CDN cache for: [${tag}]`)
+          getLogger().debug(`Purging CDN cache for: [${tag}]`)
           purgeCache({ tags: [tag] }).catch((error) => {
             // TODO: add reporting here
-            logger
+            getLogger()
               .withError(error)
               .error(`[NetlifyCacheHandler]: Purging the cache for tag ${tag} failed`)
           })
@@ -212,7 +211,7 @@ export class NetlifyCacheHandler implements CacheHandler {
 
   // eslint-disable-next-line @typescript-eslint/no-explicit-any
   async revalidateTag(tagOrTags: string | string[], ...args: any) {
-    logger.withFields({ tagOrTags, args }).debug('NetlifyCacheHandler.revalidateTag')
+    getLogger().withFields({ tagOrTags, args }).debug('NetlifyCacheHandler.revalidateTag')
 
     const tags = Array.isArray(tagOrTags) ? tagOrTags : [tagOrTags]
 
@@ -225,14 +224,14 @@ export class NetlifyCacheHandler implements CacheHandler {
         try {
           await this.blobStore.setJSON(await this.encodeBlobKey(tag), data)
         } catch (error) {
-          logger.withError(error).log(`Failed to update tag manifest for ${tag}`)
+          getLogger().withError(error).log(`Failed to update tag manifest for ${tag}`)
         }
       }),
     )
 
     purgeCache({ tags }).catch((error) => {
       // TODO: add reporting here
-      logger
+      getLogger()
         .withError(error)
         .error(`[NetlifyCacheHandler]: Purging the cache for tags ${tags.join(', ')} failed`)
     })

src/run/handlers/request-context.cts

@@ -1,9 +1,13 @@
 import { AsyncLocalStorage } from 'node:async_hooks'
 
+import { LogLevel, systemLogger } from '@netlify/functions/internal'
+
 import type { NetlifyCachedRouteValue } from '../../shared/cache-types.cjs'
 
+type SystemLogger = typeof systemLogger
+
 export type RequestContext = {
-  debug: boolean
+  captureServerTiming: boolean
   responseCacheGetLastModified?: number
   responseCacheKey?: string
   usedFsRead?: boolean
@@ -18,21 +22,27 @@ export type RequestContext = {
    * Promise that need to be executed even if response was already sent
    */
   backgroundWorkPromise: Promise<unknown>
+  logger: SystemLogger
 }
 
 type RequestContextAsyncLocalStorage = AsyncLocalStorage<RequestContext>
 
-export function createRequestContext(debug = false): RequestContext {
+export function createRequestContext(request?: Request): RequestContext {
   const backgroundWorkPromises: Promise<unknown>[] = []
 
   return {
-    debug,
+    captureServerTiming: request?.headers.has('x-next-debug-logging') ?? false,
     trackBackgroundWork: (promise) => {
       backgroundWorkPromises.push(promise)
     },
     get backgroundWorkPromise() {
       return Promise.allSettled(backgroundWorkPromises)
     },
+    logger: systemLogger.withLogLevel(
+      request?.headers.has('x-nf-debug-logging') || request?.headers.has('x-next-debug-logging')
+        ? LogLevel.Debug
+        : LogLevel.Log,
+    ),
   }
 }
 
@@ -66,3 +76,7 @@ export const getRequestContext = () => getRequestContextAsyncLocalStorage().getS
 export function runWithRequestContext<T>(requestContext: RequestContext, fn: () => T): T {
   return getRequestContextAsyncLocalStorage().run(requestContext, fn)
 }
+
+export function getLogger(): SystemLogger {
+  return getRequestContext()?.logger ?? systemLogger
+}

src/run/handlers/server.ts

@@ -14,9 +14,8 @@ import {
   setVaryHeaders,
 } from '../headers.js'
 import { nextResponseProxy } from '../revalidate.js'
-import { logger } from '../systemlog.cjs'
 
-import { createRequestContext, getRequestContext } from './request-context.cjs'
+import { createRequestContext, getLogger, getRequestContext } from './request-context.cjs'
 import { getTracer } from './tracer.cjs'
 
 const nextImportPromise = import('../next.cjs')
@@ -107,7 +106,7 @@ export default async (request: Request, context: FutureContext) => {
 
     // We don't await this here, because it won't resolve until the response is finished.
     const nextHandlerPromise = nextHandler(req, resProxy).catch((error) => {
-      logger.withError(error).error('next handler error')
+      getLogger().withError(error).error('next handler error')
       console.error(error)
       resProxy.statusCode = 500
       span.setAttribute('http.status_code', 500)

src/run/handlers/tracer.cts

@@ -18,7 +18,7 @@ function spanHook(span: Span): Span {
     const meta = spanMeta.get(span)
     if (meta) {
       const requestContext = getRequestContext()
-      if (requestContext?.debug) {
+      if (requestContext?.captureServerTiming) {
         const duration = (typeof endTime === 'number' ? endTime : performance.now()) - meta.start
 
         const serverTiming = requestContext.serverTiming ?? ''

src/run/handlers/tracing.ts

@@ -7,7 +7,7 @@ import {
   SEMRESATTRS_SERVICE_VERSION,
 } from '@opentelemetry/semantic-conventions'
 
-import { logger } from '../systemlog.cjs'
+import { getLogger } from './request-context.cjs'
 
 const {
   default: { version, name },
@@ -33,7 +33,8 @@ process.on('SIGTERM', () => {
     .then(
       // eslint-disable-next-line @typescript-eslint/no-empty-function
       () => {},
-      (error: unknown) => logger.withError(error).log('Error shutting down OpenTelemetry NodeSDK'),
+      (error: unknown) =>
+        getLogger().withError(error).log('Error shutting down OpenTelemetry NodeSDK'),
     )
     // eslint-disable-next-line n/no-process-exit
     .finally(() => process.exit(0))