winston: logging methods no longer take a callback, can't reliably use it in some environments (AWS Lambda)

I keep getting alerts on this thread, so figure I’ll share why I think this still isn’t working for a lot of people. Background: our use-case (and the context wherein this issue was opened) is AWS Lambda, so what I talk about here only applies there.

Lambda runs Node under the Lambda Execution Context. Pertinent information being:

After a Lambda function is executed, AWS Lambda maintains the execution context for some time in anticipation of another Lambda function invocation.

and

• Any declarations in your Lambda function code (outside the handler code, see Programming Model) remains initialized, providing additional optimization when the function is invoked again.

i.e. to speed up launches, Lambda “freezes” and “thaws” environments instead of fully shutting them down. To do this, Lambda doesn’t wait for Node to exit, it waits for your handler function to exit. Any asynchronous processes are run outside of the handler function, and thus are apt to be frozen with the rest of the Lambda Execution Context if they are not waited for.

Now let’s look at the suggested solution for waiting for Winston - adapted from UPGRADE-3.0.md, assuming we’re running in Lambda:

async function lambdaHandler(event, context) {
  const logger = winston.createLogger({
    transports: [
      new winston.transports.Console(),
      new CustomAsyncTransport(),
    ],
  });
  logger.log('info', 'some message');
  logger.on('finish', () => process.exit());
  logger.end();
}

Spot the problem? logger fires logger.end() within the handler function context, but the function fired by logger.on('finish') runs outside the handler context. Any async processes tied-up by CustomAsyncTransport will stall the finish event from firing, making it likely that the Execution Context freezes before that event fires.

To solve this, lambdaHandler must wait for the logger to exit before resolving:

async function lambdaHandler(event, context) {
  const logger = winston.createLogger({
    transports: [
      new winston.transports.Console(),
      new CustomAsyncTransport(),
    ],
  });
  const loggerFinished = new Promise(resolve => logger.on('finish', resolve));
  logger.log('info', 'some message');
  logger.end();
  await loggerFinished;
}

Since lambdaHandler doesn’t exit until logger fires the finish event, our CustomAsyncTransport should close before our lambda handler, saving those processes from being frozen (assuming the finish event is correctly implemented by @indexzero).

This can be generalized to something similar to the code I’ve shared previously:

async function waitForLogger(logger) {
  const loggerDone = new Promise(resolve => logger.on('finish', resolve));
  // alternatively, use end-of-stream https://www.npmjs.com/package/end-of-stream
  // although I haven't tested this
  // const loggerDone = new Promise(resolve => eos(logger, resolve));
  logger.end();
  return loggerDone;
}

async function lambdaHandler(event, context) {
  const logger = winston.createLogger({
    transports: [
      new winston.transports.Console(),
      new CustomAsyncTransport(),
    ],
  });
  logger.log('info', 'some message');
  await waitForLogger(logger);
}

Hope this helps some people.

@tsaockham I have solution 😃

function waitForLogger() {
    return new Promise(resolve => setTimeout(resolve, 2500));
}

After 2h of searching solution I implemented this, even function waitForLogger by @dpraul didn’t worked, I am done.

Does not make it not an issue. Thanks for bringing it up.

const winston = require('winston');

class CustomTransport extends winston.Transport {
  log({ message }, cb) {
    setTimeout(() => {
      console.log(`custom logger says: ${message}`);
      cb(null);
    }, 3000);
  }
}

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console(),
    new CustomTransport(),
  ],
});

logger.on('finish', () => {
  console.log('done!');
});
logger.log('info', 'here is some content');
logger.end();

Expected output:

{"level":"info","message":"here is some content"}
custom logger says: here is some content
done!

Actual output:

{"level":"info","message":"here is some content"}
done!
custom logger says: here is some content

The finish event is firing before all the transports have finished. The same behavior occurs when using .on('close', fn) and the .close() event at the end.

Thanks to some input from @mcollina @davidmarkclements & @mafintosh I learned that my understanding of pipe semantics was flawed.

• 'error' and 'finish' events do not back propagate through the pipe chain.
• 'error' events cause unpipe to occur.

Going to explore how to either back propagate these events or expose an explicit method on Logger that implements the technique you’re using now @dpraul (maybe using end-of-stream).

