AWS Lambda using Winston logging loses Request ID

Question

When using console.log to add log rows to AWS CloudWatch, the Lambda Request ID is added on each row as described in the docs

A simplified example based on the above mentioned doc

exports.handler = async function(event, context) {
  console.log("Hello");
  return context.logStreamName
};

Would produce output such as

START RequestId: c793869b-ee49-115b-a5b6-4fd21e8dedac Version: $LATEST

2019-06-07T19:11:20.562Z c793869b-ee49-115b-a5b6-4fd21e8dedac INFO Hello

END RequestId: c793869b-ee49-115b-a5b6-4fd21e8dedac

REPORT RequestId: c793869b-ee49-115b-a5b6-4fd21e8dedac Duration: 170.19 ms Billed Duration: 200 ms Memory Size: 128 MB Max Memory Used: 73 MB

The relevant detail here regarding this question is the Request ID, c793869b-ee49-115b-a5b6-4fd21e8dedac which is added after the timestamp on the row with "Hello".

The AWS documentation states

To output logs from your function code, you can use methods on the console object, or any logging library that writes to stdout or stderr.

The Node.js runtime logs the START, END, and REPORT lines for each invocation, and adds a timestamp, request ID, and log level to each entry logged by the function.

When using Winston as a logger, the Request ID is lost. Could be an issued with formatters or transports. The logger is created like

const logger = createLogger({
    level: 'debug',
    format: combine(
      timestamp(),
      printf(
        ({ timestamp, level, message }) => `${timestamp} ${level}: ${message}`
      )
    ),
    transports: [new transports.Console()]
  });

I also tried simple() formatter instead of printf(), but that has no effect on whether Request ID is present or not. Also removing formatting altogether still prints the plain text, i.e. no timestamp or request id.

I also checked the source code of Winston Console transport, and it uses either console._stdout.write if present, or console.log for writing, which is what the AWS documentation said to be supported.

Is there some way to configure Winston to keep the AWS Lambda Request ID as part of the message?

P.S. There are separate Winston Transports for AWS CloudWatch that I am aware of, but they require other setup functionality that I'd like to avoid if possible. And since the Request ID is readily available, they seem like an overkill.

P.P.S. Request ID can also be fetched from Lambda Context and custom logger object initialized with it, but I'd like to also avoid that, pretty much for the same reasons: extra work for something that should be readily available.

Answer 1

The issue is with the usage of console._stdout.write() / process._stdout.write(), which Winston built-in Console Transport uses when present.

For some reason lines written to stdout go to CloudWatch as is, and timestamp/request ID are not added to log rows as they are with console.log() calls.

There is a discussion on Github about making this a constructor option that could be selected on transport creation, but it was closed as a problem related to specific IDEs and how they handle stdout logs. The issue with AWS Lambdas is mentioned only as a side note in the discussion.

My solution was to make a custom transport for Winston, which always uses console.log() to write the messages and leave timestamp and request ID to be filled in by AWS Lambda Node runtime.

Addition 5/2020: Below is an examples of my solution. Unfortunaly I cannot remember much of the details of this implementation, but I pretty much looked at Winston sources in Github and took the bare minimum implementation and forced use of console.log

'use strict';

const TransportStream = require('winston-transport');

class SimpleConsole extends TransportStream {
  constructor(options = {}) {
    super(options);
    this.name = options.name || 'simple-console';
  }

  log(info, callback) {
    setImmediate(() => this.emit('logged', info));

    const MESSAGE = Symbol.for('message');
    console.log(info[MESSAGE]);

    if (callback) {
      callback();
    }
  }
};

const logger = createLogger({
  level: 'debug',
  format: combine(
    printf(({ level, message }) => `${level.toUpperCase()}: ${message}`)
  ),
  transports: [new SimpleConsole()]
});

const debug = (...args) => logger.debug(args);
// ... And similar definition to other logging levels, info, warn, error etc

module.exports = {
  debug
  // Also export other logging levels..
};

Another option

As pointed out by @sanrodari in the comments, the same can be achieved by directly overriding the log method in built-in Console transport and force the use of console.log.

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console({
      log(info, callback) {
        setImmediate(() => this.emit('logged', info));

        if (this.stderrLevels[info[LEVEL]]) {
          console.error(info[MESSAGE]);

          if (callback) {
            callback();
          }
          return;
        }

        console.log(info[MESSAGE]);

        if (callback) {
          callback();
        }
      }
    })
  ]
});

See full example for more details

Answer 2

As already mentioned by @kaskelloti AWS does not transforms messages logged by console._stdout.write() and console._stderr.write()

here is my modified solution which respects levels in AWS logs

const LEVEL = Symbol.for('level');
const MESSAGE = Symbol.for('message');

const logger = winston.createLogger({
    transports: [
        new winston.transports.Console({
            log(logPayload, callback) {
                setImmediate(() => this.emit('logged', logPayload));
                const message = logPayload[MESSAGE]

                switch (logPayload[LEVEL]) {
                    case "debug":
                        console.debug(message);
                        break
                    case "info":
                        console.info(message);
                        break
                    case "warn":
                        console.warn(message);
                        break
                    case "error":
                        console.error(message);
                        break
                    default:
                        //TODO: handle missing levels
                        break
                }

                if (callback) {
                    callback();
                }
            }
        })
    ],
})