Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

process: flush stdout/stderr upon process.exit() #6773

Closed
wants to merge 1 commit into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions deps/uv/include/uv.h
Original file line number Diff line number Diff line change
Expand Up @@ -483,6 +483,8 @@ UV_EXTERN int uv_try_write(uv_stream_t* handle,
const uv_buf_t bufs[],
unsigned int nbufs);

UV_EXTERN int uv_flush_sync(uv_stream_t* stream);

/* uv_write_t is a subclass of uv_req_t. */
struct uv_write_s {
UV_REQ_FIELDS
Expand Down
15 changes: 15 additions & 0 deletions deps/uv/src/unix/stream.c
Original file line number Diff line number Diff line change
Expand Up @@ -1625,6 +1625,21 @@ void uv__stream_close(uv_stream_t* handle) {
}


/* Have stream block and then synchronously flush queued writes.
* This function works without an event loop.
* Intended to be used just prior to exit().
* Returns 0 on success, non-zero on failure.
*/
int uv_flush_sync(uv_stream_t* stream) {
int rc = uv_stream_set_blocking(stream, 1);
if (rc == 0) {
uv__write(stream);
rc = (int)stream->write_queue_size;
}
return rc;
}


int uv_stream_set_blocking(uv_stream_t* handle, int blocking) {
/* Don't need to check the file descriptor, uv__nonblock()
* will fail with EBADF if it's not valid.
Expand Down
62 changes: 62 additions & 0 deletions lib/internal/process.js
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,69 @@ function setupKillAndExit() {
process._exiting = true;
process.emit('exit', process.exitCode || 0);
}

// Flush stdio streams prior to exit.
// `flushSync` not present if stream redirected to file in shell.
flushSync(process.stdout);
flushSync(process.stderr);

process.reallyExit(process.exitCode || 0);

function flushSync(stream) {

// Behavior of this function outside of process.exit() is undefined
// due to the following factors:
// * Stream fd may be blocking after this call.
// * In the event of an incomplete flush pending buffered write
// requests may be truncated.
// * No return code.

if (stream._writev)
return;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why are you bailing out if there is _writev?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because stdio didn't use it, and frankly I did not understand it. If usage expands beyond stdout and stderr, please feel free to improve.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I assume if there is _writev it already flushes the writes, but I have not checked. (Was kzc's code)

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I assume if there is _writev it already flushes the writes, but I have not checked. (Was kzc's code)

It's still buffered in stream module - just in a different form. Patches supporting _writev flushing welcome.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In my defence this issue involved quite a few subsystems, so please forgive me for not understanding how it all works. ;-)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In my defence this issue involved quite a few subsystems, so please forgive me for not understanding how it all works.

@kzc I think node is too big for anyone to understand how it all works on all its details.

I think _writev should be handled, but in the worst case we should put a big comment in how we skip streams with _writev.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mcollina Either way works for me - as long as @Fishrock123 does it. ;-)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm, I'll take a look.


var handle = stream._handle;
if (!handle || !handle.flushSync)
return;

var fd = handle.fd;
if (typeof fd !== 'number' || fd < 0)
return;

// FIXME: late module resolution avoids cross require problem
const fs = require('fs');

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: unnecessary blank line

const Buffer = require('buffer');

// Queued libuv writes must be flushed first.
// Note: fd will set to blocking after handle.flushSync()
if (handle.flushSync() !== 0) {
// bad fd or write queue for libuv stream not entirely flushed
return;
}

// then the queued stream chunks can be flushed
var state = stream._writableState;
var entry = state.bufferedRequest;
while (entry) {
var chunk = entry.chunk;
if (!(chunk instanceof Buffer)) {
chunk = Buffer.from(chunk, entry.encoding);
}
// Note: fd is blocking at this point
var written = fs.writeSync(fd, chunk, 0, chunk.length);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Fishrock123 @kzc this stream is a net.Socket, but we use fs.writeSync to handle this case. This needs to be really well explained somewhere. I understand what's going on (they are both file descriptors), but probably TTYs needs to be rethinked a bit.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

but probably TTYs needs to be rethinked a bit.

I agree, the current code for all these different things is a mess, but that's not something we are in a position to immediately refactor I think.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree, the current code for all these different things is a mess, but that's not something we are in a position to immediately refactor I think.

As long as this activity is planned for v7/v8, I am happy for any short-term fixes. But this needs to really be rethinked.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

regarding fs.writeSync, I was just using what was available and known to work. Should it be in a different module? Yeah, probably.

I just put together a working proof of concept just to get the ball rolling and give people a concrete proposal to build upon. Feel free to improve this code.

if (written !== chunk.length) {
// stream chunk not flushed entirely - stop writing.
// FIXME: buffered request queue should be repaired here
// rather than being truncated after loop break
break;
}
entry = entry.next;
}

state.bufferedRequestCount = 0;
state.bufferedRequest = null;
state.lastBufferedRequest = null;
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not fond of this approach, as we are messing with the stream internals outside of streams. If we want this to happen nicely, we should support it inside the fs streams (I think stdio and stderr are from fs, correct me if I am wrong).

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had initially put this code in _stream_writable.js for that reason. But please read the caveats at the top of this function:

 +      // Behavior of this function outside of process.exit() is undefined
 +      // due to the following factors:
 +      // * Stream fd may be blocking after this call.
 +      // * In the event of an incomplete flush pending buffered write
 +      //   requests may be truncated.
 +      // * No return code.

If this were rolled into stream proper, these issues would have to be addressed. Either that or make this an underscore prefixed function indicating internal use only.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These does not belong in _stream_writable, because that is generic and not related to fs.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mcollina stdio is a fs stream only if piped to/from a file. IIRC those only block and aren't a problem.

So we are talking about pipes or TTYs which both use net.Socket, although I disagree this really belongs there?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Fishrock123 it belongs there more than here. We need to be able to test this "in isolation" and provide it as a feature in node, rather than a rigged bugfix for a regression. That might come in a future PR if we need to get this out quickly.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not certain we do, actually, but this is probably out of scope until after we fix this? Maybe? Idk,

};

process.kill = function(pid, sig) {
Expand Down
17 changes: 17 additions & 0 deletions src/stream_wrap.cc
Original file line number Diff line number Diff line change
Expand Up @@ -77,6 +77,7 @@ StreamWrap::StreamWrap(Environment* env,
void StreamWrap::AddMethods(Environment* env,
v8::Local<v8::FunctionTemplate> target,
int flags) {
env->SetProtoMethod(target, "flushSync", FlushSync);
env->SetProtoMethod(target, "setBlocking", SetBlocking);
StreamBase::AddMethods<StreamWrap>(env, target, flags);
}
Expand Down Expand Up @@ -273,6 +274,22 @@ void StreamWrap::SetBlocking(const FunctionCallbackInfo<Value>& args) {
}


void StreamWrap::FlushSync(const FunctionCallbackInfo<Value>& args) {
StreamWrap* wrap = Unwrap<StreamWrap>(args.Holder());

if (!wrap->IsAlive())
return args.GetReturnValue().Set(UV_EINVAL);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While I'm aware that SetBlocking also uses UV_EINVAL on this, it definitely feels like the wrong error code to be using in this case. Ah well tho.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any suggestions? :D

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It was copied from StreamWrap::SetBlocking() just above that function.


#if defined(_WIN32)
int rc = 0;
#else
int rc = uv_flush_sync(wrap->stream());
#endif

args.GetReturnValue().Set(rc);
}


int StreamWrap::DoShutdown(ShutdownWrap* req_wrap) {
int err;
err = uv_shutdown(&req_wrap->req_, stream(), AfterShutdown);
Expand Down
1 change: 1 addition & 0 deletions src/stream_wrap.h
Original file line number Diff line number Diff line change
Expand Up @@ -72,6 +72,7 @@ class StreamWrap : public HandleWrap, public StreamBase {
int flags = StreamBase::kFlagNone);

private:
static void FlushSync(const v8::FunctionCallbackInfo<v8::Value>& args);
static void SetBlocking(const v8::FunctionCallbackInfo<v8::Value>& args);

// Callbacks for libuv
Expand Down
1 change: 0 additions & 1 deletion test/known_issues/known_issues.status
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,6 @@ prefix known_issues
[true] # This section applies to all platforms

[$system==win32]
test-stdout-buffer-flush-on-exit: SKIP

[$system==linux]

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -15,13 +15,11 @@ if (process.argv[2] === 'child') {
process.exit();
}

[22, 21, 20, 19, 18, 17, 16, 16, 17, 18, 19, 20, 21, 22].forEach((exponent) => {
[22, 16].forEach((exponent) => {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Even [16, 18] would be adequate:

> 'foo bar baz quux quuz aaa bbb ccc'.repeat(Math.pow(2, 16)).length
2162688
> 'foo bar baz quux quuz aaa bbb ccc'.repeat(Math.pow(2, 18)).length
8650752

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Depends on whether or not you want the test to fail reliably on all (supported) platforms when there's a problem.

If you want it to fail reliably on all the platforms on our current CI when there's a problem, then you need a lot of numbers in that Array because the test is non-deterministic and will pass if the buffer manages to flush before the program exits.

Unfortunately, that may make the test take waaay too long when it succeeds. (I don't actually know how long it takes to run on a Raspberry Pi, for example.)

However, if you're happy just having it fail most of the time--but not all the time!--when a problem is introduced, then yes, two numbers in that Array will probably suffice.

If anyone has ideas for making the test deterministic, that would be great. Not sure it's really possible, short of test doubles and making it a unit test rather than a test-the-actual-system test...

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Depends on whether or not you want the test to fail reliably on all (supported) platforms when there's a problem.

This test used to be an expected-fail. This PR moved it into the normal test section as it should be passing/deterministic.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kzc If there is no bug for it to detect, yes, it will pass deterministically. However, if stdout is not being flushed on exit, it will not fail deterministically. It will fail most of the time. That's the (potential) problem with getting rid of all those test iterations. Of course, there is a cost/benefit calculation to make here and it could be that the right thing to do is to get rid of most or all of those iterations. (I suspect that's the case.)

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

However, if stdout is not being flushed on exit, it will not fail deterministically. It will fail most of the time.

Yes, that was the intention. If stdio is not flushed the new test in this PR should fail.

We're likely in agreement but our messaging is probably being misinterpreted between us.

Copy link
Member

@Trott Trott May 17, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What I'm trying to say is that if a bug is introduced at a later date such that stdout is not flushed, the best thing is if the test will fail 100% of the time in that situation. With the change in this PR, if such a bug is introduced at a later date, it will not fail 100% of the time. EDIT: By "not fail 100% of the time", I mean "will fail only 80% or 90% or 75% or something like that". I do not mean "succeed all the time". Sorry about the ambiguity.

So, unless there's a compelling reason to make the change to the test file (reducing the number of test cases in the array), I would recommend against it. (However, there probably is a compelling reason, such as "If we don't make the change, the test times out on CI half the time." That's pretty compelling.)

Copy link

@kzc kzc May 17, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, unless there's a compelling reason to make the change to the test file (reducing the number of test cases in the array

Before this PR when the test case in question was an expected-fail it did fail most (all?) of the time because only around 64KB of data was processed per step instead of the 138MB for just one step of the test.

When this test was converted to a passing test it was processing on the order of 500MB+ which I think is a bit excessive. It was making some test systems time out.

I understand what you're saying. I don't disagree with you. But there is some middle ground.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It was making some test systems time out.

Yeah, I figured something like that was going on. Changing the test this way to avoid that problem sounds good to me (of course).

const bigNum = Math.pow(2, exponent);
const longLine = lineSeed.repeat(bigNum);
const cmd = `${process.execPath} ${__filename} child ${exponent} ${bigNum}`;
const stdout = execSync(cmd).toString().trim();

assert.strictEqual(stdout, longLine, `failed with exponent ${exponent}`);
});