Simplifying GCP Log Bundling via Node Async Local Storage

Logs are critical in production environments, serving as a key resource for identifying and resolving issues. Often, they are the only clues available to debug live problems. Imagine a scenario where a software bug erroneously credits extra funds to customer accounts — a situation where you can’t simply “turn back time” to insert helpful debugging logs.

In one of our client projects at Symph, we have employed a way to neatly bundle these important log statements by request. We’ll go much deeper into this, but before that, you need to know the following:

• The express application, which is responsible for serving static files and API requests, is hosted on Google Cloud Platform’s App Engine standard environment.
• The Express application is running on Node.js V18.
• The application uses winston as the backbone of its logging implementation.
• The application logs are exported to GCP Cloud Logging via Google Cloud’s winston transport for Node JS.

Log Bundling

Log bundling is a technique that groups application logs by the requests that generate them. In practical terms, this means each log entry is directly associated with a specific user request. This is useful for us at a specific client project at Symph because oftentimes in that project, production investigations were done on a per-report basis. This meant that we often had to track the flow of how a problematic request of a specific user was handled by our application. This is very difficult to do without any sort of log grouping/filtering. Without log bundling, this is how Cloud Logging would look like:

As you can see, it’s hard to make sense of what’s happening. Which request is logging which application log? If we’re trying to identify a production bug by “going through” the logs, which logs should we trace? Cloud Logging acts as a log DUMP. For us to make maximum use of it, we’ll have to structure the logs so that we can apply powerful filters to them.

Winston -> Cloud Logging

Following Google’s recommendation for writing logs to Cloud Logging from App Engine, we used the winston logging library together with a custom Cloud Logging transport found here. This transport is what handles the structuring of our application logs into a standard format accepted by Cloud Logging. For our project, this transport was the key to log bundling. It had a middleware that handled the injection of a request-specific logger to the request object, which when used throughout the processing of a request, automatically takes care of bundling together all the application logs in Cloud Logging. Below is a sample usage of the middleware provided in the custom transport’s documentation.

const lw = require('@google-cloud/logging-winston');
const winston = require('winston');

// Import express module and create an http server.
const express = require('express');
const logger = winston.createLogger();

async function main() {
    // Create a middleware that will use the provided logger.
    // A Cloud Logging transport will be created automatically
    // and added onto the provided logger.
    const mw = await lw.express.makeMiddleware(logger);
    // Alternatively, you can construct a LoggingWinston transport
    // yourself and pass it int.
    // const transport = new LoggingWinston({...});
    // const mw = await lw.express.makeMiddleware(logger, transport);

    const app = express();

    // Install the logging middleware. This ensures that a Winston-style `log`
    // function is available on the `request` object. Attach this as one of the
    // earliest middleware to make sure that the log function is available in all
    // subsequent middleware and routes.
    app.use(mw);

    // Setup an http route and a route handler.
    app.get('/', (req, res) => {
        // `req.log` can be used as a winston style log method. All logs generated
        // using `req.log` use the current request context. That is, all logs
        // corresponding to a specific request will be bundled in the Cloud Logging
        // UI.
        req.log.info('this is an info log message');
        res.send('hello world');
    });

    // `logger` can be used as a global logger, one not correlated to any specific
    // request.
    logger.info('bonjour');

    // Start listening on the http server.
    app.listen(8080, () => {
        logger.info('http server listening on port 8080');
    });
}

main();

‍

To demonstrate the concepts discussed in this article without divulging any **confidential** data, I will walk you through a simple working example that models how we solved this “log bundling” problem for one of our client projects.

Approach 1

First, we initialized a custom winston logger. This is where we defined how we wanted our application logs to appear in Cloud logging.

const app = express();

const logger = winston.createLogger({
  transports: [new winston.transports.Console(), new lw.LoggingWinston()],
  level: "debug",

  format: winston.format.combine(
    winston.format.errors({ stack: true }),
    winston.format.colorize(),
    winston.format.printf((info) => {
      const logLines = [`[${info.level}] ${info.message}`];

      if (info.stack) {
        logLines.push(`\n${info.stack}`);
      }

      return logLines.join("");
    })
  ),
});

‍

Then we registered the middleware from the custom winston transport as the first entry point of our application.

  // registration of middleware for log bundling
  app.use(await lw.express.makeMiddleware(logger));

‍

This had to be registered first since we wanted all application logs to be bundled.

After these steps, we were able to log messages using the log object injected into the request object as demonstrated below

  // initialization of middlewares //
  app.use((req: CustomRequest, res: Response, next: NextFunction) => {
    req.log.info("This is a sample middleware");
    return next();
  });

  // initialization of endpoints //
  app.post("", (req: CustomRequest, res: Response) => {
    req.log.info("You submitted a POST request.");
  });

‍

‍

This isn’t magic. The lw.express.makeMiddleware method does the following under the hood:

1. It takes the custom winston logger that we created
2. It modifies the behavior of the logging functions of that custom logger (info, debug, error) by ensuring that the messages published to Cloud Logging through these methods are attached to a parent request via the log’s trace ID
3. Finally, it attaches the modified logger to the request object for use in the next stages of the request execution.

