Winston: File logging reconfiguration issue (Error: write after end)

[peterbakonyi05]

Please tell us about your environment:

• _winston version?_
  
  
  
  • [ ] winston@2
  
  
  • [ X] winston@3
  
  
• _node -v outputs:_v10.15.0
• _Operating System?_Windows 10
• _Language? JavaScript (pure Node)

What is the problem?

When logger is reconfigured, the open streams are destroyed and winston tries to write to an already destroyed stream.

I created a really simple playground to replicate it (less than 10 lines of actual code): https://github.com/peterbakonyi05/winston-log-rotate-reconfiguration-issue/blob/master/index.js

What do you expect to happen instead?

winston creates a new stream and handles reconfiguration.

Note

Alternatively, instead of reconfiguring winston a new instance can be created, in case someone else has the same issue. Just call .close on the old instance and create a new from scratch.

[SzHeJason]

+1

const winston = require('winston')
const logger = winston.createLogger({
  level: 'info',
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({ filename: 'combined.log' })
  ]
})

//
// Replaces the previous transports with those in the
// new configuration wholesale.
//

logger.configure({
  level: 'verbose',
  transports: [new winston.transports.Console()]
})

module.exports = {
  logger
}

winston : 3.1.0

[indexzero]

This makes sense. PR would be welcome here.

[Nikosmonaut]

It seems to be fixed with v 3.2.1

[govindrai]

Still happening on 3.2.1

[Durisvk]

Tried to reproduce with unit test in logger.test.js:

  // https://github.com/winstonjs/winston/issues/1573
  it.only('.configure({ transports }) purity', function (done) {
    var combinedFile = path.join(__dirname, 'fixtures', 'file', 'combined.log');
    function getWinstonConfiguration() {
      return {
          level: 'info',
          format: winston.format.json(),
          defaultMeta: { service: 'user-service' },
          transports: [
              new winston.transports.Console(),
              new winston.transports.File({ filename: combinedFile }),
          ]
      };
    }


    var logger = winston.createLogger(getWinstonConfiguration());
    logger.info('this should make the first log to file');

    setTimeout(() => {
      try {
        logger.configure(getWinstonConfiguration());

        logger.info('this should make the second log to file after reconfiguration');
        assume(true).true();
        done();
      } catch(e) {
        assume(!!e).false()
        done(e);
      }
    }, 200);
  });

but unsuccessful:

am I missing something or this was fixed?

[Abdul007Malik]

Yes still happening in 3.2.1
~\nodeproject\node_moduleswinston\libwinston\logger.js:307
throw ex;
^

Error: write after end
at writeAfterEnd (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_writable.js:257:12)
at PassThrough.Writable.write (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_writable.js:301:21)
at File.log (~ \nodeproject\node_moduleswinston\libwinston\transports\file.js:185:34)
at ExceptionStream._write (~ \nodeproject\node_moduleswinston\libwinston\exception-stream.js:48:29)
at doWrite (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_writable.js:405:139)
at writeOrBuffer (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_writable.js:394:5)
at ExceptionStream.Writable.write (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_writable.js:303:11)
at DerivedLogger.ondata (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_readable.js:662:20)
at DerivedLogger.emit (events.js:187:15)
at addChunk (~ \nodeproject\node_moduleswinston\node_modules\readable-stream\lib_stream_readable.js:297:12)

Since I set the handleExceptions to true, so when this error occur neither winston handle this exception nor process.on("uncaughtException")

[apaparazzi0329]

tl;dr
Pass by reference in logger.add() function causes the transport object to be altered and thus invalidated when used again in logger.configure()

I think I found the cause of this issue, stemming from the logger.add() function:

add(transport) {

    console.log('In add function\n')
    const target =
      !isStream(transport) || transport.log.length > 2
        ? new LegacyTransportStream({ transport })
        : transport;

    console.log("Original target:", JSON.stringify(target), "\n")
    if (!target._writableState || !target._writableState.objectMode) {
      throw new Error(
        'Transports must WritableStreams in objectMode. Set { objectMode: true }.'
      );
    }

    // Listen for the `error` event and the `warn` event on the new Transport.
    this._onEvent('error', target);
    this._onEvent('warn', target);
    this.pipe(target);

    console.log("Target after pipe:", JSON.stringify(target))

    if (transport.handleExceptions) {
      this.exceptions.handle();
    }

    if (transport.handleRejections) {
      this.rejections.handle();
    }

    return this;
  }

I added my own print statements to keep track of the target object. As can be seen in output from the print statements; the target object is edited after it is used for piping. Since target is equivalent to the transport parameter through pass by reference, the change to target also changes the transport object and thus makes it invalid for reuse in logger.configure(). This explains why an entirely new but identical transport would work with configure() but editing the original transport would give the error.

Probable Solution: Make a deep copy of the passed in transport object so that the target object is pass by value

This is my first time commenting on an open issue on GitHub so please let me know if I missed anything that would make this more helpful. I would have tried to create a coded solution myself but since object cloning doesn't seem to be a native tool in JavaScript I figured it would be better for someone with more knowledge of the code base to create an actual solution

[shadrech]

This is a issue for me as well. Any updates?

[gssbsmrt]

I'm also facing the same issue whenever i use firebase commands. please help me fix this

[justingolden21]

Just deployed to firebase like ten times no problems, several minutes later I try deploying and get this issue on line 307 of logger in Winston. Have no idea what Winston is, but still having this issue in 11/4/20

[Motoxpro]

@justingolden21 Just had the same thing happen to me. Eventually, I re-installed then npm package firebase-tools and it worked

[JadianZheng]

Still happen in 3.3.3

[mdtanrikulu]

If you are calling logger.configure(options) at some point to change/set i.e. logger level dynamically or some other options, simply add File transport just before the new configuration setter. That helped me.
```js
...
// you may want to check before if file transport is already exist, in my case i havent added before.
options.transports.push(new winston.transports.File({ filename: "./name_of_log_file.log" }))
logger.configure(options);