chore: follow up to SWR to address not blocking comments (#238)

* test: rename test to have more accurate name

* feat: create OTEL span for generating response, add some useful attributes

* fix: fix wrong cache-status for miss

* chore: move http attributes to entry of handler, add status_code, rethrow error

* feat: add span for getting blob for date calculation

Author: pieh

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

@@ -17,16 +17,23 @@ export default async function (req, context) {
           'deploy.id': context.deploy.id,
           'request.id': context.requestId,
           'site.id': context.site.id,
+          'http.method': req.method,
+          'http.target': req.url,
           monorepo: true,
           cwd: '{{cwd}}',
         })
         if (!cachedHandler) {
           const { default: handler } = await import('./{{nextServerHandler}}')
           cachedHandler = handler
         }
-        return cachedHandler(req, context)
+        const response = await cachedHandler(req, context)
+        span.setAttributes({
+          'http.status_code': response.status,
+        })
+        return response
       } catch (error) {
         span.recordException(error)
+        throw error
       } finally {
         span.end()
       }

src/build/templates/handler.tmpl.js

@@ -1,7 +1,7 @@
 import serverHandler from './dist/run/handlers/server.js'
 import tracing, { trace } from './dist/run/handlers/tracing.js'
 
-export default function handler(req, context) {
+export default async function handler(req, context) {
   if (process.env.NETLIFY_OTLP_TRACE_EXPORTER_URL) {
     tracing.start()
   }
@@ -14,10 +14,17 @@ export default function handler(req, context) {
           'deploy.id': context.deploy.id,
           'request.id': context.requestId,
           'site.id': context.site.id,
+          'http.method': req.method,
+          'http.target': req.url,
         })
-        return serverHandler(req, context)
+        const response = await serverHandler(req, context)
+        span.setAttributes({
+          'http.status_code': response.status,
+        })
+        return response
       } catch (error) {
         span.recordException(error)
+        throw error
       } finally {
         span.end()
       }

src/run/handlers/server.ts

@@ -46,50 +46,55 @@ export default async (request: Request) => {
     })
   }
 
-  const { req, res } = toReqRes(request)
+  return await tracer.startActiveSpan('generate response', async (span) => {
+    const { req, res } = toReqRes(request)
 
-  const resProxy = nextResponseProxy(res)
+    const resProxy = nextResponseProxy(res)
 
-  // temporary workaround for https://linear.app/netlify/issue/ADN-111/
-  delete req.headers['accept-encoding']
+    // temporary workaround for https://linear.app/netlify/issue/ADN-111/
+    delete req.headers['accept-encoding']
 
-  // 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')
-    console.error(error)
-    resProxy.statusCode = 500
-    resProxy.end('Internal Server Error')
-  })
+    // 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')
+      console.error(error)
+      resProxy.statusCode = 500
+      resProxy.end('Internal Server Error')
+    })
 
-  // Contrary to the docs, this resolves when the headers are available, not when the stream closes.
-  // See https://github.com/fastly/http-compute-js/blob/main/src/http-compute-js/http-server.ts#L168-L173
-  const response = await toComputeResponse(resProxy)
-
-  await adjustDateHeader(response.headers, request)
-
-  setCacheControlHeaders(response.headers, request)
-  setCacheTagsHeaders(response.headers, request, tagsManifest)
-  setVaryHeaders(response.headers, request, nextConfig)
-  handleNextCacheHeader(response.headers)
-
-  // Temporary workaround for an issue where sending a response with an empty
-  // body causes an unhandled error. This doesn't catch everything, but redirects are the
-  // most common case of sending empty bodies. We can't check it directly because these are streams.
-  // The side effect is that responses which do contain data will not be streamed to the client,
-  // but that's fine for redirects.
-  // TODO: Remove once a fix has been rolled out.
-  if ((response.status > 300 && response.status < 400) || response.status >= 500) {
-    const body = await response.text()
-    return new Response(body || null, response)
-  }
+    // Contrary to the docs, this resolves when the headers are available, not when the stream closes.
+    // See https://github.com/fastly/http-compute-js/blob/main/src/http-compute-js/http-server.ts#L168-L173
+    const response = await toComputeResponse(resProxy)
+
+    await adjustDateHeader(response.headers, request, span, tracer)
+
+    setCacheControlHeaders(response.headers, request)
+    setCacheTagsHeaders(response.headers, request, tagsManifest)
+    setVaryHeaders(response.headers, request, nextConfig)
+    handleNextCacheHeader(response.headers)
+
+    // Temporary workaround for an issue where sending a response with an empty
+    // body causes an unhandled error. This doesn't catch everything, but redirects are the
+    // most common case of sending empty bodies. We can't check it directly because these are streams.
+    // The side effect is that responses which do contain data will not be streamed to the client,
+    // but that's fine for redirects.
+    // TODO: Remove once a fix has been rolled out.
+    if ((response.status > 300 && response.status < 400) || response.status >= 500) {
+      const body = await response.text()
+      span.end()
+      return new Response(body || null, response)
+    }
+
+    const keepOpenUntilNextFullyRendered = new TransformStream({
+      flush() {
+        // it's important to keep the stream open until the next handler has finished,
+        // or otherwise the cache revalidates might not go through
+        return nextHandlerPromise.then(() => {
+          span.end()
+        })
+      },
+    })
 
-  const keepOpenUntilNextFullyRendered = new TransformStream({
-    flush() {
-      // it's important to keep the stream open until the next handler has finished,
-      // or otherwise the cache revalidates might not go through
-      return nextHandlerPromise
-    },
+    return new Response(response.body?.pipeThrough(keepOpenUntilNextFullyRendered), response)
   })
