Restructuring log middleware

.gitignore

@@ -1,3 +1,4 @@
 coverage
 dist
 node_modules
+.eslintcache

README.md

@@ -12,21 +12,18 @@ Here is an example server with log tracing enabled.
 
 ```js
 import {
-  fetchGcpProjectId,
   getHttpTraceHeader,
   middleware,
-  logger as BNLogger
+  logger as buildLogger
 } from "@bonniernews/logger";
 import express from "express";
 
-const logger = BNLogger();
+const logger = buildLogger();
 const app = express();
 
-app.use(middleware);
-
-// Fetches the project ID from the GCP metadata server in the background on startup.
-// This is only necessary if you don't set the `GCP_PROJECT` environment variable.
-fetchGcpProjectId();
+// This middleware will create a request context and
+// automatically decorate all logs with tracing data:
+app.use(middleware());
 
 app.get("/", async (req, res) => {
   logger.info("Hello, world!");
@@ -39,6 +36,12 @@ app.get("/", async (req, res) => {
 });
 ```
 
+The `middleware` should be put as early as possible, since only logs after this middleware will get the tracing data. The middleware will lookup the active project ID from GCP. Alternatively, you can set the `GCP_PROJECT` environment variable for this purpose.
+
+Use the `getHttpTraceHeader` function to pass tracing headers to downstream services.
+
+If you want to decorate logs with custom data, use the exported `decorateLogs` function. In order to use this, the middleware needs to be installed first.
+
 ### Logger Interface
 
 #### Options

index.ts

@@ -1,5 +1,4 @@
-export { fetchGcpProjectId } from "./lib/gcp";
 export { getHttpTraceHeader } from "./lib/http";
-export { getLoggingTraceData, logger } from "./lib/logging";
+export { decorateLogs, logger, Logger, LoggerOptions, DestinationStream } from "./lib/logging";
 export { middleware } from "./lib/middleware";
 export { createTraceparent } from "./lib/traceparent";

lib/gcp.ts

@@ -1,26 +1,17 @@
 import gcpMetaData from "gcp-metadata";
 
-let gcpProjectId: string | undefined = undefined;
-
-export function getGcpProjectId() {
-  return process.env.GCP_PROJECT || gcpProjectId;
-}
-
 /**
  * Fetches the Google Cloud Platform (GCP) project ID from the GCP metadata server.
  *
- * You only need to call this function if you're not setting the `GCP_PROJECT` environment variable.
+ * You can alternatively set the `GCP_PROJECT` environment variable, which takes precedence.
  */
