Add structured logging to aid debugging of future outages (#60346)

Author: Ebonsignori

src/archives/middleware/archived-enterprise-versions-assets.ts

@@ -6,6 +6,9 @@ import { isArchivedVersion } from '@/archives/lib/is-archived-version'
 import { setFastlySurrogateKey, SURROGATE_ENUMS } from '@/frame/middleware/set-fastly-surrogate-key'
 import { archivedCacheControl, defaultCacheControl } from '@/frame/middleware/cache-control'
 import type { ExtendedRequest } from '@/types'
+import { createLogger } from '@/observability/logger'
+
+const logger = createLogger(import.meta.url)
 
 // This module handles requests for the CSS and JS assets for
 // deprecated GitHub Enterprise versions by routing them to static content in
@@ -127,6 +130,11 @@ export default async function archivedEnterpriseVersionsAssets(
       throw err
     }
 
+    logger.warn('Failed to proxy archived enterprise asset', {
+      url: proxyPath,
+      error: err instanceof Error ? err : new Error(String(err)),
+    })
+
     // It's important that we don't give up on this by returning a 404
     // here. It's better to let this through in case the asset exists
     // beyond the realm of archived enterprise versions.

src/archives/middleware/archived-enterprise-versions.ts

@@ -120,15 +120,24 @@ export default async function archivedEnterpriseVersions(
       return res.safeRedirect(redirectCode, redirectTo)
     }
 
-    const redirectJson = (await getRemoteJSON(getProxyPath('redirects.json', requestedVersion), {
-      retry: retryConfiguration,
-      // This is allowed to be different compared to the other requests
-      // we make because downloading the `redirects.json` once is very
-      // useful because it caches so well.
-      // And, as of 2021 that `redirects.json` is 10MB so it's more likely
-      // to time out.
-      timeout: { response: 1000 },
-    })) as Record<string, string>
+    let redirectJson: Record<string, string>
+    try {
+      redirectJson = (await getRemoteJSON(getProxyPath('redirects.json', requestedVersion), {
+        retry: retryConfiguration,
+        // This is allowed to be different compared to the other requests
+        // we make because downloading the `redirects.json` once is very
+        // useful because it caches so well.
+        // And, as of 2021 that `redirects.json` is 10MB so it's more likely
+        // to time out.
+        timeout: { response: 1000 },
+      })) as Record<string, string>
+    } catch (err) {
+      logger.error('Failed to fetch archived redirects.json', {
+        version: requestedVersion,
+        error: err instanceof Error ? err : new Error(String(err)),
+      })
+      throw err
+    }
     if (!req.context) throw new Error('No context on request')
     const [language, withoutLanguage] = splitPathByLanguage(req.path, req.context.userLanguage)
     const newRedirectTo = redirectJson[withoutLanguage]
@@ -179,15 +188,24 @@ export default async function archivedEnterpriseVersions(
     versionSatisfiesRange(requestedVersion, `>${lastVersionWithoutArchivedRedirectsFile}`) &&
     !deprecatedWithFunctionalRedirects.includes(requestedVersion)
   ) {
-    const redirectJson = (await getRemoteJSON(getProxyPath('redirects.json', requestedVersion), {
-      retry: retryConfiguration,
-      // This is allowed to be different compared to the other requests
-      // we make because downloading the `redirects.json` once is very
-      // useful because it caches so well.
-      // And, as of 2021 that `redirects.json` is 10MB so it's more likely
-      // to time out.
-      timeout: { response: 1000 },
-    })) as Record<string, string>
+    let redirectJson: Record<string, string>
+    try {
+      redirectJson = (await getRemoteJSON(getProxyPath('redirects.json', requestedVersion), {
+        retry: retryConfiguration,
+        // This is allowed to be different compared to the other requests
+        // we make because downloading the `redirects.json` once is very
+        // useful because it caches so well.
+        // And, as of 2021 that `redirects.json` is 10MB so it's more likely
+        // to time out.
+        timeout: { response: 1000 },
+      })) as Record<string, string>
+    } catch (err) {
+      logger.error('Failed to fetch archived redirects.json', {
+        version: requestedVersion,
+        error: err instanceof Error ? err : new Error(String(err)),
+      })
+      throw err
+    }
 
     // make redirects found via redirects.json redirect with a 301
     if (redirectJson[req.path]) {
@@ -230,12 +248,20 @@ export default async function archivedEnterpriseVersions(
 
   // Log errors for non-200 responses to help identify issues with archived content
   if (r.status !== 200) {
+    let upstreamBody: string | undefined
+    try {
+      upstreamBody = await r.text()
+    } catch {
+      // ignore — body reading failure shouldn't affect error handling
+    }
     logger.error('Failed to fetch archived enterprise content', {
       version: requestedVersion,
       path: req.path,
       status: r.status,
+      statusText: r.statusText,
       responseTime: `${responseTime}ms`,
       url: getProxyPath(req.path, requestedVersion),
+      upstreamBody: upstreamBody?.slice(0, 500),
     })
   }
 

src/frame/start-server.ts

@@ -7,11 +7,14 @@ import { checkNodeVersion } from './lib/check-node-version'
 import '../observability/lib/handle-exceptions'
 import createApp from './lib/app'
 import warmServer from './lib/warm-server'
+import { createLogger } from '@/observability/logger'
 
 dotenv.config()
 
 checkNodeVersion()
 
+const logger = createLogger(import.meta.url)
+
 const { PORT, NODE_ENV } = process.env
 const port = Number(PORT) || 4000
 
@@ -52,7 +55,16 @@ async function startServer() {
   // Workaround for https://github.com/expressjs/express/issues/1101
   const server = http.createServer(app)
 
+  process.once('SIGTERM', () => {
+    logger.info('Received SIGTERM, beginning graceful shutdown', { pid: process.pid, port })
+    server.close(() => {
+      logger.info('HTTP server closed')
+    })
+  })
+
   return server
-    .listen(port, () => console.log(`app running on http://localhost:${port}`))
+    .listen(port, () =>
+      logger.info('Server started', { port, pid: process.pid, nodeEnv: process.env.NODE_ENV }),
+    )
     .on('error', () => server.close())
 }

src/observability/lib/handle-exceptions.ts

@@ -1,25 +1,37 @@
 import FailBot from './failbot'
+import { createLogger } from '@/observability/logger'
+
+const logger = createLogger(import.meta.url)
+
+// Safely convert an unknown thrown value to an Error, avoiding JSON.stringify
+// which can throw on circular references.
+function toError(value: Error | unknown): Error {
+  if (value instanceof Error) return value
+  try {
+    return new Error(JSON.stringify(value))
+  } catch {
+    return new Error(String(value))
+  }
+}
 
 process.on('uncaughtException', async (err: Error | unknown) => {
-  console.error(err)
+  const error = toError(err)
+  logger.error('uncaughtException', { error })
   try {
-    // Type guard to ensure we have an Error object for FailBot
-    const error = err instanceof Error ? err : new Error(JSON.stringify(err))
     FailBot.report(error)
   } catch (failBotError) {
-    console.warn('Even sending the uncaughtException error to FailBot failed!')
-    console.error(failBotError)
+    logger.warn('Even sending the uncaughtException error to FailBot failed!')
+    logger.error('Failed to report uncaughtException to FailBot', { error: toError(failBotError) })
   }
 })
 
 process.on('unhandledRejection', async (err: Error | unknown) => {
-  console.error(err)
+  const error = toError(err)
+  logger.error('unhandledRejection', { error })
   try {
-    // Type guard to ensure we have an Error object for FailBot
-    const error = err instanceof Error ? err : new Error(JSON.stringify(err))
     FailBot.report(error)
   } catch (failBotError) {
-    console.warn('Even sending the unhandledRejection error to FailBot failed!')
-    console.error(failBotError)
+    logger.warn('Even sending the unhandledRejection error to FailBot failed!')
+    logger.error('Failed to report unhandledRejection to FailBot', { error: toError(failBotError) })
   }
 })

src/observability/logger/index.ts

@@ -10,6 +10,10 @@ import { POD_IDENTITY } from '@/observability/logger/lib/pod-identity'
 
 type IncludeContext = { [key: string]: unknown }
 
+// Read once at module startup so every log line carries the deployed version.
+// BUILD_SHA is baked into each Docker image via ARG/ENV in the Dockerfile.
+const BUILD_SHA = process.env.BUILD_SHA || undefined
+
 // Type definitions for logger methods with overloads
 interface LoggerMethod {
   // Pattern 1: Just a message e.g. `logger.info('Hello world')`
@@ -136,6 +140,7 @@ export function createLogger(filePath: string) {
         ...loggerContext, // requestUuid, path, method, headers, etc. (per-request)
         timestamp,
         level,
+        ...(BUILD_SHA !== undefined ? { build_sha: BUILD_SHA } : {}),
         file: path.relative(process.cwd(), new URL(filePath).pathname),
         message: finalMessage,
       }
@@ -146,6 +151,8 @@ export function createLogger(filePath: string) {
         if (typeof value === 'object' && value instanceof Error) {
           // Errors don't serialize well to JSON, so just log the message + stack trace
           includedContextWithFormattedError[key] = value.message
+          includedContextWithFormattedError[`${key}_code`] = (value as NodeJS.ErrnoException).code
+          includedContextWithFormattedError[`${key}_name`] = value.name
           includedContextWithFormattedError[`${key}_stack`] = value.stack
         } else {
           includedContextWithFormattedError[key] = value

src/observability/middleware/handle-errors.ts

@@ -7,6 +7,9 @@ import { setFastlySurrogateKey, SURROGATE_ENUMS } from '@/frame/middleware/set-f
 import { errorCacheControl } from '@/frame/middleware/cache-control'
 import statsd from '@/observability/lib/statsd'
 import { ExtendedRequest } from '@/types'
+import { createLogger } from '@/observability/logger'
+
+const logger = createLogger(import.meta.url)
 
 const DEBUG_MIDDLEWARE_TESTS = Boolean(JSON.parse(process.env.DEBUG_MIDDLEWARE_TESTS || 'false'))
 
@@ -29,6 +32,10 @@ function timedOut(req: ExtendedRequest) {
     incrementTags.push(`product:${req.context.currentCategory}`)
   }
   statsd.increment('middleware.timeout', 1, incrementTags)
+  logger.warn('Request timed out', {
+    path: req.pagePath || req.path,
+    method: req.method,
+  })
 }
 
 async function handleError(