Automated Logging in Express.js

Learn the significance of Logging, how to implement an automated logging solution in your Node.js applications, redact sensitive data, and preserve logs for later.

Why should you use Logging in your applications?

Logging is an essential practice in development that involves recording events, actions, and information within the application and its components.

Imagine a scenario when a customer attempts to purchase a product on your application and a sudden error appears on the screen and he cannot complete the action. The customer then contacts support and explains to them what happened. The support team with as little information provided by the customer has to figure out what went wrong, debug, and fix it.

Keep in mind customer does not know anything about status codes, headers, or response messages, and most customers won’t even bother to explain what went wrong.
At the same time, developers spend valuable time going through cases like user behavior, failed APIs, performance issues, monitoring and analytics, etc.

Looking at all of these scenarios, we need a way to look into valuable insights into what’s happening within our application, to track operations from beginning to end, and to know what happened, and what was invoked at a specific point in time.
This is where Logging comes into play.

With Logging, we collect as much as information we can for every request, store it, and if we need it, we can look up the history and see what it was that the customer was doing before the failure occurred.

Also, not all logs result in a failure. So it’s a common practice to separate logs per level:

• Fatal
• Error
• Warning
• Debug
• Info
• Trace

Learn more on Logging.

In the world of Node.js, the most common way to log data is to use the plain console.log(). However, there are some downsides to this and that’s why we have packages on NPM that are specifically designed for logging:

• Morgan
• Winston
• Pino
• Debug, etc.

In this chapter, we’ll focus on Winston, as it is the most comprehensive logging solution for Node.js. I encourage you to try other loggers as well.

Using Winston

To get started, install Winston in the Node.js project:

> npm i winston

And import it into the TypeScript/JavaScript file.

import winston from 'winston';

const logger = winston.createLogger({
 // ... config goes here
});

In between we’ll add formatting options to correctly parse JSON (with json()), to include the current timestamp (timestamp()), text message and metadata (using printf()).

const { combine, timestamp, json, printf } = winston.format;
const timestampFormat = 'MMM-DD-YYYY HH:mm:ss';

