_writev doesn't wait for chunk log callbacks before calling its own callback

[laganojunior]

Function in question:

winston-transport/index.js

Lines 117 to 166 in 46db8f3

	TransportStream.prototype._writev = function _writev(chunks, callback) {
	if (this.logv) {
	const infos = chunks.filter(this._accept, this);
	if (!infos.length) {
	return callback(null);
	}
	// Remark (indexzero): from a performance perspective if Transport
	// implementers do choose to implement logv should we make it their
	// responsibility to invoke their format?
	return this.logv(infos, callback);
	}
	for (let i = 0; i < chunks.length; i++) {
	if (!this._accept(chunks[i])) continue;
	if (chunks[i].chunk && !this.format) {
	this.log(chunks[i].chunk, chunks[i].callback);
	continue;
	}
	let errState;
	let transformed;
	// We trap(and re-throw) any errors generated by the user-provided format, but also
	// guarantee that the streams callback is invoked so that we can continue flowing.
	try {
	transformed = this.format.transform(
	Object.assign({}, chunks[i].chunk),
	this.format.options
	);
	} catch (err) {
	errState = err;
	}
	if (errState || !transformed) {
	// eslint-disable-next-line callback-return
	chunks[i].callback();
	if (errState) {
	// eslint-disable-next-line callback-return
	callback(null);
	throw errState;
	}
	} else {
	this.log(transformed, chunks[i].callback);
	}
	}
	return callback(null);
	};

This implementation of _writev calls callback before all the callbacks of this.log(chunks[i]...) are called. This means that the transport stream may seem finished even if the underlying implementation hasn't finished writing out all the chunks yet.

We ran into this when we saw that during tests that when we close a winston logger, we would sometimes see a finish event be emitted from the logger before our transport finished writing its files.

We're currently working around this by implementing our own logv for our transport since that gives us control over calling the callback to _writev only when each chunk is finished.

I'm happy to try to construct a minimal example and/or provide a merge request to fix this. I just want to check here if this is something that's done by design or otherwise known.

[laganojunior]

This may be related to other people reporting similar observations of 'finished' events being emitted early?

• logging methods no longer take a callback, can't reliably use it in some environments (AWS Lambda) winston#1250 (comment)
• transports.File is not flushing on end. winston#1504

[laganojunior]

Also this too:

winstonjs/winston#228 (comment)

I imagine this workaround works because they're bypassing the finished event of TransportStream and instead using the finished event of the underlying file write stream which probably does wait for file writes before emitting finished. Unfortunately, this workaround probably doesn't work for generic custom transports unless they happen to define an internal stream variable.

[laganojunior]

Made a commit to add a test to demonstrate the issue and a patch to fix it. #50

[danielweck]

Yes, you are correct, my workaround ; which is itself inspired by other implementations reported in the issue tracker ; relies on the file Transport allowing access to the "private" _stream event emitter:

transport._stream.once('finish', finishedCallback); /* transport._stream.end(); does not flush pending writes */

(instead of transport.once('finish', finishedCallback); transport.close();, which currently isn't a reliable mechanism for a clean detection of Winston completion)

The worst part of this hack is the necessity to run the workaround for each registered transport, but as I could not find a reliable Winston accessor I had to allocate a _transports variable (for (const transport of _transports) { ... }).

I am sure there is a better way to implement this, but whatever worked at the time did the job for me. I simply had no time to look into Winston's internals.

winstonjs/winston#228 (comment)

[laganojunior]

@indexzero How do I go about asking someone to look at this?

[derekngo]

+1