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

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();
                }
            }
        })
    ],
})

Answer 2

according to the AWS docs

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.

I ran a quick test using the following Winston setup in a lambda:

const path = require('path');
const { createLogger, format, transports } = require('winston');
const { combine, errors, timestamp } = format;

const baseFormat = combine(
  timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
  errors({ stack: true }),
  format((info) => {
    info.level = info.level.toUpperCase();
    return info;
  })(),
);

const splunkFormat = combine(
  baseFormat,
  format.json(),
);

const prettyFormat = combine(
  baseFormat,
  format.prettyPrint(),
);

const createCustomLogger = (moduleName) => createLogger({
  level: process.env.LOG_LEVEL,
  format: process.env.PRETTY_LOGS ? prettyFormat : splunkFormat,
  defaultMeta: { module: path.basename(moduleName) },
  transports: [
    new transports.Console(),
  ],
});

module.exports = createCustomLogger;

and in CloudWatch, I am NOT getting my Request ID. I am getting a timestamp from my own logs, so I'm less concerned about it. Not getting the Request ID is what bothers me