This is how the logs looked like in Cloud Logging:

By inspecting the log properties, we can see that a trace is defined. To see all the related logs for that request, we can filter the log entries using this trace property.

What’s the problem? In our case, the way we initially implemented log bundling was by propagating the request object throughout our services.This was problematic because this meant the following:

1. Each service class instance that we had was created on a per-request basis, mainly because we wanted the logs generated from each service to be automatically bundled. For this to happen, the request-specific logger should be used.

class BaseService {
  protected logger: winston.Logger;

  constructor(request: CustomRequest) {
    this.logger = request.log;
  }
}

class Service1 extends BaseService {
  test() {
    this.logger.info("Called the test method");
  }
}

‍

// initialization of endpoints //
  app.post("", (req: CustomRequest, res: Response) => {
    const service = new Service1(req);
    service.test();
  });

‍

2. We had to PROPAGATE the logger object anywhere we wanted bundled logs. This honestly was not that big of a problem but it felt weird having to pass an additional object that semantically had nothing to do with the method being called. As in the theoretical helper function below:

export const add = (num1: number, num2: number, logger: winston.Logger) => {
  logger.info("Adding numbers:", num1, "and", num2);
  return num1 + num2;
};

‍

What does the logger have anything to do with adding two numbers? Why do we have to pass it as a parameter when calling the add function?

‍

Approach 2 (a step forward)

Reflecting on our implementation, the main technical requirement that had to be fulfilled was for the request-specific logger to be shared and used across affected services. In retrospect, we did not have to propagate the request object to fulfill this need. We just needed a way to persist and give access to the request-specific logger injected by the transport middleware.

Luckily, Node.js’s AsyncLocalStorage provided the perfect solution for our challenges. It enabled us to persist and manage data across asynchronous operations within a given execution context. Essentially, this feature allowed us to store the request-specific logger in a central location and access it from anywhere in our system.

To achieve this, first we had to initialize a global async local storage instance dedicated for storing loggers.

export const centralizedLoggerStorage = new AsyncLocalStorage();

‍

Then we had to attach a middleware that takes the logger object from the request object and stores it within the global async local storage instance.

  // registration of middleware for log bundling
  app.use(await lw.express.makeMiddleware(logger));

  app.use((req: CustomRequest, res: Response, next: NextFunction) => {
    // store injected logger to the local storage for use via logger service
    centralizedLoggerStorage.run(req.log, () => {
      next();
    });
  });

‍

Calling the NextFunction inside the run callback of AsyncLocalStorage implies that req.log can be accessed from anywhere within the execution of that request. We were now able to log messages by retrieving the request-specific logger from the async local storage instance like the following:

 app.post("", (req: CustomRequest, res: Response) => {
    (centralizedLoggerStorage.getStore() as winston.Logger).info("I am a log");
 });

‍

With this, we modified our code structure to remove all request propagation logic. To do this, we first created a custom logger service class to abstract the usage of AsyncLocalStorage.
‍

export class LoggerService {
  public static get() {
    return (centralizedLoggerStorage.getStore() as winston.Logger) ?? console;
  }

  public static info(...messages: any[]) {
    LoggerService.get().info(messages.join());
  }

  public static debug(...messages: any[]) {
    LoggerService.get().debug(messages.join());
  }

  public static error(...messages: any[]) {
    LoggerService.get().error(messages.join());
  }
}

‍

Note in the sample implementation above that the centralized logger is explicitly retrieved from the store in every call to the log methods. This is intentional because we were now open to implementing the singleton design pattern, where multiple concurrent requests can use the same instance of a service. On the contrary, if a centralized logger class property were to be defined and initialized in the constructor of a singleton class, the centralized logger would behave differently because it wouldn’t be able to cover the state of every single request.

This pattern allowed us to maximize resource usage efficiency via singletons. Refer to the sample usage below.

 class Service1 {
    test() {
      LoggerService.info("Called the test method");
    }
  }

  const service = new Service1();

  app.post("", (req: CustomRequest, res: Response) => {
    service.test();
  });

‍

This revised logging strategy not only reduced the complexity but also prevented the semantic pollution that occurred when passing the logger object unnecessarily to unrelated functions. Now, our logging is both more streamlined and more effective, with each log entry linked to its request context.

export const add = (num1: number, num2: number) => {
  LoggerService.info("Adding numbers:", num1, "and", num2);
  return num1 + num2;
};

‍

After all the modifications, the log bundling still works!

How might we do better?

• The implementation we settled for is tightly coupled with the middleware provided by the custom winston transport. This is okay for our use case because most of our applications are deployed on GCP. However, this would be problematic for use in other platforms because it requires that the application be able to export logs to GCP Cloud Logging. In these cases, it might be worth creating your own custom middleware that emulates the required behavior.

‍

----

Written by Sheen Capadngan, full stack developer and Google Cloud Certified Professional Cloud Architect & Developer.