nodejs-logging-winston: Error: `write after end` when handling SIGINT

Environment details

OS: MacOS
Node.js version: 10 LTS
npm version:
@google-cloud/logging-winston version: 3.0.6
winston 3.2.1

Steps to reproduce

Winston 3 now has a mechanism to wait for logs to flush described here: https://github.com/winstonjs/winston/blob/master/UPGRADE-3.0.md#winstonlogger

winston.Logger.log and level-specific methods (.info, .error, etc) no longer accepts a callback. The vast majority of use cases for this feature was folks awaiting all logging to complete, not just a single logging message.

Since upgrading, I am unable to get the logs to flush before the process exits (via signal or normal termination).

const winston = require("winston")
const { LoggingWinston } = require("@google-cloud/logging-winston")

const logger = winston.createLogger({
  exitOnError: false,
  level: "info",
  transports: [
    new winston.transports.Console({
      handleExceptions: false
    }),
    new LoggingWinston({
      keyfileName:
        "/Users/jamesholcomb/keys/2e645b0b8d27.json",
      projectId: "my-proj"
    })
  ]
})

logger.emitErrs = false

logger.info("started")

process.on("SIGINT", () => {
  logger.info("Ctrl-C pressed")
  logger.on("finish", () => process.exit(0))
  logger.end()
})

process.openStdin()

Output error:

{"message":"started","level":"info"}
^C{"message":"Ctrl-C pressed","level":"info"}
events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: write after end
    at writeAfterEnd (/Users/jamesholcomb/gcp-test/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:261:12)
    at DerivedLogger.Writable.write (/Users/jamesholcomb/gcp-test/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:305:21)
    at DerivedLogger.info (/Users/jamesholcomb/gcp-test/node_modules/winston/lib/winston/create-logger.js:81:14)
    at process.on (/Users/jamesholcomb/gcp-test/index.js:42:10)
    at process.emit (events.js:198:13)
Emitted 'error' event at:
    at errorOrDestroy (/Users/jamesholcomb/gcp-test/node_modules/winston/node_modules/readable-stream/lib/internal/streams/destroy.js:98:101)
    at writeAfterEnd (/Users/jamesholcomb/gcp-test/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:263:3)
    at DerivedLogger.Writable.write (/Users/jamesholcomb/gcp-test/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:305:21)
    [... lines matching original stack trace ...]
    at process.emit (events.js:198:13)

If I comment out the LoggingWinston transport setup, there is no error.

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 1
Comments: 16 (7 by maintainers)

Most upvoted comments

How is this not a bug? The suggested way of flushing logs doesn’t work in this basic reproducible environment

This also happens to us occasionally, and we couldn’t use setTimeout on the logger.end, since we have no idea how long we’ll have to wait here.

Is there any possible solution for this? In v2 I could have flushed the logs without ending by using the callback arg in logger.info, but we’re using v3 so that’s not possible anymore

RLRabinowitz on Jun 17, 2021

Thanks @RLRabinowitz for your response - I agree that the migration was not properly addressed. I am not sure what exactly happened (this migration predates me), but I guess that winston change was introduced independently since it is not part of googleapis project. I believe the winston 3.0 migration was inevitable in order to be up to date with latest winston changes and the issue with write after end was discovered later due to async nature of Log. I must admit that such migration in winston library supposed to be backward compatible for the sake of clients relying on such functionality - filed the 2095 on winston to revive callback functionality. As of now, I do not see how we can solve this issue except of using printing structured logging to STDOUT feature since current default solution is async/callback oriented. I am happy that you have a workaround as of now - thanks for sharing it since it could be leveraged by more users! I believe that for now we should add some explanation in README regarding this limitation.

losalex on Mar 23, 2022

@losalex it seems like winston implements its logger as a Transform stream and pipes to its transports, delaying the finish event (according to the docs on _final) until the transports are all finished.

It looks like the nodejs-logging-winston transport is a Transform stream as well (via winston-transform), so it seems like if your transport can keep track of its own state, then perhaps all it needs to do is implement its own _final that defers things until it has finished sending the logs and then winston will behave correctly?

elyobo on Jun 17, 2022

I understand that updating the README can help explain the context of the bug, but this needs to remain open so that a proper fix can be implemented. @bcoe suggested a path forward by tracking pending requests.

jamesholcomb on Mar 24, 2022

Hey @losalex, gotta say that I’m not sure what other option would be available, other than bringing back callback functionality.

We’ve already solved our issue internally with this workaround mentioned above, which is specific to the transports we use

My main issue with this personally right now is that the “breaking changes” part of the changelog is misleading. The suggested way of migrating to 3.0 is wrong, it should either mention setTimeout there, or say that the functionality is no longer available

RLRabinowitz on Mar 23, 2022