const logger = winston.createLogger({
  format: combine(
    timestamp({ format: timestampFormat }),
    json(),
    printf(({ timestamp, level, message, ...data }) => {
      const response = {
        level,
        message,
        data, // metadata
      };

      return JSON.stringify(response);
    })
  )

// Usage:
logger.warn(/* Message */, /* Metadata object */)
logger.warn('Hello', { data })

We can store logs in the console, file, or database (or all three) using the Transport array:

export const logger = winston.createLogger({
  format: combine(
    timestamp({ format: timestampFormat }),
    json(),
    printf(({ timestamp, level, message, ...data }) => {
      const response = {
        level,
        timestamp,
        message,
        data,
      };

      return JSON.stringify(response);
    })
  ),
  // store logs in the console
  transports: [
    new winston.transports.Console()
  ],
});

Winston in Express-APIvantage

If you’re new to the series, I’m building a custom Express TypeScript starter project (Express-APIvantage) with to teach cool features in a well-organized project. You can download the starter repository here.
Click 👉 here to get the full code of today’s lesson.

Logger Service

Let’s put together a service that will be used for logging.

import winston from 'winston';

const { combine, timestamp, json, printf } = winston.format;
const timestampFormat = 'MMM-DD-YYYY HH:mm:ss';

// Logger for API endpoints
export const httpLogger = winston.createLogger({
  format: combine(
    timestamp({ format: timestampFormat }),
    json(),
    printf(({ timestamp, level, message, ...data }) => {
      const response = {
        level,
        timestamp,
        message,
        data,
      };

      return JSON.stringify(response);
    })
  ),
  transports: [
    new winston.transports.Console()
  ],
});

This is how we’d call the logger from the outside:

import { httpLogger } from '../../services/logger.service';

httpLogger.info('Some message', { greetings: 'Hello' });

Where in the response object:

• info is a level property
• ‘Some message’ is a message property
• { greetings } is a data property

Using the Logger service

If we invoke the logger in the endpoint we should get a fine response printed to the console.

httpLogger.info('Some message', { greetings: 'Hello' });

{
  "level": "info",
  "timestamp": "Aug-30-2023 21:03:44",
  "message": "Some message",
  "data": { "greetings": "Hello" }
}

As stated above, when logging it’s important to obtain as much useful information as possible. For that reason, we can make use of the data object and pass the actual request and response objects (from endpoints) to retrieve information, such as:

• Request Headers
• Request URI
• Request Method
• Request Query
• Request Parameters
• Response Body
• Response Headers
• Response Status Code, etc.

  .get('/:id', getUserByIdValidator, async (req: Request, res: Response) => {
    const { id } = req.params;

    const existingUser = await UserModel.findById(id);
    res.send(existingUser);

    httpLogger.info('Success', { req, res }) // <-- extract useful info
  })

Formatting Logs

To make the code as clean as possible we’ll create a method that will format the important request/response information and pass it to the logger.

const formatHTTPLoggerResponse = (
  req: Request,
  res: Response,
  responseBody: any
) => {
 // ...
}

Inside we’ll format each object separately:

    request: {
      headers: req.headers,
      host: req.headers.host,
      baseUrl: req.baseUrl,
      url: req.url,
      method: req.method,
      body: req.body,
      params: req?.params,
      query: req?.query,
      clientIp:
        req.headers['x-forwarded-for'] ?? req?.socket.remoteAddress,
      },

Then the same thing from the response object as well.

    response: {
      headers: res.getHeaders(),
      statusCode: res.statusCode,
      body: responseBody,
    },

We’ll put the two together in a function that should look like this:

const formatHTTPLoggerResponse = (
  req: Request,
  res: Response,
  responseBody: any // object or array sent with res.send()
) => {

  return {
    request: {
      headers: req.headers,
      host: req.headers.host,
      baseUrl: req.baseUrl,
      url: req.url,
      method: req.method,
      body: req.body,
      params: req?.params,
      query: req?.query,
      clientIp:
        req?.headers[HTTPHeaders.ForwardedFor] ?? req?.socket.remoteAddress,
    },
    response: {
      headers: res.getHeaders(),
      statusCode: res.statusCode,
      body: responseBody,
    }
  };
};

export default formatHTTPLoggerResponse;

Now when call the logger service we’ll pass the request/response data through the function we created above.

  .get('/:id', getProductByIdValidator, async (req: Request, res: Response) => {
    try {
      const { id } = req.params;

      const existingProduct = await useTypeORM(ProductEntity).findOneBy({ id });

      if (!existingProduct) {
        res
          .status(404)
          .send({ message: `Product with id: ${id} was not found.` });
        // Logger (1)
        httpLogger.error('Failure message', 
          formatHTTPLoggerResponse(req, res, 
          { message: `Product with id: ${id} was not found.` }))
        return;
      }

      res.send(existingProduct);
      // Logger (2)
      httpLogger.info('Success message', 
        formatHTTPLoggerResponse(req, res, existingProduct)
      )
    } catch (e: unknown) {
      res.status(500).send({ message: ErrorMessages.GetFail });

      // Logger (3)
      httpLogger.error('Failure message', 
        formatHTTPLoggerResponse(req, res, 
        { message: ErrorMessages.GetFail })
      )
    }
  })

We’ll also update the logger service by creating a unique log identifier (logId) for each log, as well as displaying app information (such as version or environment).

import { randomBytes } from 'crypto';

const appVersion = process.env.npm_package_version;
const generateLogId = (): string => randomBytes(16).toString('hex');

export const httpLogger = winston.createLogger({
  format: combine(
    timestamp({ format: timestampFormat }),
    json(),
    printf(({ timestamp, level, message, ...data }) => {
      const response = {
        level,
        logId: generateLogId(),
        timestamp,
        appInfo: {
          appVersion,
          environment: process.env.NODE_ENV,
          proccessId: process.pid,
        },
        message,
        data,
      };

      // indenting logs for better readbility
      return JSON.stringify(response, null, LogIndentation.MD);
    })
  ),
  transports: [
    new winston.transports.Console(),
  ]

Photo by Jessica Lewis from Pexels

DEMO

Now let’s see the results.

Successful Scenario

Request:

GET
http://localhost:3000/api/typeorm/products/3

Response:

{
  "id": 3,
  "name": "new keyboard",
  "price": 1000,
  "description": "Wooden table",
  "datePublished": "Sat May 13 2023",
  "image": "https://rukminim1.flixcart.com/image/612/612..."
}

Log Output:

{
    "level": "info",
    "logId": "043ee172a7e81c6a235f37824190697b",
    "timestamp": "Aug-30-2023 20:03:44",
    "appInfo": {
        "appVersion": "1.0.0",
        "proccessId": 18464
    },
    "message": "Success Message",
    "data": {
        "request": {
            "headers": {
                "host": "localhost:3000",
                "connection": "keep-alive",
                "cache-control": "max-age=0",
                ... // more headers stuff
            },
            "host": "localhost:3000",
            "baseUrl": "/api/typeorm/products",
            "url": "/3",
            "method": "GET",
            "body": {},
            "params": {
                "id": "3"
            },
            "query": {},
            "clientIp": "::1" // localhost
        },
        "response": {
            "headers": {
                "x-powered-by": "Express",
                "access-control-allow-origin": "*" // CORS allow all
            },
            "statusCode": 200,
            "body": {
                "id": 3,
                "name": "new keyboard",
                "price": 1000,
                "description": "Wooden table",
                "datePublished": "Sat May 13 2023",
                "image": "https://rukminim1.flixcart.com/image/612/612..."
            }
        }
    }
}

Failed Scenario

Request:

GET
http://localhost:3000/api/typeorm/products/999

Response:

{
  "message": "Product with id: 999 was not found."
}

Log Output:

{
    "level": "error",
    "logId": "49d802fe5bbfa776d5c6f5a2ac0a6f58",
    "timestamp": "Aug-30-2023 20:06:04",
    "appInfo": {
        "appVersion": "1.0.0",
        "proccessId": 18464
    },
    "message": "Failure message",
    "data": {
        "request": {
            "headers": {
                "host": "localhost:3000",
                "connection": "keep-alive",
                // ...
            },
            "host": "localhost:3000",
            "baseUrl": "/api/typeorm/products",
            "url": "/999",
            "method": "GET",
            "body": {},
            "params": {
                "id": "999"
            },
            "query": {},
            "clientIp": "::1"
        },
        "response": {
            "headers": {
                "x-powered-by": "Express",
                "access-control-allow-origin": "*"
            },
            "statusCode": 404,
            "body": {
                "message": "Product with id: 999 was not found."
            }
        }
    }
}

If you liked the content so far and want to see more of the chapters consider buying me a warm cup of coffee.

Buy me a coffee

Changing The Game

We’ve seen that Winston can produce pretty detailed logs. Now it’s time to step up the game.

I don’t know about you, but it’s a waste of time to keep writing the same logger service call for each condition in each endpoint. Not to mention that logs are printed in the console and it is very difficult to recover them later. It would also be nice if it could know how long it took for the request to be completed and if we can hide sensitive information such as passwords.

To address these issues in our app, we should shift our attention to these four pillars:

• Intercept
• Redact
• Estimate
• Preserve

Build a Logger Interceptor

To avoid copy-pasting a logger function for every API endpoint and every condition case, we’ll create a response interceptor middleware that will be triggered whenever the response object sends data to the client and we’ll pick up the request/response information in the interceptor.

What this means is that when we call,

res.status(400).send({ message: 'Something went wrong' });

We’ll be able to extract the same request/response information as before automatically.

Creating interceptor middleware

const responseInterceptor = (
  req: Request,
  res: Response,
  next: NextFunction
) => {

  // Save the original response method
  const originalSend = res.send;

  let responseSent = false;

  // Override the response method
  res.send = function (body: any): Response {

    if (!responseSent) {
      if (res.statusCode < 400) {
        httpLogger.info(
          'Some Success message',
          formatHTTPLoggerResponse(req, res, body)
        );
      } else {
        httpLogger.error(
          body.message,
          formatHTTPLoggerResponse(req, res, body)
        );
      }

      responseSent = true;
    }

    // Call the original response method
    return originalSend.call(this, body);
  };

  // Continue processing the request
  next();
};

Injecting the interceptor in router.ts:

const routerSetup = (app: Express) =>
  app
    // place an interceptor above all routes that you want to `intercept`
    .use(responseInterceptor)
    .use('/api/mongoose/users', mongooseUsersRouter)
    .use('/api/typeorm/products', typeormProductsRouter)

export default routerSetup;

Now we’ll have an interceptor that will trigger for every request a log a message after a response is sent to the client. This means that we can remove every other call to httpLogger in our controllers.

Instead of logging manually, we’re relying on an interceptor to produce the logs

Obscure sensitive information from logs

Personal information should be hidden even from logs. That’s why we’re going to redact log messages that contain sensitive information.

First, we’ll define an enum that will contain all keys we want to redact.

// Define sensitive keys you want to remove from logs
export enum SensitiveKeys {
  Password = 'password',
  NewPassword = 'new_password',
  OldPassword = 'old_password',
  RepeatPassword = 'repeat_password'
}

Then we’ll create a recursive function that we’ll loop through the response data (array or an object) and replace sensitive words with the asterisk.

import { SensitiveKeys } from '../enums/logger/sensitive-keys.enum';

const sensitiveKeysList = Object.values(SensitiveKeys) as string[];

const redactLogData = (data: any): any => {

  if (typeof data === 'object' && data !== null 
      && !data.constructor.name.startsWith('model')) {
    if (Array.isArray(data)) {
      return data.map(item => redactLogData(item));
    }

    const redactedData: any = {};

    for (const key in data) {
      if (sensitiveKeysList.includes(key)) {
        redactedData[key] = '*****'; // replace password with *
      } else {
        // Recursively redact sensitive keys within nested objects
        redactedData[key] = redactLogData(data[key]);
      }
    }

    return redactedData;
  } else {
    return data;
  }
};

export default redactLogData;

Then we apply this method to a response body object in the log formatter:

    response: {
      headers: res.getHeaders(),
      statusCode: res.statusCode,
      body: redactLogData(responseBody), // <--- Redacting logs
    }

Calculate Request Duration

We’ll use simple math to calculate the difference between the beginning and the end of a request and print that in the log.

Since we know that our logging interceptor is triggered before any other endpoint, we can create a variable that stores the current time in milliseconds on top of the interceptor.

const responseInterceptor = (
  req: Request,
  res: Response,
  next: NextFunction
) => {
  // used to calculate time between request and the response
  const requestStartTime = Date.now();

Then pass this to the logger formatter that will be called after the request has finished:

  httpLogger.info(
    getResponseMessage(req.method),
    formatHTTPLoggerResponse(req, res, body, requestStartTime)
  );

And do some calculations inside:

  if (requestStartTime) {
    const endTime = Date.now() - requestStartTime;
    requestDuration = `${endTime / 1000}s`; // ms to s
  }

...    
    response: {
      headers: res.getHeaders(),
      statusCode: res.statusCode,
      requestDuration,
      body: redactLogData(responseBody),
    }

Preserving the Logs

Now let’s learn how to save logs. Winston offers several options:

• Store into files
• Store into the database (MongoDB / Elasticsearch)
• Store to AWS Cloudwatch
• Send logs to another API (like a centralized service)

Save Logs to a file

Just like when logging into the console, we’ll create a new Transport from Winston that will to the files.
We also provide the name of the file that will hold the logs.

export const httpLogger = winston.createLogger({
  format: combine(
    ...
  ),
  transports: [
    // log to console
    new winston.transports.Console(),
    // log to file
    new winston.transports.File({
      filename: 'logs/application-logs.log',
    }),

With this in place, we should now see logs printed both in the console and in the file.

Saving logs to file

Rotate files daily

Having all of the logs in a single file can get messy quickly. That’s why it’s a good practice to rotate files daily or after they reach a certain threshold (size limit).
To achieve this we need to install another package:

> npm i winston-daily-rotate-file

Then we import it into a logger service and add our configuration:

import  DailyRotateFile from 'winston-daily-rotate-file';

...
  transports: [
    // log to file, but rotate daily
    new DailyRotateFile({
      // each file name includes current date
      filename: 'logs/rotating-logs-%DATE%.log', 
      datePattern: 'MMMM-DD-YYYY',
      zippedArchive: false, // zip logs true/false
      maxSize: '20m', // rotate if file size exceeds 20 MB
      maxFiles: '14d' // max files
    })
  ],
});

Then we should see a new log file for each day.

Save logs to the database

Since we’re already using a MongoDB database in our project, we’ll use it to store logs there. However, we have to make a few adjustments to our logger, so for this case, we’ll create a new logger instance, httpLoggerDB.

First, we need to install a package and set it up in our service.

> npm i winston-mongodb

import winston from 'winston';
import 'winston-mongodb';

Then we create a logger:

// Logger for MongoDB
export const httpLoggerDB = winston.createLogger({
  format: combine(
    json(),
    metadata()
  ),
  transports: [
    new winston.transports.MongoDB({
      // we'll use the existing database to preserve logs
      db: process.env.MONGODB_URI as string,
      collection: 'logs', // name of the table/collection
      options: { useUnifiedTopology: true }
    }),
  ],
});

Let’s go over these changes:

• MongoDB will already generate the unique identifier and the timestamp. That means we do not need those fields in the format.
• The request and the response data will be passed into the meta Object in MongoDB, thus we’ve included the metadata() function in the format.
• We do not need to format the response as an object with JSON.stringify() because MongoDB will already save the information as a Document object.

Using our new logger in the interceptor:

      if (res.statusCode < 400) {
        httpLoggerDB.info(
          getResponseMessage(req.method),
          formatHTTPLoggerResponse(req, res, body, requestStartTime)
        );
      } else {
        httpLoggerDB.error(
          body.message,
          formatHTTPLoggerResponse(req, res, body, requestStartTime)
        );
      }

Then run the app, test a few routes, and head on over to MongoDB Atlas to preview your logs in action.

Our logger in MongoDB

If you’ve made it so far and are looking for full code, here is the link to the repository you’re looking for:

GitHub - Leka-Workshop/Express-APIvantage at 3-Logging

UPDATE

You can find an updated version here:

GitHub - Leka-Workshop/Express-APIvantage at 4-error-handling

Extras

These are some bonus features to improve your logging solution.

CLI Logger

To have a clearer understanding of what is going on when you run the project we’ll build a logger solely for that.

export const cliLogger = winston.createLogger({
  format: combine(
    label({ label: appVersion }),
    timestamp({ format: timestampFormat }),
    colorize({ level: true }),
    printf(
      ({ level, message, label, timestamp }) =>
        `[${timestamp}] ${level} (${label}): ${message}`
    )
  ),
  transports: [new winston.transports.Console()],
});

And put it in place (in init.ts) when the app starts or fails to start:

    app.listen(PORT, () => {
      cliLogger.info(`Server started on port ${PORT} 🚀🚀🚀`);
    });

  } catch (error: unknown) {
    cliLogger.error('Server startup failed! ❌');
    httpLogger.error(ErrorMessages.AppStartupFail, { error });
  }

Success Scenario

[Aug-30-2023 20:01:28] info (1.0.0): Databases connected successfully!
[Aug-30-2023 20:01:28] info (1.0.0): . . . . . . .
[Aug-30-2023 20:01:28] info (1.0.0): Server started on port 3000 🚀🚀🚀

Error Scenario

[Aug-30-2023 19:57:27] error (1.0.0): Server startup failed! ❌
{
    "level": "error",
    "logId": "85d51dab0b9fb7617c5b9438192d6a57",
    "timestamp": "Aug-30-2023 19:57:27",
    "appInfo": {
        "appVersion": "1.0.0",
        "proccessId": 29552
    },
    "message": "Unable to start the app!",
    "data": {
        "error": {
            "cause": {
                "errno": -4039,
                "code": "ETIMEDOUT",
                "syscall": "connect",
                "address": "...",
                "port": 27017
            },
            "connectionGeneration": 0
        }
    }
}

Interact with logs through UI

With logs stored in the file or the database, you can create an endpoint that retrieves the logs from MongoDB (using Mongoose) and filter selections.
Then in the next step, you can build UI using your favorite frontend framework that interacts with logs exposed by API for better observability.

Database Debugging Logs

We can enable database logs which can be very useful during development for logging the actual database queries that ORM/ODM generates and executes.

Mongoose (MongoDB)
Start by importing Mongoose in the database setup file and set debug mode to true.

import mongoose, { connect } from 'mongoose';

mongoose.set('debug', true); // <--- Enables debug logs

export default async function mongooseConnect(): Promise<void> {
  // ...
}

Then when you execute any Mongoose query in the app, you’ll see detailed logs of what is executed behind the scenes in Mongoose.

// JS Code
const existingUser = await UserModel.findById(id);

// Mongoose Log
Mongoose: users.findOne({ _id: ObjectId("6469eb45...") }, 
   { projection: { password: 0 } }
// password: 0 = do not return password field

TypeORM (SQL)
Now let’s apply the same in TypeOrm, by setting the logging flag to true.

export default async function typeORMConnect(): Promise<void> {

  const dataSource = new DataSource({
    type: 'postgres',
    url: process.env.PGSQL_URI,
    entities: [
      `${__dirname}/entity/*.entity.js`,
      `${__dirname}/entity/*.entity.ts`
    ],
    synchronize: true,
    logging: true // <--- Enables debug logs
  });

  typeORMDB = await dataSource.initialize();
}

Upon which when executing a query, TypeORM returns a raw SQL of what went on behind the scenes.

// JS Code
const existingProduct = await useTypeORM(ProductEntity).findOneBy({ id });

-- TypeORM Log
SELECT "ProductEntity"."id", 
  "ProductEntity"."name", 
  "ProductEntity"."price", 
  "ProductEntity"."description" 
  FROM "product_entity" "ProductEntity" 
  WHERE ("ProductEntity"."id" = $1) LIMIT 1

Don’t forget to turn off the debug mode before committing to the production/testing environment as these logs will slow down your apps.
Or you keep them active only in dev mode, e.g.
logging: process.env.NODE_ENV === ‘development’; // true/false

Hide Logs

This is an extra functionality that is usually used when testing to avoid creating unnecessary log entries.

  transports: [
    new winston.transports.Console({
      silent: process.env.NODE_ENV === 'test_env'
    }),

When silent is set to true the logger will not log.

Azure Application Insights by Learn.Microsoft

Third-Party Tools

If you hate to set up logging yourself, there is a plethora of third-party tools that help you do just that, as well as provide a fine user interface to interact with.

Some of the tools of the trade:

• Azure Application Insights
• AWS Cloudwatch + X-Ray
• Sentry
• Grafana

Wrapping Up

Overall, Logging is an important topic in developing any type of application. In the next chapter in the series, we’ll learn about Error handling in Node.js and some of the best practices to implement alongside the existing logger.

I’ll see you in the next one 👋

Read More

Build a Global Exception Handler using Express.js & TypeScript

API Validations in Express.js

Server-Side Exception Handling Patterns & Practices

Learn More

• A complete guide to Winston Logging in Node.js
• Node.js logging with Winston
• Mongoose debug messages