Enable Request Bundling using asynchronous context tracking

[raman-nbg]

What would you like to see in the library?

This library provides an express middleware enabling request bundling. The library instantiates child loggers with trace/span IDs and makes it available under req.log for each request. This approach requires to pass the logger instance through all functions of your code and increases complexity.

An alternative approach could be to use asynchronous context tracking. The express middleware would need to call the downstream middlewares within the context of AsyncLocalStorage. With this, users of this library could simple create one global logger instance and make use of it. The logger instance will automatically add the trace/span IDs based on the current request context.

Describe alternatives you've considered

It is possible to do the implementation without the library. But for convenience it would be better to provide this functionality within this library.

Additional context/notes

I have implemented this with some tweaks. See below for my code. It could be easily adopted to be part of this library.

requestAwareLogger.ts

import { GoogleAuth } from 'google-auth-library';
import {
  LOGGING_SAMPLED_KEY,
  LOGGING_SPAN_KEY,
  LOGGING_TRACE_KEY,
  LoggingWinston
} from '@google-cloud/logging-winston';
import { HttpRequest, Log, middleware } from '@google-cloud/logging';
import { NextFunction, Request, Response } from 'express';
import winston from 'winston';
import { Handler } from 'express';
import { AsyncLocalStorage } from 'node:async_hooks';

export const createRequestAwareLogger = async <T>(
  logger: winston.Logger,
  asyncLocalStorage: AsyncLocalStorage<T>
): Promise<Handler[]> => {
  const traceBundleMiddlware: Handler = await createTraceBundleMiddlware(logger);
  const requestContextMiddleware: Handler = await createRequestContextMiddleware(asyncLocalStorage);

  return [traceBundleMiddlware, requestContextMiddleware];
};

const createTraceBundleMiddlware = async (logger: winston.Logger) => {
  const projectId = await new GoogleAuth().getProjectId();

  // This function will be invoked at the very end of a request and logs the http request and response
  const emitParentLogEntry = (
    httpRequest: HttpRequest,
    trace: string,
    span?: string,
    sampled?: boolean
  ) => {
    const cloudTransport = logger.transports.find((t) => t instanceof LoggingWinston);
    const requestLogName = Log.formatName_(projectId, `${cloudTransport?.common.logName}_reqlog`);

    logger.info(httpRequest.requestUrl || 'http request', {
      logName: requestLogName,
      [LOGGING_TRACE_KEY]: trace,
      [LOGGING_SPAN_KEY]: span,
      [LOGGING_SAMPLED_KEY]: sampled,
      httpRequest
    });
  };

  // This function is responsible to create an object (trace bundle) which will be used as the object for the local storage
  const createTraceBundle = (trace: string, span?: string, sampled?: boolean) => {
    return {
      [LOGGING_TRACE_KEY]: trace,
      [LOGGING_SPAN_KEY]: span,
      [LOGGING_SAMPLED_KEY]: sampled
    };
  };

  // This creates a middleware which create the trace bundle and makes it available under req.log
  return middleware.express.makeMiddleware(projectId, createTraceBundle, emitParentLogEntry);
};

// This middleware initiates the request context using the local storage.
// See https://nodejs.org/api/async_context.html
const createRequestContextMiddleware = <T>(asyncLocalStorage: AsyncLocalStorage<T>): Handler => {
  return (req: Request, res: Response, next: NextFunction) => {
    // eslint-disable-next-line @typescript-eslint/no-explicit-any
    const traceBundle = (req as any).log;

    // Run the next function within the scope of the async local storage.
    // With this, the remaining middlewares (and route handlers) can access
    // the the logger making use of the trace bundle.
    asyncLocalStorage.run(traceBundle, () => {
      next();
    });
  };
};

logger.ts

import { AsyncLocalStorage } from 'node:async_hooks';
import * as winston from 'winston';
import { LoggingWinston } from '@google-cloud/logging-winston';

export const asyncLocalStorage = new AsyncLocalStorage();

// Create a winston format to add the traceId information based on asyncLocalStorage
// This function will be run at each log entry.
// With this, all logs of a request will be bundled together.
const logBundleFormat = winston.format((transformableInfo: winston.Logform.TransformableInfo) => {
  // eslint-disable-next-line @typescript-eslint/no-explicit-any
  const store = asyncLocalStorage.getStore() as any;

  return {
    ...transformableInfo,
    ...store
  };
});

// Use Google's LoggingWinston transport to directly write logs to Cloud Logging without writing to stdout/console
const transports: winston.transport[] = [
  new LoggingWinston({
    maxEntrySize: 250000 // a little less than the maximum log message size of 256 kb
  })
];

const logger = winston.createLogger({
  transports: transports,
  format: winston.format.combine(logBundleFormat(), winston.format.json())
});

export default logger;

Now, the express app could look like this:

import express from 'express';
import logger, { asyncLocalStorage } from './logger.js';
import { createRequestAwareLogger } from './requestAwareLogger.js';

const app = express();

const requestAwareLogger = await createRequestAwareLogger(logger, asyncLocalStorage);
app.use(requestAwareLogger);

// all logs in the downstream middlewares have context awareness
app.use((req, res) => {
  logger.info("Yay, I am context aware!");
  logger.info("And I am as well - we will be logged in a bundle.");

  res.status(200).send();
})

// run server
const server = app.listen(3000, () => {
  logger.info(`Express.js server is running on port 3000`);
});

export default app;

[raman-nbg]

@cindy-peng, how can we proceed on this topic?