@natesilva going to leave this issue open until the explicit fix is in, but in the meantime you should be able to use the technique above:

• Listen for 'finish' events on all transports
• Call logger.end()
• When all 'finish' events have been emitted you are done logging.

I still don’t know what’s causing the issue, but I found a workaround that waits for all the transports to finish!

const winston = require('winston');

class CustomTransport extends winston.Transport {
  log({ message }, cb) {
    setTimeout(() => {
      console.log(`custom logger says: ${message}`);
      cb(null);
    }, 3000);
  }
}

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console(),
    new CustomTransport(),
  ],
});

async function waitForLogger(l) {
  const transportsFinished = l.transports.map(t => new Promise(resolve => t.on('finish', resolve)));
  l.end();
  return Promise.all(transportsFinished);
}

logger.log('info', 'here is some content');

waitForLogger(logger).then(() => console.log('all done!'));

Output:

{"level":"info","message":"here is some content"}
custom logger says: here is some content
all done!

It seems that logger.end() properly propagates to the transports, but fires the finish event before all the transports have fired theirs. The workaround is to wait on each Transport to fire its own finish event and not rely on the Logger at all.

I think this issue should put in the first priority. For process with code like:

process.on('uncaughtException', err => {
	logger.error(err, () => {
		process.exit(1);
	});
});

It will cause the process hang forever and unable to restart gracefully.

Will this issue be fixed or it will just keep closed?

