feat: start moving to SugaredTracer and collect spans manually to be able to create 'server-timing' header when debugging (#358)

* chore: wrap blob.get with individual trace, add more attributes

* feat: add server-timing header to response when x-nf-debug-logging is enabled

* chore: remove tmp extra attributes

* chore: remove dev logs

* fix: lint

* test: update request-context tests

* chore: convert to using SugaredTracer methods

* chore: fix lint, remove more unneded manual error setting on spans

* fix: let's not await await

* Apply suggestions from code review

Co-authored-by: Lukas Holzer <[email protected]>

* chore: format with prettier

* fix: rename types

---------

Co-authored-by: Lukas Holzer <[email protected]>
Co-authored-by: pieh <[email protected]>

Author: pieh

.eslintrc.cjs

@@ -33,6 +33,23 @@ module.exports = {
   },
   overrides: [
     ...overrides,
+    {
+      files: ['src/run/**'],
+      rules: {
+        'no-restricted-imports': [
+          'error',
+          {
+            paths: [
+              {
+                name: '@opentelemetry/api',
+                importNames: ['trace'],
+                message: 'Please use `getTracer()` from `./handlers/tracer.cjs` instead',
+              },
+            ],
+          },
+        ],
+      },
+    },
     {
       files: ['src/run/handlers/**'],
       rules: {

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

@@ -1,4 +1,9 @@
-import tracing, { trace } from '{{cwd}}/.netlify/dist/run/handlers/tracing.js'
+import {
+  createRequestContext,
+  runWithRequestContext,
+} from '{{cwd}}/.netlify/dist/run/handlers/request-context.cjs'
+import { getTracer } from '{{cwd}}/.netlify/dist/run/handlers/tracer.cjs'
+import tracing from '{{cwd}}/.netlify/dist/run/handlers/tracing.js'
 
 process.chdir('{{cwd}}')
 
@@ -8,10 +13,11 @@ export default async function (req, context) {
     tracing.start()
   }
 
-  /** @type {import('@opentelemetry/api').Tracer} */
-  const tracer = trace.getTracer('Next.js Runtime')
-  return tracer.startActiveSpan('Next.js Server Handler', async (span) => {
-    try {
+  const requestContext = createRequestContext(req.headers.get('x-nf-debug-logging'))
+  const tracer = getTracer()
+
+  const handlerResponse = await runWithRequestContext(requestContext, () => {
+    return tracer.withActiveSpan('Next.js Server Handler', async (span) => {
       span.setAttributes({
         'account.id': context.account.id,
         'deploy.id': context.deploy.id,
@@ -31,16 +37,14 @@ export default async function (req, context) {
         'http.status_code': response.status,
       })
       return response
-    } catch (error) {
-      span.recordException(error)
-      if (error instanceof Error) {
-        span.addEvent({ name: error.name, message: error.message })
-      }
-      throw error
-    } finally {
-      span.end()
-    }
+    })
   })
+
+  if (requestContext.serverTiming) {
+    handlerResponse.headers.set('server-timing', requestContext.serverTiming)
+  }
+
+  return handlerResponse
 }
 
 export const config = {

src/build/templates/handler.tmpl.js

@@ -1,15 +1,21 @@
+import {
+  createRequestContext,
+  runWithRequestContext,
+} from './.netlify/dist/run/handlers/request-context.cjs'
 import serverHandler from './.netlify/dist/run/handlers/server.js'
-import tracing, { trace } from './.netlify/dist/run/handlers/tracing.js'
+import { getTracer } from './.netlify/dist/run/handlers/tracer.cjs'
+import tracing from './.netlify/dist/run/handlers/tracing.js'
 
 export default async function handler(req, context) {
   if (process.env.NETLIFY_OTLP_TRACE_EXPORTER_URL) {
     tracing.start()
   }
 
-  /** @type {import('@opentelemetry/api').Tracer} */
-  const tracer = trace.getTracer('Next.js Runtime')
-  return tracer.startActiveSpan('Next.js Server Handler', async (span) => {
-    try {
+  const requestContext = createRequestContext(req.headers.get('x-nf-debug-logging'))
+  const tracer = getTracer()
+
+  const handlerResponse = await runWithRequestContext(requestContext, () => {
+    return tracer.withActiveSpan('Next.js Server Handler', async (span) => {
       span.setAttributes({
         'account.id': context.account.id,
         'deploy.id': context.deploy.id,
@@ -25,16 +31,14 @@ export default async function handler(req, context) {
         'http.status_code': response.status,
       })
       return response
-    } catch (error) {
-      span.recordException(error)
-      if (error instanceof Error) {
-        span.addEvent({ name: error.name, message: error.message })
-      }
-      throw error
-    } finally {
-      span.end()
-    }
+    })
   })
+
+  if (requestContext.serverTiming) {
+    handlerResponse.headers.set('server-timing', requestContext.serverTiming)
+  }
+
+  return handlerResponse
 }
 
 export const config = {

src/run/handlers/cache.cts

@@ -5,7 +5,7 @@ import { Buffer } from 'node:buffer'
 
 import { getDeployStore, Store } from '@netlify/blobs'
 import { purgeCache } from '@netlify/functions'
-import { trace, type Span, SpanStatusCode } from '@opentelemetry/api'
+import { type Span } from '@opentelemetry/api'
 import { NEXT_CACHE_TAGS_HEADER } from 'next/dist/lib/constants.js'
 import type {
   CacheHandler,
@@ -15,6 +15,7 @@ import type {
 } from 'next/dist/server/lib/incremental-cache/index.js'
 
 import { getRequestContext } from './request-context.cjs'
+import { getTracer } from './tracer.cjs'
 
 type TagManifest = { revalidatedAt: number }
 
@@ -26,7 +27,7 @@ export class NetlifyCacheHandler implements CacheHandler {
   options: CacheHandlerContext
   revalidatedTags: string[]
   blobStore: Store
-  tracer = trace.getTracer('Netlify Cache Handler')
+  tracer = getTracer()
   tagManifestsFetchedFromBlobStoreInCurrentRequest: TagManifestBlobCache
 
   constructor(options: CacheHandlerContext) {
@@ -90,77 +91,67 @@ export class NetlifyCacheHandler implements CacheHandler {
   }
 
   async get(...args: Parameters<CacheHandler['get']>): ReturnType<CacheHandler['get']> {
-    return this.tracer.startActiveSpan('get cache key', async (span) => {
-      try {
-        const [key, ctx = {}] = args
-        console.debug(`[NetlifyCacheHandler.get]: ${key}`)
-
-        const blobKey = await this.encodeBlobKey(key)
-        span.setAttributes({ key, blobKey })
-        const blob = (await this.blobStore.get(blobKey, {
-          type: 'json',
-        })) as CacheHandlerValue | null
+    return this.tracer.withActiveSpan('get cache key', async (span) => {
+      const [key, ctx = {}] = args
+      console.debug(`[NetlifyCacheHandler.get]: ${key}`)
 
-        // if blob is null then we don't have a cache entry
-        if (!blob) {
-          span.addEvent('Cache miss', { key, blobKey })
-          return null
-        }
+      const blobKey = await this.encodeBlobKey(key)
+      span.setAttributes({ key, blobKey })
 
-        const staleByTags = await this.checkCacheEntryStaleByTags(blob, ctx.tags, ctx.softTags)
+      const blob = (await this.tracer.withActiveSpan('blobStore.get', async (blobGetSpan) => {
+        blobGetSpan.setAttributes({ key, blobKey })
+        return await this.blobStore.get(blobKey, {
+          type: 'json',
+        })
+      })) as CacheHandlerValue | null
 
-        if (staleByTags) {
-          span.addEvent('Stale', { staleByTags })
-          return null
-        }
+      // if blob is null then we don't have a cache entry
+      if (!blob) {
+        span.addEvent('Cache miss', { key, blobKey })
+        return null
+      }
 
-        this.captureResponseCacheLastModified(blob, key, span)
+      const staleByTags = await this.checkCacheEntryStaleByTags(blob, ctx.tags, ctx.softTags)
 
-        switch (blob.value?.kind) {
-          case 'FETCH':
-            span.addEvent('FETCH', { lastModified: blob.lastModified, revalidate: ctx.revalidate })
-            return {
-              lastModified: blob.lastModified,
-              value: blob.value,
-            }
-
-          case 'ROUTE':
-            span.addEvent('ROUTE', { lastModified: blob.lastModified, status: blob.value.status })
-            return {
-              lastModified: blob.lastModified,
-              value: {
-                ...blob.value,
-                body: Buffer.from(blob.value.body as unknown as string, 'base64'),
-              },
-            }
-          case 'PAGE':
-            span.addEvent('PAGE', { lastModified: blob.lastModified })
-            return {
-              lastModified: blob.lastModified,
-              value: blob.value,
-            }
-          default:
-            span.recordException(new Error(`Unknown cache entry kind: ${blob.value?.kind}`))
-          // TODO: system level logging not implemented
-        }
+      if (staleByTags) {
+        span.addEvent('Stale', { staleByTags })
         return null
-      } catch (error) {
-        if (error instanceof Error) {
-          span.recordException(error)
-        }
-        span.setStatus({
-          code: SpanStatusCode.ERROR,
-          message: error instanceof Error ? error.message : String(error),
-        })
-        throw error
-      } finally {
-        span.end()
       }
+
+      this.captureResponseCacheLastModified(blob, key, span)
+
+      switch (blob.value?.kind) {
+        case 'FETCH':
+          span.addEvent('FETCH', { lastModified: blob.lastModified, revalidate: ctx.revalidate })
+          return {
+            lastModified: blob.lastModified,
+            value: blob.value,
+          }
+
+        case 'ROUTE':
+          span.addEvent('ROUTE', { lastModified: blob.lastModified, status: blob.value.status })
+          return {
+            lastModified: blob.lastModified,
+            value: {
+              ...blob.value,
+              body: Buffer.from(blob.value.body as unknown as string, 'base64'),
+            },
+          }
+        case 'PAGE':
+          span.addEvent('PAGE', { lastModified: blob.lastModified })
+          return {
+            lastModified: blob.lastModified,
+            value: blob.value,
+          }
+        default:
+          span.recordException(new Error(`Unknown cache entry kind: ${blob.value?.kind}`))
+      }
+      return null
     })
   }
 
   async set(...args: Parameters<IncrementalCache['set']>) {
-    return this.tracer.startActiveSpan('set cache key', async (span) => {
+    return this.tracer.withActiveSpan('set cache key', async (span) => {
       const [key, data] = args
       const blobKey = await this.encodeBlobKey(key)
       const lastModified = Date.now()
@@ -189,7 +180,6 @@ export class NetlifyCacheHandler implements CacheHandler {
           })
         }
       }
-      span.end()
     })
   }
 
@@ -264,22 +254,9 @@ export class NetlifyCacheHandler implements CacheHandler {
 
         if (!tagManifestPromise) {
           tagManifestPromise = this.encodeBlobKey(tag).then((blobKey) => {
-            return this.tracer.startActiveSpan(`get tag manifest`, async (span) => {
+            return this.tracer.withActiveSpan(`get tag manifest`, async (span) => {
               span.setAttributes({ tag, blobKey })
-              try {
-                return await this.blobStore.get(blobKey, { type: 'json' })
-              } catch (error) {
-                if (error instanceof Error) {
-                  span.recordException(error)
-                }
-                span.setStatus({
-                  code: SpanStatusCode.ERROR,
-                  message: error instanceof Error ? error.message : String(error),
-                })
-                throw error
-              } finally {
-                span.end()
-              }
+              return this.blobStore.get(blobKey, { type: 'json' })
             })
           })
 

src/run/handlers/request-context.cts

@@ -1,16 +1,20 @@
 import { AsyncLocalStorage } from 'node:async_hooks'
 
 export type RequestContext = {
+  debug: boolean
   responseCacheGetLastModified?: number
   responseCacheKey?: string
   usedFsRead?: boolean
   didPagesRouterOnDemandRevalidate?: boolean
+  serverTiming?: string
 }
 
 type RequestContextAsyncLocalStorage = AsyncLocalStorage<RequestContext>
 
-export function createRequestContext(): RequestContext {
-  return {}
+export function createRequestContext(debug = false): RequestContext {
+  return {
+    debug,
+  }
 }
 
 const REQUEST_CONTEXT_GLOBAL_KEY = Symbol.for('nf-request-context-async-local-storage')