-
Notifications
You must be signed in to change notification settings - Fork 30.5k
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
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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; | ||
|
||
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'); | ||
|
||
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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); | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. @Fishrock123 @kzc this stream is a There was a problem hiding this comment. Choose a reason for hiding this commentThe 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. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. regarding 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; | ||
} | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 There was a problem hiding this comment. Choose a reason for hiding this commentThe 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:
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. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. These does not belong in There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. @mcollina stdio is a So we are talking about pipes or TTYs which both use There was a problem hiding this comment. Choose a reason for hiding this commentThe 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. There was a problem hiding this comment. Choose a reason for hiding this commentThe 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) { | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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); | ||
} | ||
|
@@ -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); | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. While I'm aware that SetBlocking also uses There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Any suggestions? :D There was a problem hiding this comment. Choose a reason for hiding this commentThe 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); | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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) => { | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Even
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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... There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
This test used to be an expected-fail. This PR moved it into the normal test section as it should be passing/deterministic. There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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. There was a problem hiding this comment. Choose a reason for hiding this commentThe 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.) There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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}`); | ||
}); | ||
|
||
|
There was a problem hiding this comment.
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
?There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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)There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It's still buffered in stream module - just in a different form. Patches supporting
_writev
flushing welcome.There was a problem hiding this comment.
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. ;-)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@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
.There was a problem hiding this comment.
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. ;-)
There was a problem hiding this comment.
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.