@dpraul’s solution here (https://github.com/winstonjs/winston/issues/1250#issuecomment-452128291) explained the problem and workaround very well. This worked for me in AWS lambda.

One note that he called out earlier in the thread that I’ll re-iterate. You will need to create your logger AND transport objects at the beginning of the lambda handler. If you try to re-use them you’ll get errors since the transport stream will be closed when the lambda execution environment is frozen.

EDIT: this does not work

============ I’m not sure if this is the best way, nor whether it works in all cases, but so far we are handling this by doing the following:

I’ve created a wait-for-logger.js function as such:

function waitForLogger(logger) {
  return new Promise((resolve) => {
    logger.on('close', resolve);
    logger.close();
  });
}

module.exports = waitForLogger;

At the end of our handler, we wait for the function output before returning:

const logger = require('./logger');
const waitForLogger = require('./wait-for-logger');

async function handler(event, context) {
  // your functionality
  logger.log('info', 'This should make it through all the transports');
  // ...

  await waitForLogger(logger);
}

We are using the nodejs8.10 Lambda runtime - if you are using an older runtime, you can probably do something like the following:

function handler(event, context, callback) {
  // your functionality
  logger.log('info', 'This should make it through all the transports');
  // ...

   waitForLogger(logger).then(() => callback(null));
}

After much digging, debugging and attempting to get the Loggly winston plugin work in lambda…our solution was to write our own simple logger that talks directly to the Loggly API and the console and dump Winston. 😛 Sorry, it’s not currently open source, but it’s separable from our product so I could probably publish it if there’s interest.

I was pretty disappointed this didn’t work. I just couldn’t find a way to reliably block waiting for logging to complete with a timeout. We’d end up getting errors instead when calling finish and logs would get dropped which made it a mostly useless solution for lambda. You couldn’t be sure if there was an error and hence you didn’t get logs or if the logs were just lost. After rolling our own (which I usually try to avoid) it was clear there were problems in the logging.

I’m not sure if the issue was in the Loggly Winston plugin in our case or with Winston itself. But, it seemed to boil down to Winston. Either way, it was disappointing.

-Johnny

On Tue, Jun 8, 2021 at 11:41 AM Aidan Ayala @.***> wrote:

Is there a suggested approach to handling this yet? I see there’s an unmerged PR #1909 https://github.com/winstonjs/winston/pull/1909 which looks to address it?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/winstonjs/winston/issues/1250#issuecomment-856880887, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAQ2PCUCGERV4JYFZJIGXFDTRY2Y7ANCNFSM4EX6KBJA .

Oh the problem with above is that I try to close an already closed logger so promise never resolves, this fixes it

const closeLogger = async () => {
  if (logger && !logger.writable) {
    // If it's already closed don't try to close it again
    return Promise.resolve();
  }
  const loggerClosed = new Promise(resolve => logger.on('finish', resolve));
  // https://github.com/winstonjs/winston/issues/1250
  logger.end();
  return loggerClosed;
}

@natesilva thought about this some more

1. In winston@3 both the Logger and the Transport are Node.js streams.
2. Writeable streams expose an .end method and a 'finish' event.

Therefore in theory this should work, but I have not tested it yet:

const winston = require('winston');
const logger = winston.createLogger({
  transports: [
    new winston.transports.Console()
  ]
});

process.on('exit', function () {
  console.log('Your process is exiting');
});

logger.on('finish', function () {
  console.log('Your logger is done logging');
});

logger.log('info', 'Hello, this is a raw logging event',   { 'foo': 'bar' });
logger.log('info', 'Hello, this is a raw logging event 2', { 'foo': 'bar' });

logger.end();

I know this is a long old thread but I will share how i could fix it. First, i want to thank @kasvtv and @dpraul for their shared approach that helped me define the following implementation:

class AMQPTransport extends Transport {
  constructor(opts) {
    super(opts);

    this.callsInProgress = new Map();
    this.index = 0;

    this.name = 'amqpTransport';

    const { amqp } = opts;

    const { exchange } = amqp;

    this._rabbitOptions = {
      appName: opts.appName,
      url: amqp.url,
      options: amqp.options,
      exchange: {
        name: exchange.name,
        type: exchange.type,
        options: exchange.options,
      },
    };

    this.init();
  }

  async _final(callback) {
    console.log('amqp final');
    await Promise.all(this.callsInProgress.values());
    await disconnect();
    callback();
  }

  log(info, callback) {
    const output = {
      level: info.level,
      message: info.message,
      timestamp: info.timestamp,
    };

    const { appName, exchange } = this._rabbitOptions;

    const i = this.index++;
    const promise = publish(exchange.name, `logs.${output.level}.${appName}`, output);

    this.callsInProgress.set(
      i,
      promise.finally(() => {
        console.count('amqp logged');
        this.callsInProgress.delete(i);
        callback();
      }),
    );
  }

  init() {
    const { url, options, exchange } = this._rabbitOptions;

    createProducer(url, options, (channel) => {
      return Promise.all([channel.assertExchange(exchange.name, exchange.type, exchange.options)]);
    });
  }
}

The key here is to define the function _final

async _final(callback) {
    console.log('amqp final');
    await Promise.all(this.callsInProgress.values());
    await disconnect();
    callback();
  }

And in order to wait for the logger before closing the process, you can

const waitForLogger = async () => {
      const loggerFinished = new Promise((resolve) => winstonLogger.on('finish', resolve));
      winstonLogger.end();
      return loggerFinished;
}

The map is still necessary due to the finish event being fired once log.end() is called and the first pending callback function inside log function is fired. If you have multiple log functions pending to call the callback function (async logging), you have to wait for every pending log and here is when the _final function enters to action.

I hope this helps!

@dpraul I do not know enough about the stream/lambda internals. When the finish event comes before I attach this listener, will this promise ever be resolved?

I’m not certain. At the time of writing (which was in 2019, so YMMV), the logger wouldn’t fire the finish event until logger.end() was called. The waitForLogger function calls this after setting up the listener, so all is good. If you’re ending the logger elsewhere, I’m not sure what the behaviour will be like.

@hdpa that’s probably because after you close it your function is reused, our current solution is this:

// logger.js
let logger;

const recreateLogger = () => {
  logger = winston.createLogger({
  ....
};

const getLogger = () => {
  if (logger && !logger.writable) {
    recreateLogger();
  }
  return logger;
}

const closeLogger = async () => {
  const loggerClosed = new Promise(resolve => logger.on('finish', resolve));
  // https://github.com/winstonjs/winston/issues/1250
  logger.end();
  return loggerClosed;
}

then in our function we just call getLogger() to get the logger which automatically reopens it if it’s closed and at the end of the function we use closeLogger() to make sure it flushes all the logs to cloudwatch

Tell me pls, in winston@3 i can’t use callbacks like in version 2? (there is no answer in the documentation)

// ... some check the connection to db ... and if fail:
logger.error('message',  function() {
  process.exit(1);
});

And if not use callback my app closes faster than message was logged =(

@indexzero yes, that would be correct.

We’re using a different solution.