Error: write after end when handling SIGINT

[jamesholcomb]

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.

[jamesholcomb]

I played around with this to see if I could get past the error. Changing

nodejs-logging-winston/src/index.ts

Line 182 in 8bc9aad

this.common.log(info[LEVEL] || level, message, metadata || {}, callback);

to

this.common.log(info[LEVEL] || level, message, metadata || {}, () => this.emit('finish');

works around it.

[bcoe]

@jamesholcomb thanks for the good reproduction 👍

[jamesholcomb]

Here's a workaround I'm using that does not require changing the lib:

setTimeout(() => logger.end(), 1000)

[jamesholcomb]

Is there an internal path forward on this? The workaround is not effective for task oriented processes that perform heavy logging then exit...it's impossible to know how long to delay.

[bcoe]

@jamesholcomb I think to address this what we would need to do would be to add a feature to @google-cloud/logging that tracks all of the logs that have been sent but not emitted yet.

Another workaround you might be able to use Node.js', process._getActiveRequests()/process._getActiveHandles() to introspect whether there are any requests still on the wire ... I'm not sure how this behaves with http2 however.

[RLRabinowitz]

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

[losalex]

@jamesholcomb and @RLRabinowitz , do you think that fix provided by @chrismaree helps?

[RLRabinowitz]

Hey @losalex.

As far as I understand, that's just the workaround to add setTimeout on the logger.end. As mentioned above, we can't do that, we have no idea how long we'll have to wait here

[RLRabinowitz]

We've ended up using a transport that had its own implementation of "wait for logs to flush" - https://github.com/lazywithclass/winston-cloudwatch with the kthxbye method.

Then, we just explicitly call this method when closing out the process

[losalex]

@RLRabinowitz , sorry for late reply and thanks for shared workaround!
I am still checking with our team on possible solution and will get back to you.

[losalex]

After looking for this issue more, unfortunately I do not have a great solution for this problem without making some redesign - the removed callback support in winson library breaks the contract we have for nodejs-logging library APIs which are async and callback oriented (based on what I see there is no way to await on winston calls). One possible solution to this problem is to leverage printing structured logging to STDOUT solution which could be used if you run in Google Cloud environment with Cloud Logging Agent enabled (or any cloud which has an ability to capture process.stdout data and send it to Cloud Logging). The other option is to bring back callback functionality in winston.
I am open to any suggestions at this point - please let me know if you have any ideas/comments on this matter.

[RLRabinowitz]

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

[losalex]

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.

[jamesholcomb]

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.

[losalex]

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.

Thanks for your comment @jamesholcomb - sorry, this issue was closed automatically by README change and no time was given to provide more comments. Perhaps I should explain more on a reason why I think there is no good solution might be here. Tracking pending requests could address the issue only partially - correct me if I wrong, but some of the data still could be buffered on a transport level. Also worth mentioning that I do not see a flush on a Writable which could trigger all data to be written - let me know if you think there is a way to trigger data flush.
As I mentioned earlier, the base library googleapis/nodejs-logging is designed to use callbacks as a tracking mechanism (since awaiting on every call could be problematic). We also have a solution for printing structured logging to STDOUT as alternative which could be used with logging agents in a cloud.
So based on said before, I believe the only way to fully address the issue is to return callback functionality to Winston library which is tracked by 2095. This would be also a right step to maintain backward compatibility on a library which I believe should be a common practice for SDKs used by many users.
Please let me know what do you think about it. Feel free to reactivate a work item if you feel this could be somehow addressed by some fix in this library.

[elyobo]

@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?