Error logging and tracing

Our projects backend was built using serverless with each API endpoint being an AWS lambda function.

The code had winston logger setup with each API to log messages to cloudwatch in a standardised format. These logs would then be ingested by various tools, such as SumoLogic, which allowed us to query and search for logs very easily.

Lambda Function --> use logger --> prints formatted logs to Cloudwatch --> send them to Log Consumption Tools

Problem

While working with our APIs, we encountered some pain points that made our lives difficult during debugging and error monitoring:

(1) Too much noise in the logs:

We were printing logs for certain events within the API such as a request has completed, or a step in the function has started. These logs were relevant and helpful in error scenarios but were getting printed for non-error scenarios as well. Considering our APIs get hit millions of times daily, this made querying for relevant logs quite difficult.

(2) No trace to figure out what caused the error

The error logs had a trace but most of the times it wasn't related to what actually caused the error or how far along in the function execution did the error occur.

Proposed Solution

After a long discussion within the team, we decided it would be best to:

• Only consider 500 status code as an error and print it to the console because 4xx errors indicate user made a mistake from their end (no intervention required on our part)
• Create an internal trace which could be printed ONLY when an error occured

Winston caters for various so called Transports which are just ways in which we would want our messages to be stored/consumed.

eg - Winston's built-in Console Transport simply prints the message to the console whereas File Transport stores them in a file of our choosing.

Interestingly, Winston also allows us to create Custom Transports which is the approach we decided to take.

Solution Development - Winston Basics

Winston provides a simple createLogger method to create a new instance of the logger like so:

const winston = require("winston");

const myLogger = winston.createLogger({
  // options to customise the logger here
});

createNewLogger will give us an instance of the logger above but we can't do anything useful with it until we provide atleast a transport to go with it.

const winston = require("winston");

const myLogger = winston.createLogger({
  // we are using built-in Console Transport
  transports: [
    new winston.transports.Console()
    //can contain mutiple transports - built-in or custom
  ]
});

To print messages using the above logger instance, we need to attach logging levels aka severity levels to our logs. Since winston has the npm logging levels built-in by default, we can use them easily:

// npm logging levels

error: 0, ---> most severe
warn: 1,
info: 2,
http: 3,
verbose: 4,
debug: 5,
silly: 6 ----> least severe

Now lets print some different messages with varying severity levels:

myLogger.error("I am quite severe");
myLogger.info("I am just giving some info");
myLogger.info({name: "wow", age: 89}); // print an object
myLogger.warn(["jon snow", "arya stark"]); // or an array

// the above will output the below:

{ "message":"I am quite severe", "level":"error" }
{ "message":"I am just some stuff", "level":"info" }
{ "message":{ "name":"wow","age":89 }, "level":"info" }
{ "message":[ "jon snow", "arya stark" ], "level":"warn" }

Custom Transport Basics

According to Winston docs:

To add a custom transport, all you need to do is accept any options you need, implement a log() method, and consume it with winston.

We also need to use an additional package - winston-transport which provides the base Transport class like so:

const winston = require("winston");
const Transport = require("winston-transport");

class OurTransport extends Transport {
  constructor(props) {
    super(props);
  }
  log(info, callback) {
    // info contains the full message - {message:"", level:""}
    console.log(info);
    // to mark function as complete, use callback
    callback();
  }
}

// create a logger instance with custom transport
const myLogger = winston.createLogger({
  transports: [new OurTransport()]
});

In the above snippet, we are creating a custom tranport - OurTransport which is extending from the Transport base class and has a simple log method.

The log method will be invoked every time we log a message with the logger instance.

We are then able to use this new custom transport with the new instance of our logger as before to print messages:

myLogger.error("Still same as before");
myLogger.info("no change happened");

// the above will output the below:

{ "message":"Still same as before", "level":"error" }
{ "message":"no change happened", "level":"info" }

Until now, we haven't done anything special apart from replicating what the built-in Console Tranport does. But lets get the magic started (after this huge prelude).

Building a Custom Tracer

The goal was to:

