winston: transports.File stops logger without any error message

I’m trying to use transports.File to save log file in loop with logger. After several logs print out it stops to write log to file and print nothing in console without any error message.

Here is my test code:

import winston from 'winston'

const winstonConfig = {
  level: 'debug',
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({
      filename:  'file/path/to/combined.log',
      maxsize: 10 * 1024 * 1024,
      maxFiles: 10
    })
  ]
}
let logger = winston.createLogger(winstonConfig)

for(let i=0; i<10000; i++){
  logger.debug(i)
}

Is it stdout buffer issue?

I’m using version 3.0.0-rc1 with node:8-alpine image in docker container

About this issue

Original URL
State: closed
Created 6 years ago
Reactions: 4
Comments: 31 (2 by maintainers)

Commits related to this issue

Fixes issue #1194 — committed to rcoedo/winston by deleted user 6 years ago
Fix file transport write behaviour (#1194) — committed to rcoedo/winston by deleted user 6 years ago
fix issue #1194 - where rotation of files isn't done when tailable is set to true — committed to diag/winston by ledbit 6 years ago
fix file rolling when tailing is set to true (#1420) * fix issue #1194 - where rotation of files isn't done when tailable is set to true * more fixes to tail rolling + fix & enable unit tests *... — committed to winstonjs/winston by ledbit 6 years ago
fix file rolling when tailing is set to true (#1420) * fix issue #1194 - where rotation of files isn't done when tailable is set to true * more fixes to tail rolling + fix & enable unit tests *... — committed to Mizumaki/winston by ledbit 6 years ago

Most upvoted comments

@rcoedo commit fixes the issue but there is still an issue with formatting which I think is related to this.

const winston = require('winston')

const winstonConfig = {
  level: 'debug',
  transports: [
    new winston.transports.Console({
      format: winston.format.printf(info => `${info.level}: ${info.message}`)
    }),
    new winston.transports.File({
      filename: 'winston.log',
      maxsize: 10 * 1024 * 1024,
      maxFiles: 10,
      format: winston.format.printf(info => `${info.level}: ${info.message}`)
    })
  ]
}
const logger = winston.createLogger(winstonConfig)

for (let i = 0; i < 10000; i++) {
  logger.debug(i)
}

Produces this output to a file:

....
debug: 2600
debug: 2601
debug: 2602
debug: 2603
debug: 2604
debug: 2605
debug: 2606
{"message":2607,"level":"debug"}
{"message":2608,"level":"debug"}
{"message":2609,"level":"debug"}
{"message":2610,"level":"debug"}
{"message":2611,"level":"debug"}
{"message":2612,"level":"debug"}
{"message":2613,"level":"debug"}
{"message":2614,"level":"debug"}
{"message":2615,"level":"debug"}
{"message":2616,"level":"debug"}
{"message":2617,"level":"debug"}
{"message":2618,"level":"debug"}
{"message":2619,"level":"debug"}
{"message":2620,"level":"debug"}
{"message":2621,"level":"debug"}
debug: 2622
debug: 2623
debug: 2624
debug: 2625
debug: 2626
debug: 2627
debug: 2628
.....

Output in the console is formatted correctly.

jansteuer on Apr 10, 2018

I think this still happens when using the tailable: true option.

rcoedo on Jun 27, 2018

@jansteuer I can reproduce the behavior. When the stream.write tell us to wait for the drain event, the following 15 lines receive a non formatted message for some reason. I tried to find why but I failed.

I believe this is related to how the Logger handles the transports but I’m not sure. Maybe someone with some expertise in winston can guide us to finally fix the file transport 😃

rcoedo on Apr 13, 2018

@bouchezb The winston-daily-rotate-file issue was identified and has been solved! Give it a shot by installing winston-daily-rotate-file@next.

While this good news is specifically related to the winston-daily-rotate-file Transport and not the File Transport, the issue that affected winston-daily-rotate-file could also be affecting the File Transport.

@billiebbb and @beac0n two questions for you:

What versions of node/npm are you running?
Can you tell if the logger stops working after a file rotation occurs?

I ask the second question because internal stream event bubbling with winston-daily-rotate-file is what caused the Transport to close and unpipe itself. This happened during the file rotation process. Some logs might make it into the newly created file before it was closed if they were reported quickly enough. Given the tight loop in @billiebbb’s example code, it might be the case that those logs are buffered and then several files created before the File transport has some time to react to its first internal file sending an “I’m done” message (close or finish or something…).

ericdrobinson on Mar 2, 2018