-export async function fetchGcpProjectId() {
+export async function getGcpProjectId(): Promise<string | undefined> {
+  if (process.env.GCP_PROJECT) {
+    return process.env.GCP_PROJECT;
+  }
+
   const isAvailable = await gcpMetaData.isAvailable();
   if (!isAvailable) return;
 
-  gcpProjectId = await gcpMetaData.project("project-id");
-}
-
-/**
- * Resets the GCP project ID, for testing.
- */
-export function reset() {
-  gcpProjectId = undefined;
+  return await gcpMetaData.project("project-id");
 }

lib/http.ts

@@ -1,7 +1,6 @@
 import { getStore } from "./middleware";
 
-export function getHttpTraceHeader() {
-  const { traceparent } = getStore();
-  if (traceparent) return { traceparent };
-  return {};
+export function getHttpTraceHeader(): Record<string, string> {
+  const { traceparent } = getStore() || {};
+  return traceparent ? { traceparent } : {};
 }

lib/logging.ts

@@ -1,34 +1,39 @@
-import pino, { DestinationStream, LoggerOptions } from "pino";
-import { getGcpProjectId } from "./gcp";
+import pino, {
+  DestinationStream as PinoDestinationStream,
+  LoggerOptions as PinoOptions,
+  Logger as PinoLogger,
+} from "pino";
 import { getStore } from "./middleware";
-import { getTraceFromTraceparent } from "./traceparent";
 
-export function getLoggingTraceData() {
-  const { traceparent, ...rest } = getStore();
-  if (!traceparent) return rest;
-
-  const trace = getTraceFromTraceparent(traceparent);
-  if (!trace) return rest;
+function getLoggingData() {
+  const store = getStore();
+  return store ? store.logFields : {};
+}
 
-  const logData = { traceId: trace.traceId, spanId: trace.parentId, ...rest };
+/**
+ * Add any additional log data to the request context. To use this feature, you must enable the
+ * request storage by initializing the built-in middleware.
+ */
+export function decorateLogs(obj: Record<string, unknown>) {
+  const store = getStore();
 
-  const gcpProjectId = getGcpProjectId();
-  if (!gcpProjectId) return logData;
+  if (!store) throw new Error("@bonniernews/logger middleware has not been initialized");
 
-  return {
-    ...logData,
-    "logging.googleapis.com/trace": `projects/${gcpProjectId}/traces/${trace.traceId}`,
-    "logging.googleapis.com/spanId": trace.parentId,
-    "logging.googleapis.com/trace_sampled": trace.isSampled,
-  };
+  for (const key in obj) {
+    store.logFields[key] = obj[key];
+  }
 }
 
-type BnLoggerOptions = Omit<LoggerOptions, "level" | "formatters"> & {
+export type Logger = PinoLogger<never, boolean>;
+
+export type LoggerOptions = Omit<PinoOptions, "level" | "formatters"> & {
   logLevel?: "trace" | "debug" | "info" | "warn" | "error" | "fatal";
-  formatLog?: NonNullable<LoggerOptions["formatters"]>["log"];
+  formatLog?: NonNullable<PinoOptions["formatters"]>["log"];
 };
 
-export function logger(options: BnLoggerOptions = {}, stream?: DestinationStream | undefined) {
+export type DestinationStream = PinoDestinationStream;
+
+export function logger(options: LoggerOptions = {}, stream?: DestinationStream | undefined): Logger {
   const env = process.env.NODE_ENV /* c8 ignore next */ || "development";
   const shouldPrettyPrint = ["development", "test", "dev"].includes(env) && !stream;
 
@@ -68,7 +73,7 @@ export function logger(options: BnLoggerOptions = {}, stream?: DestinationStream
         ...(formatLog && { log: formatLog }),
       },
       transport,
-      mixin: (...args) => ({ ...getLoggingTraceData(), ...mixin?.(...args) }),
+      mixin: (...args) => ({ ...getLoggingData(), ...mixin?.(...args) }),
       ...rest,
     },
     stream

lib/middleware.ts

@@ -1,23 +1,57 @@
 import type { RequestHandler } from "express";
 import { AsyncLocalStorage } from "node:async_hooks";
-import { createTraceparent } from "./traceparent";
+import { getGcpProjectId } from "./gcp";
+import { getTraceFromTraceparent, createTraceparent } from "./traceparent";
 
-type Store = {
-  traceparent?: string;
-  clientServiceAccount?: string;
+type LogFields = {
+  traceId?: string;
+  spanId?: string;
+  "logging.googleapis.com/trace"?: string;
+  "logging.googleapis.com/spanId"?: string;
+  "logging.googleapis.com/trace_sampled"?: boolean;
   [key: string]: unknown;
 };
 
+export type Store = {
+  traceparent?: string;
+  logFields: LogFields;
+};
+
+export type Middleware = () => RequestHandler;
+
 const storage = new AsyncLocalStorage<Store>();
 
-export const middleware: RequestHandler = (req, _res, next) => {
-  const traceparent = req.header("traceparent") || createTraceparent();
+export const middleware: Middleware = () => {
+  let initialized = false;
+  let projectId: string | undefined;
+
+  return async (req, _res, next) => {
+    if (!initialized) {
+      initialized = true;
+      projectId = await getGcpProjectId();
+    }
+
+    const traceparent = req.header("traceparent") || createTraceparent();
+    const trace = getTraceFromTraceparent(traceparent);
+    const logFields: LogFields = {};
+
+    if (trace) {
+      logFields.traceId = trace.traceId;
+      logFields.spanId = trace.parentId;
+
+      if (projectId) {
+        logFields["logging.googleapis.com/trace"] = `projects/${projectId}/traces/${trace.traceId}`;
+        logFields["logging.googleapis.com/spanId"] = trace.parentId;
+        logFields["logging.googleapis.com/trace_sampled"] = trace.isSampled;
+      }
+    }
 
-  storage.run({ traceparent }, () => {
-    next();
-  });
+    storage.run({ traceparent, logFields }, () => {
+      next();
+    });
+  };
 };
 
-export function getStore() {
-  return storage.getStore() || {};
+export function getStore(): Store | undefined {
+  return storage.getStore();
 }