feat: add system logging to middleware handler (#174)

* feat: add system logging to middleware handler

* chore: remove log line

* chore: add docs for system logging

* chore: expand README

* chore: remove docs from README

Author: eduardoboucas

README.md

@@ -17,8 +17,11 @@ How to add new integration test scenarios to the application:
 4. Add your test
 
 > Currently the tests require a built version of the `dist/run/handlers/cache.cjs` so you need to
-> run `npm run build` before executing the integration tests. In addition, the integration tests
-> need to be prepared before first use. You can do this by running `npm run pretest`.
+> run `npm run build` before executing the integration tests.
+
+In addition, the integration tests need to be prepared before first use. You can do this by running
+`npm run pretest`. To speed up this process and build only the fixtures whose name starts with a
+given prefix, run `npm run pretest -- <prefix>`.
 
 ### E2E testing
 

edge-runtime/lib/headers.ts

@@ -1,3 +1,8 @@
+export const InternalHeaders = {
+  NFDebugLogging: 'x-nf-debug-logging',
+  NFRequestID: 'x-nf-request-id',
+}
+
 // Next 13 supports request header mutations and has the side effect of prepending header values with 'x-middleware-request'
 // as part of invoking NextResponse.next() in the middleware. We need to remove that before sending the response the user
 // as the code that removes it in Next isn't run based on how we handle the middleware

edge-runtime/lib/logging.ts

@@ -0,0 +1,5 @@
+export {
+  logger,
+  LogLevel,
+  StructuredLogger,
+} from '../vendor/v1-7-0--edge-utils.netlify.app/logger/mod.ts'

edge-runtime/lib/response.ts

@@ -2,6 +2,7 @@ import type { Context } from '@netlify/edge-functions'
 import { HTMLRewriter } from '../vendor/deno.land/x/[email protected]/index.ts'
 
 import { updateModifiedHeaders } from './headers.ts'
+import type { StructuredLogger } from './logging.ts'
 import { normalizeDataUrl, relativizeURL } from './util.ts'
 import { addMiddlewareHeaders, isMiddlewareRequest, isMiddlewareResponse } from './middleware.ts'
 
@@ -10,15 +11,18 @@ export interface FetchEventResult {
   waitUntil: Promise<any>
 }
 
-export const buildResponse = async ({
-  result,
-  request,
-  context,
-}: {
-  result: FetchEventResult
-  request: Request
+interface BuildResponseOptions {
   context: Context
-}) => {
+  logger: StructuredLogger
+  request: Request
+  result: FetchEventResult
+}
+
+export const buildResponse = async ({ context, logger, request, result }: BuildResponseOptions) => {
+  logger
+    .withFields({ is_nextresponse_next: result.response.headers.has('x-middleware-next') })
+    .debug('Building Next.js response')
+
   updateModifiedHeaders(request.headers, result.response.headers)
 
   // They've returned the MiddlewareRequest directly, so we'll call `next()` for them.
@@ -102,6 +106,8 @@ export const buildResponse = async ({
   const isDataReq = request.headers.get('x-nextjs-data')
 
   if (rewrite) {
+    logger.withFields({ rewrite_url: rewrite }).debug('Is rewrite')
+
     const rewriteUrl = new URL(rewrite, request.url)
     const baseUrl = new URL(request.url)
     const relativeUrl = relativizeURL(rewrite, request.url)
@@ -142,5 +148,6 @@ export const buildResponse = async ({
     res.headers.delete('x-middleware-next')
     return addMiddlewareHeaders(context.next(), res)
   }
+
   return res
 }

edge-runtime/middleware.ts

@@ -2,6 +2,8 @@ import type { Context } from '@netlify/edge-functions'
 
 import matchers from './matchers.json' assert { type: 'json' }
 
+import { InternalHeaders } from './lib/headers.ts'
+import { logger, LogLevel } from './lib/logging.ts'
 import { buildNextRequest, RequestData } from './lib/next-request.ts'
 import { buildResponse } from './lib/response.ts'
 import { FetchEventResult } from './lib/response.ts'
@@ -31,18 +33,26 @@ export async function handleMiddleware(
 ) {
   const nextRequest = buildNextRequest(request, context)
   const url = new URL(request.url)
+  const reqLogger = logger
+    .withLogLevel(
+      request.headers.has(InternalHeaders.NFDebugLogging) ? LogLevel.Debug : LogLevel.Log,
+    )
+    .withFields({ url_path: url.pathname })
+    .withRequestID(request.headers.get(InternalHeaders.NFRequestID))
 
   // While we have already checked the path when mapping to the edge function,
   // Next.js supports extra rules that we need to check here too, because we
   // might be running an edge function for a path we should not. If we find
   // that's the case, short-circuit the execution.
   if (!matchesMiddleware(url.pathname, request, searchParamsToUrlQuery(url.searchParams))) {
+    reqLogger.debug('Aborting middleware due to runtime rules')
+
     return
   }
 
   try {
     const result = await nextHandler({ request: nextRequest })
-    const response = await buildResponse({ result, request: request, context })
+    const response = await buildResponse({ context, logger: reqLogger, request, result })
 
     return response
   } catch (error) {

edge-runtime/vendor.ts

@@ -16,3 +16,5 @@ import 'https://deno.land/x/[email protected]/index.ts'
 
 import 'https://esm.sh/v91/[email protected]/deno/dist/server/web/spec-extension/request.js'
 import 'https://esm.sh/v91/[email protected]/deno/dist/server/web/spec-extension/response.js'
+
+import 'https://v1-7-0--edge-utils.netlify.app/logger/mod.ts'