• have some sort of trace (Array of trace messages)
• only print it when an error happened

Lets tweak our custom transport so it contains a customTrace property to which we can add messages:

class CustomTracer extends Transport {
  constructor(props) {
    super(props);
    this.customTrace = []; // add this prop to the class
  }

  log(info, callback) {
    // add info object to customTrace on each invocation
    this.customTrace.push(info);
    console.log(info);
    callback();
  }
}

If we start logging messages, they will be stored as part of the customTrace property:

//customTrace = [ infoTrace, infoTrace, errorTrace ]
customTrace = [
    { "message":"info message", "level":"info" }
    { "message":"error message", "level":"error" }
]

Now all that remains is to print it ONLY when an error happens, otherwise keep storing the messages:

  log(info, callback) {
    this.customTrace.push(info);
    if(info.level==="error") {
        console.log({ ...info, trace: this.customTrace });
    }
    callback();
  }

If we now print messages using info or any other severity level, we won't see anything in the console. However, as soon as we log a message with the error severity level, boom! all stored messages in customArray will be printed like so:

myLogger.info("nothing will be printed");
myLogger.verbose("still nothing");

myLogger.error({ errorMessage: "Error happened, time to print the trace" });

// results in the following

{
  message: { errorMessage: "Error happened, time to print the trace" },
  level:"error",
  trace: [
    { "message":"info message","level":"info" }
    { "message":"error message","level":"error" }
  ]
}

And Voila! we have what we wanted!!

Redacting Sensitive Keys with Winston Formats

After implementing the sweet tracer above, we noticed a security issue. For most API calls we were using various API Keys, secrets and user's personal information.

Sometimes, if an error happened, these sensitive values were getting printed in the logs! Ooopss!

To solve this issue, we decided to use Winston Formats which allow us to manipulate our logs however we want before feeding them into a Transport.

We wrote a format that would loop through each key of our message object and would redact its value if the key was deemed to be sensitive.

incoming message --> Redactor Format --> redacts keys in message --> pass it on to Transport

// create the format using winston.format.printf
const customRedactorFormat = winston.format.printf((info) => {
  if (typeof info.message === "object") deepObjectRedactor(info.message);
  return info;
});

// use the custom format to a new instance of the logger
const myLogger = winston.createLogger({
  format: customRedactorFormat(),
  transports: [new OurTransport()]
});

The above snippet creates a custom format and uses it when creating the new instance of the logger. It also uses a deepObjectRedactor function which does the actual manipulation of the data like so:

const deepObjectRedactor = (obj) => {
  // we have assumed the following keys to be sensitive for this example:
  const sensitiveKeys = ["email", "apiKey", "secret"];

  Object.keys(obj).forEach((key) => {
    if (typeof obj[key] === "object") return deepObjectRedactor(obj[key]);
    // if one of the lowercase senstive keys === lowercase key and if the key has a value, redact it
    if (sensitiveKeys.map((e) => e.toLowerCase()).includes(key.toLowerCase()) && obj[key]) {
      obj[key] = "**********";
    }
  });
};

If we now print our messages which have some sensitive keys (email, apiKey, secret):

myLogger.info({ apiKey: "cool-stuff", name: "Max" });
myLogger.info({ secrets: "secrect-stuff", apiKey: "something" });
myLogger.error({ errorMessage: "I have errored", errorCode: 200, email:"user@gmail.com" });

// will print the following:

{
  message: { errorMessage: "I have errored", errorCode: 200, email:"**********" },
  level:"error",
  trace: [
    {
      "message":{ apiKey: "**********", name: "Max"},
      "level":"info"
    }
    {
      "message":{ secrets: "**********", apiKey: "**********" },
      "level":"info"
    },
    {
      "message":{ errorMessage: "I have errored", errorCode: 200, email:"**********" },
      "level":"error"
    }
  ]
}

Conclusion

Centralised error logging coupled with a unique trace has been really helpful for us. Although, we used winston, the same can be achieved with any other open sourced loggers. Happy Bug squashing!

Documentation Winston