fix(logger): prevent "write after end" error during shutdown#2599
Open
mldangelo wants to merge 1 commit intowinstonjs:masterfrom
Open
fix(logger): prevent "write after end" error during shutdown#2599mldangelo wants to merge 1 commit intowinstonjs:masterfrom
mldangelo wants to merge 1 commit intowinstonjs:masterfrom
Conversation
79d17e0 to
e393f86
Compare
When logger.end() is called during heavy logging, a race condition can occur where the readable buffer still contains data when transports are ended, causing 'write after end' errors. The issue is in _final(): the pipe from Logger to transports is asynchronous - data pushed via _transform() goes to the readable buffer, and the pipe reads from it to write to transports. If transport.end() is called while the readable buffer still has data, the pipe tries to write to an ending transport. The fix uses an event-driven approach: listen for 'data' events which fire as the pipe consumes data from the readable buffer. When the buffer empties, we can safely end transports. This is more efficient than polling and trusts the Node.js stream mechanism. Fixes: winstonjs#2219
e393f86 to
569d0ba
Compare
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Fixes the "write after end" race condition that occurs when calling
logger.end()during heavy logging.This is a companion fix to #2594 (which addressed File transport flushing). While #2594 fixed data loss at the transport level, this PR fixes a race condition at the Logger level that can cause "write after end" errors.
Problem
When
logger.end()is called, the_final()method immediately callstransport.end()on all transports. However, the Logger's readable buffer may still contain data that needs to be piped to transports. Sincetransport.end()sets the transport'sstate.ending = true, any subsequent pipe writes fail with "write after end".Reproduction scenario:
logger.end()immediately_final()callingtransport.end()Solution
The fix uses an event-driven approach to ensure the readable buffer is fully drained before ending transports:
_final()is called, check if the readable buffer is empty'data'events which fire as the pipe consumes data from the bufferthis._readableState.length === 0), remove the listener and end transportsThis approach is:
Testing
Added new test file
test/unit/winston/write-after-end.test.jswith 10 comprehensive test cases:onDatalistener)_finalruns)Tests 8-10 use a custom
SlowTransportto simulate backpressure and ensure the event-driven drain path is exercised (not just the fast "buffer already empty" path).All 244 existing tests pass.
Related Issues
Fixes #2219
Related to #2594 - Together these two fixes ensure reliable logging shutdown: #2594 ensures File transport data reaches disk, and this PR ensures all buffered data reaches transports before they end.
Checklist