transports.File is not flushing on end.

[racquetmaster]

Please tell us about your environment:

• winston version?
  • winston@2
  • winston@3
• node -v outputs: v10.10.0
• Operating System? (Windows, macOS, or Linux)
• Language? (all | TypeScript X.X | ES6/7 | ES5 | Dart)

What is the problem?

File transport is not flushing on exit. Even when flushing per https://github.com/winstonjs/winston#awaiting-logs-to-be-written-in-winston

Steps to reproduce:

'use strict';

let winston = require('winston');
// VERSION: "winston": "^3.1.0",

let file_transport = new winston.transports.File({
    filename: `${__dirname}/myfile.log.json`,
});
let logger = winston.createLogger({
    transports: [file_transport],
});


async function run() {
    for (let i = 0; i < 1000; i++) {
        logger.info('message');
    }

    logger.info('THE LAST MESSAGE');

    await new Promise(resolve => {
        file_transport.on('finish', resolve);
        logger.end();
    });

    process.exit(1);
}

run();

What do you expect to happen instead?

all messages (including THE LAST MESSAGE) should be written to the file.

[skrud]

I'm experiencing the same issue in some unit tests.

In addition to waiting for the transport to emit the 'finish' event, I've tried just waiting on the logger's finish event and also all the transports.

  it('Should log to file', function(done) {
    const loggingDir = fs.mkdtempSync('logging-dir');

    // Configure with output file
    const loggingFile = path.join(loggingDir, 'log-test.log');
    logger = winston.createLogger({
      transports: [
        new winston.transports.File({filename: loggingFile})
      ]
    });
    
    // Wait until the logger *and* all transports have emitted the 'finish' event
    Promise.all([logger].concat(logger.transports).map(st =>
      new Promise(function(resolve, reject) {
        st.on('finish', resolve);
      })
    )).then(function() {
      let f = fs.readFileSync(loggingFile, 'utf-8');
      expect(f).is.not.empty;
      expect(f).to.satisfy(str => str.includes('Test Message'));
      expect(f).to.satisfy(str => !str.includes('Silly'));
      done();
    }).catch(function(err) {
      done(err);
    });

There is still a race condition here because the test does pass some of the time, and inevitably if I look in the file manually it does have the logging output within it.

[GitStorageOne]

Should be a function flushAllTransports(): Promise<void> which should take care of flushing all buffered data (not just wait next save iteration, but force transport to save) and then resolve promise.

export function flushLogs(): Promise<void> {
  // tslint:disable-next-line: typedef
  return new Promise((resolve, reject) => {
    logger.on('finish', () => resolve());
    logger.end();
  });
}

[ronanquillevere]

I am experiencing the same issue, makes it really hard to use winston with asynchronous processing

[ronanquillevere]

I am experiencing the exact same issue, the posted code by @racquetmaster is correct. It makes it almost impossible to use winston with asynchronous processing

I have been following the documentation (below) calling the end() on Logger. I also tried directly on (File) Transport like @racquetmaster without success. IMO this is a very important issue.

Often it is useful to wait for your logs to be written before exiting the process. Each instance of winston.Logger is also a [Node.js stream]. A finish event will be raised when all logs have flushed to all transports after the stream has been ended.

'use strict'

const winston = require('winston')

const logFilePath = __dirname + '/test-async.log'

const logger = winston.createLogger({
  level: 'debug',
  format: winston.format.combine(
    winston.format.timestamp({
      format: 'YYYY-MM-DD HH:mm:ss'
    }),
    winston.format.simple(),
    winston.format.printf(info => {
      return `[${info.timestamp}] [${info.level}] ${info.message}`
    })),
  transports: [
    new winston.transports.File({
      filename: logFilePath
    })
  ]
})

let code = 1
const asyncFunction = async function(){
  return new Promise(function(resolve) {
    setTimeout(function() {
      logger.info('resolved')
      resolve(0)
    }, 300)
  })
}

const start = async function(){

  logger.info('START')

  code = await asyncFunction()
  logger.info(`code : ${code}`)
  logger.on('finish', function() {
    process.exit(code)
  })

  //Should display END before exiting the process according to doc
  logger.info('END')
  logger.end()
}

start()

[danielweck]

This works for me:
#228 (comment)

[ronanquillevere]

This seems to solve the issue for me

  logger.on('finish', function() {
    setImmediate(() => process.exit(code))
  })

Did not have the time to look at winston code in detail but it seems to mean than the finish event is raised too early, maybe it is added to the event loop before the flush of the underlying transports

[SmartArray]

I am sure this fix works pretty well: #1868
but I wanted to let you know what we have been using to "gracefully" stop the logger:

const fileTransport = new winston.transports.File({
  filename: 'error.log',
  level: 'error',
});

/**
 * Create a basic logger that outputs stderr to error.log
 */
const logger = winston.createLogger({
  level: 'info',
  transports: [
    fileTransport,
  ],
});

logger.endGracefully = () => new Promise((fulfill, reject) => {
  // Add logic for other transports here ...

  fileTransport.on('flush', () => {
    fulfill();
  });
  
  logger.end();
});

// CODE

logger.error('Here comes a log entry');

setTimeout(async () => {
  logger.error('Here comes another log entry');

  await logger.endGracefully();
  process.exit(0);
}, 1000)

Here comes another log entry will be visible in the log file and the process exits normally.

[russellrobinson]

I am sure this fix works pretty well: #1868
but I wanted to let you know what we have been using to "gracefully" stop the logger:

Thanks for this. Your workaround doesn't work in my tests.

Here's the basic test I have:

unlinkSync('error.log');
// your setup goes here....
logger.error('Hello world');
await logger.endGracefully();
const mesgs = readFileSync('error.log');

This fails because the file doesn't exist at the readFileSync.

I hope that helps.

[yogeshbiz]

This is still a major problem searched on internet.
Graceful exit is okay to advise but most cases, developers just call exit(), which does not executes all pending async task.
But this "caution" advisory must be shouted loudly in Winston documents.
Program must wait to drain everything, do you think it is obvious to guess this, even knowing node is async?
Make it easy for developers to create robust and reliable logging.
Could there be a sync call that returns when all transports are written and flushed.

Found this, https://www.npmjs.com/package/winston-log-and-exit
after wasting 6-7 hours.

[sorenlouv]

tldr: replace process.exit(1) with process.exitCode = 1;

After wasting a couple of hours I hope this will help someone else.

[mishabruml]

For anyone running in to this issue because they are trying to capture logs for assertion in unit tests (to check their logs are formatted properly), I solved this using a Stream transport rather than file. It was much, much more reliable:

import { createLogger, format, transports } from 'winston';
import { Writable } from 'stream';
import { v4 } from 'uuid';

const logger = createLogger({
  level: 'info',
  format: format.combine(
    format.timestamp(),
    format.errors({ stack: true }),
    errorFormatter(),
    format.json()
  ),
  transports: [new transports.Console({ format: format.errors({ stack: true }) })],
});

test('should log a basic message and tracetoken', () => {
      // arrange - attach stream transport for assertions
      const stream = new Writable();
      const streamTransport = new winston.transports.Stream({ stream });
      logger.add(streamTransport);

      // arrange - write stream to string
      let expectedOutput = '';
      stream._write = (chunk, encoding, next) => {
        expectedOutput += chunk;
        next();
      };

      // act
      const traceToken = v4();
      logger.info('message', { traceToken });

      // assert
      expect(expectedOutput).toMatchJSON({ // jest-json matcher (basically just parsing stringified JSON)
        traceToken,
        timestamp,
        message: 'message',
        level: 'info',
      });
    });