-
-  return new Response(response.body?.pipeThrough(keepOpenUntilNextFullyRendered), response)
 }

src/run/headers.ts

@@ -1,4 +1,5 @@
 import { getDeployStore } from '@netlify/blobs'
+import type { Span, Tracer } from '@opentelemetry/api'
 import type { NextConfigComplete } from 'next/dist/server/config-shared.js'
 
 import { encodeBlobKey } from '../shared/blobkey.js'
@@ -81,17 +82,42 @@ export const setVaryHeaders = (
  * By default, Next.js sets the date header to the current time, even if it's served
  * from the cache, meaning that the CDN will cache it for 10 seconds, which is incorrect.
  */
-export const adjustDateHeader = async (headers: Headers, request: Request) => {
+export const adjustDateHeader = async (
+  headers: Headers,
+  request: Request,
+  span: Span,
+  tracer: Tracer,
+) => {
   const cacheState = headers.get('x-nextjs-cache')
   const isServedFromCache = cacheState === 'HIT' || cacheState === 'STALE'
+
+  span.setAttributes({
+    'x-nextjs-cache': cacheState ?? undefined,
+    isServedFromCache,
+  })
+
   if (!isServedFromCache) {
     return
   }
-  const path = new URL(request.url).pathname
-  const key = await encodeBlobKey(path)
+  const key = new URL(request.url).pathname
+  const blobKey = await encodeBlobKey(key)
   const blobStore = getDeployStore()
+
   // TODO: use metadata for this
-  const { lastModified } = (await blobStore.get(key, { type: 'json' })) ?? {}
+  const { lastModified } = await tracer.startActiveSpan(
+    'get cache to calculate date header',
+    async (getBlobForDateSpan) => {
+      getBlobForDateSpan.setAttributes({
+        key,
+        blobKey,
+      })
+      const blob = (await blobStore.get(blobKey, { type: 'json' })) ?? {}
+
+      getBlobForDateSpan.addEvent(blob ? 'Cache hit' : 'Cache miss')
+      getBlobForDateSpan.end()
+      return blob
+    },
+  )
 
   if (!lastModified) {
     return
@@ -142,7 +168,7 @@ export const setCacheTagsHeaders = (headers: Headers, request: Request, manifest
  */
 const NEXT_CACHE_TO_CACHE_STATUS: Record<string, string> = {
   HIT: `hit`,
-  MISS: `miss,`,
+  MISS: `fwd=miss`,
   STALE: `hit; fwd=stale`,
 }
 

tests/e2e/simple-app.test.ts

@@ -58,7 +58,7 @@ test('next/image is using Netlify Image CDN', async ({ page }) => {
 const waitFor = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms))
 
 // adaptation of https://github.com/vercel/next.js/blob/canary/test/e2e/app-dir/app-static/app-static.test.ts#L1716-L1755
-test('should stream properly', async ({ page }) => {
+test('streams stale responses', async ({ page }) => {
   // Prime the cache.
   const path = `${ctx.url}/stale-cache-serving/app-page`
   const res = await fetch(path)
@@ -99,6 +99,9 @@ test('should stream properly', async ({ page }) => {
       )
     })
 
-    expect(timings.startedStreaming - timings.start, `streams in less than 3s, run #${i}/6`).toBeLessThan(3000)
+    expect(
+      timings.startedStreaming - timings.start,
+      `streams in less than 3s, run #${i}/6`,
+    ).toBeLessThan(3000)
   }
 })

tests/integration/cache-handler.test.ts

@@ -205,7 +205,7 @@ describe('app router', () => {
     expect(load(post3.body)('h1').text()).toBe('Revalidate Fetch')
     expect(post3.headers, 'a cache miss on a non prerendered page').toEqual(
       expect.objectContaining({
-        'cache-status': expect.stringMatching(/"Next.js"; miss/),
+        'cache-status': '"Next.js"; fwd=miss',
       }),
     )
 

tests/integration/revalidate-path.test.ts

@@ -75,13 +75,13 @@ test<FixtureTestContext>('should revalidate a route by path', async (ctx) => {
   expect(load(post2.body)('h1').text()).toBe('Hello, Statically fetched show 1')
   expect(post2.headers, 'a cache miss on the on demand revalidated path /1').toEqual(
     expect.objectContaining({
-      'cache-status': expect.stringMatching(/"Next.js"; miss/),
+      'cache-status': '"Next.js"; fwd=miss',
       'netlify-cdn-cache-control': 's-maxage=31536000, stale-while-revalidate=31536000',
     }),
   )
   expect(post2Route2.headers, 'a cache miss on the on demand revalidated path /2').toEqual(
     expect.objectContaining({
-      'cache-status': expect.stringMatching(/"Next.js"; miss/),
+      'cache-status': '"Next.js"; fwd=miss',
       'netlify-cdn-cache-control': 's-maxage=31536000, stale-while-revalidate=31536000',
     }),
   )

tests/integration/revalidate-tags.test.ts

@@ -57,7 +57,7 @@ test<FixtureTestContext>('should revalidate a route by tag', async (ctx) => {
   expect(load(post2.body)('h1').text()).toBe('Hello, Static Fetch 1')
   expect(post2.headers, 'a cache miss on the on demand revalidated page').toEqual(
     expect.objectContaining({
-      'cache-status': expect.stringMatching(/"Next.js"; miss/),
+      'cache-status': '"Next.js"; fwd=miss',
       'netlify-cdn-cache-control': 's-maxage=31536000, stale-while-revalidate=31536000',
     }),
   )