add manual and automatic backend loggers (#54372)

Co-authored-by: Kevin Heis <[email protected]>

Author: Ebonsignori

next.config.js

@@ -2,6 +2,8 @@ import fs from 'fs'
 import path from 'path'
 
 import frontmatter from 'gray-matter'
+import { getLogLevelNumber } from '#src/observability/logger/lib/log-levels.js'
+
 // Replace imports with hardcoded values
 const ROOT = process.env.ROOT || '.'
 
@@ -35,6 +37,9 @@ export default {
       'mixed-decls',
     ],
   },
+  // Don't use automatic Next.js logging in dev unless the log level is `debug` or higher
+  // See `src/observability/logger/README.md` for log levels
+  logging: getLogLevelNumber() < 3 ? false : {},
   async rewrites() {
     const DEFAULT_VERSION = 'free-pro-team@latest'
     return productIds.map((productId) => {
@@ -47,7 +52,7 @@ export default {
   webpack: (config) => {
     config.experiments = config.experiments || {}
     config.experiments.topLevelAwait = true
-    config.resolve.fallback = { fs: false }
+    config.resolve.fallback = { fs: false, async_hooks: false }
     return config
   },
 

package-lock.json

@@ -306,7 +306,6 @@
     "mdast-util-to-hast": "^13.2.0",
     "mdast-util-to-markdown": "2.1.2",
     "mdast-util-to-string": "^4.0.0",
-    "morgan": "^1.10.1",
     "next": "^15.3.3",
     "ora": "^8.0.1",
     "parse5": "7.1.2",
@@ -361,7 +360,6 @@
     "@types/lodash": "^4.17.16",
     "@types/lodash-es": "4.17.12",
     "@types/mdast": "^4.0.4",
-    "@types/morgan": "1.9.9",
     "@types/react": "18.3.20",
     "@types/react-dom": "^18.3.6",
     "@types/semver": "^7.5.8",

package.json

@@ -1,6 +1,9 @@
 import statsd from '@/observability/lib/statsd'
 import { loadUnversionedTree, loadSiteTree, loadPages, loadPageMap } from './page-data'
 import loadRedirects from '@/redirects/lib/precompile'
+import { createLogger } from '@/observability/logger'
+
+const logger = createLogger(import.meta.url)
 
 // Instrument these functions so that
 // it's wrapped in a timer that reports to Datadog
@@ -19,12 +22,9 @@ let promisedWarmServer: any
 async function warmServer(languagesOnly = []) {
   const startTime = Date.now()
 
-  if (process.env.NODE_ENV !== 'test') {
-    console.log(
-      'Priming context information...',
-      languagesOnly && languagesOnly.length ? `${languagesOnly.join(',')} only` : '',
-    )
-  }
+  logger.debug(
+    `Priming context information...${languagesOnly && languagesOnly.length ? ` ${languagesOnly.join(',')} only` : ''}`,
+  )
 
   const unversionedTree = await dog.loadUnversionedTree(languagesOnly)
   const siteTree = await dog.loadSiteTree(unversionedTree, languagesOnly)
@@ -34,9 +34,7 @@ async function warmServer(languagesOnly = []) {
 
   statsd.gauge('memory_heap_used', process.memoryUsage().heapUsed, ['event:warm-server'])
 
-  if (process.env.NODE_ENV !== 'test') {
-    console.log(`Context primed in ${Date.now() - startTime} ms`)
-  }
+  logger.debug(`Context primed in ${Date.now() - startTime} ms`)
 
   return {
     pages: pageMap,

src/frame/lib/warm-server.ts

@@ -17,6 +17,7 @@ import productNames from '@/products/lib/product-names'
 import warmServer from '@/frame/lib/warm-server'
 import nonEnterpriseDefaultVersion from '@/versions/lib/non-enterprise-default-version'
 import { getDataByLanguage, getUIDataMerged } from '@/data-directory/lib/get-data'
+import { updateLoggerContext } from '@/observability/logger/lib/logger-context'
 
 // This doesn't change just because the request changes, so compute it once.
 const enterpriseServerVersions = Object.keys(allVersions).filter((version) =>
@@ -107,5 +108,10 @@ export default async function contextualize(
     }
   }
 
+  updateLoggerContext({
+    version: req.context.currentVersion,
+    pagePath: req.pagePath,
+  })
+
   return next()
 }

src/frame/middleware/context/context.ts

@@ -7,7 +7,6 @@ import timeout from 'connect-timeout'
 
 import { haltOnDroppedConnection } from './halt-on-dropped-connection'
 import abort from './abort'
-import morgan from 'morgan'
 import helmet from './helmet'
 import cookieParser from './cookie-parser'
 import {
@@ -64,17 +63,12 @@ import dynamicAssets from '@/assets/middleware/dynamic-assets'
 import generalSearchMiddleware from '@/search/middleware/general-search-middleware'
 import shielding from '@/shielding/middleware'
 import { MAX_REQUEST_TIMEOUT } from '@/frame/lib/constants'
+import { initLoggerContext } from '@/observability/logger/lib/logger-context'
+import { getAutomaticRequestLogger } from '@/observability/logger/middleware/get-automatic-request-logger'
 
 const { NODE_ENV } = process.env
 const isTest = NODE_ENV === 'test' || process.env.GITHUB_ACTIONS === 'true'
 
-// By default, logging each request (with morgan), is on. And by default
-// it's off if you're in a production environment or running automated tests.
-// But if you set the env var, that takes precedence.
-const ENABLE_DEV_LOGGING = Boolean(
-  process.env.ENABLE_DEV_LOGGING ? JSON.parse(process.env.ENABLE_DEV_LOGGING) : !isTest,
-)
-
 const ENABLE_FASTLY_TESTING = JSON.parse(process.env.ENABLE_FASTLY_TESTING || 'false')
 
 // Catch unhandled promise rejections and passing them to Express's error handler
@@ -104,10 +98,9 @@ export default function (app: Express) {
   //
   app.set('trust proxy', true)
 
-  // *** Request logging ***
-  if (ENABLE_DEV_LOGGING) {
-    app.use(morgan('dev'))
-  }
+  // *** Logging ***
+  app.use(initLoggerContext) // Context for both inline logs (e.g. logger.info) and automatic logs
+  app.use(getAutomaticRequestLogger()) // Automatic logging for all requests e.g. "GET /path 200"
 
   // Put this early to make it as fast as possible because it's used
   // to check the health of each cluster.

src/frame/middleware/index.ts

@@ -1,7 +1,10 @@
 import { main } from './start-server'
+import { createLogger } from '@/observability/logger'
+
+const logger = createLogger(import.meta.url)
 
 try {
   await main()
 } catch (error) {
-  console.error(error)
+  logger.error('Uncaught top-level error', { error })
 }

src/frame/server.ts

@@ -5,6 +5,7 @@ import type { Language as parserLanguage } from 'accept-language-parser'
 import languages, { languageKeys } from '@/languages/lib/languages'
 import { USER_LANGUAGE_COOKIE_NAME } from '@/frame/lib/constants'
 import type { ExtendedRequest, Languages } from '@/types'
+import { updateLoggerContext } from '@/observability/logger/lib/logger-context'
 
 const chineseRegions = [
   'CN', // Mainland
@@ -70,5 +71,9 @@ export default function detectLanguage(req: ExtendedRequest, res: Response, next
   if (!req.userLanguage) {
     req.userLanguage = getLanguageCodeFromHeader(req)
   }
+  updateLoggerContext({
+    language: req.language,
+    userLanguage: req.userLanguage,
+  })
   return next()
 }

src/languages/middleware/detect-language.ts

@@ -1,7 +1,11 @@
 # Observability
 
-Observability, for lack of simpler term, is our ability to collect data about how the Docs operates. These tools allow us to monitor the health of our systems, catch any errors, and get paged if a system stops working. 
+Observability, for lack of simpler term, is our ability to collect data about how the Docs operates. These tools allow us to monitor the health of our systems, catch any errors, and get paged if a system stops working.
 
 In this directory we have files that connect us to our observability tools, as well as high-level error handling that helps keep our systems resilient.
 
 We collect data in our observability systems to track the health of the Docs systems, not to track user behaviors. User behavior data collection is under the `src/events` directory.
+
+## Logging
+
+Please see the [logger README](./logger/README.md).

src/observability/README.md

@@ -1,5 +1,6 @@
 import got, { type OptionsOfTextResponseBody, type Method } from 'got'
 import { Failbot, HTTPBackend } from '@github/failbot'
+import { getLoggerContext } from '@/observability/logger/lib/logger-context'
 
 const HAYSTACK_APP = 'docs'
 
@@ -62,7 +63,15 @@ export function report(error: Error, metadata?: Record<string, unknown>) {
     backends,
   })
 
-  return failbot.report(error, metadata)
+  // Add the request id from the logger context to the metadata
+  // Per https://github.com/github/failbotg/blob/main/docs/api.md#additional-data
+  // Metadata can only be a flat object with string & number values, so only add the requestUuid
+  const loggerContext = getLoggerContext()
+
+  return failbot.report(error, {
+    ...metadata,
+    requestUuid: loggerContext.requestUuid || 'unknown',
+  })
 }
 
 // Kept for legacy so you can continue to do: