Child process and output management #392

fitzgen · 2018-10-04T22:04:00Z

Fix #287 but also all the instances of this that we might ever run into.

fitzgen · 2018-10-04T22:11:25Z

Just a note that this last commit started ballooning in size because it involved propagating failure::Error everywhere so I could use context methods :-/

fitzgen · 2018-10-04T22:16:42Z

First build, that has to build the wasm-bindgen macro:

Rebuilding again, which is super fast:

ashleygwilliams · 2018-10-04T22:23:17Z

@fitzgen does this also cover #280 ? i'd really prefer if it didn't - but understand if that's tough. we had a collaborator ask to take #280 on in IRC today, so this is also why in the future- claiming issues and opening WIP prs asap is best.

alexcrichton

I really like the idea of ensuring that all output is verbosely recorded in log files, that's something we should definitely pick up on in Cargo!

Also just to make sure, do you have an idea of how we'll fix the colors issue with this strategy? I'd want to make sure that we're forward compatible with adding colors.

alexcrichton · 2018-10-05T03:39:07Z

src/child.rs

+            }
+        }
+
+        thread::yield_now();


I think we'll definitely want a synchronization solution before this lands to ensure that we're not just eating a core spin-waiting while cargo tries to finish. We don't actually have to try_wait or wait on the process at all until stdout/stderr are closed, so we can wait until those are done to do that and otherwise just loop around receiving on the channel (which we can do with a timeout as well)

alexcrichton · 2018-10-05T03:40:44Z

src/child.rs

+    // waiting on the child process.
+
+    let stdout_handle = thread::spawn(move || {
+        for line in stdout.lines() {


I've had unfortunately bad experiences in the past line-buffering stdout. An example of the bad behavior is that libtest in quiet mode used to simply print a .-per-test and then at the very end it'd print a newline. This logic means that no output would happen until the very very end where everything comes out all at once. We fixed this bug for Rust in the past, and I think a similar fix could be applied here where this just streams data as it comes, and the data processor specially handles newlines in the stream to append output.

alexcrichton · 2018-10-05T03:42:37Z

src/child.rs

+{
+    let message = match out {
+        Ok(Output::Stdout(line)) => format!("{} (stdout): {}", command_name, line.as_ref()),
+        Ok(Output::Stderr(line)) => format!("{} (stderr): {}", command_name, line.as_ref()),


I'm not sure we want to prefix things with (stderr) and/or (stdout) as it may quickly add noise to the output. Do you think it's worth differentiating? (people may be alarmed, for example, that Cargo always prints to stderr despite it typically not generating errors).

Additionally, the command_name may be best to print at the very beginning? Something like Running ... like in Cargo so it's there if necessary and otherwise not taking up too much space.

alexcrichton · 2018-10-05T03:45:57Z

src/child.rs

+    let mut is_long_running = false;
+
+    loop {
+        if !is_long_running && taking_too_long(since) {


I'm not sure I'm 100% convinced this strategy of swallowing the first 200ms of output will work out in the long run. In the worst case a tool finishes very quickly but some crucial information it prints to stdout/stderr is lost. I don't think that wasm-pack invokes many tools like that today though? This is largely just in terms of future concerns.

In general I feel we should depend on tools responsibly not generating lots of output that's not necessary. Like adding a wasm target with rustup which is already there should produce zero output, but I'm not sure that we should gauge that based on the 200ms delay here. (similarly Cargo's "fresh" output of "you compiled this in 0.2s" is something we'd want to hide, but there isn't a great way to do that in Cargo right now unfortunately).

So you're saying you think we should always display the child's output unconditionally?

After talking over lunch I think the conclusion was that we should probably remove this yeah, and have the main thread block on dispatching output received from the channel

For context:

We really don't want to swallow warnings from rustc, even when cargo build exits super quickly.

That general scenario could play out with other CLI tools too

The noisiest parts of the wasm-pack build output are actually things like "checking if you have wasm32-u-u installed" when 99% of the time the user already does. For this particular case, it is wasm-pack itself printing this out, not a child process, so this module is unaffected.

Therefore, we should always print all output, regardless of time the child takes to run.

For that last bullet point, and any kind of "install X if it isn't already here", we only want to print in the case where X isn't already installed and we are going to commence with installing it.

Er and to elaborate a bit! I think it's fine to leave this in if it's just hypothetical things I'm worried about and I can always file a follow-up issue, but one concrete use case we discovered which may turn out badly is a rustc invocation which prints a compiler warning (like a diagnostic) but finishes in under 200ms. I think the logic here would swallow up the warning and avoid it getting printed.

Er oops sorry, double post at the same time!

alexcrichton · 2018-10-05T03:46:58Z

src/child.rs

+                return Ok(stdout);
+            } else {
+                let msg = format!("`{}` did not exit successfully", command_name);
+                return Err(Error::cli(&msg, stderr.into(), exit).into());


This'll want to ferry along stdout as well, want to be sure to not lose anything whenever we print failure messages!

I think it'd also be good to carry along the full command line here as opposed to just the name of the command to ensure that all the arguments are in the error message too

ashleygwilliams

generally speaking, i agree with all of @alexcrichton 's points. do we know what happens in this if we don't have the magic 200ms check? i'd be curious how verbose it is. will give this a closer look once you've responded to alex's stuff.

Also don't buffer the child's stdout and stderr.

fitzgen · 2018-10-05T22:48:04Z

Ok, new commits make it so that

we don't do the 200ms thing, and instead always send child output to the console,
we don't line buffer the child's stdout and stderr
we maintain the child's stdout in the Error::Cli variant

fitzgen · 2018-10-05T22:50:52Z

Note: we will want follow up PRs to allow making certain commands run in "quiet" mode where we don't dump their output to our console, but (a) I think having these switched defaults is better in the general case, and (b) we can do that as a follow up issue.

fitzgen · 2018-10-05T22:51:43Z

Notably, we still want "quiet" commands to have their output end up in the logs, just not the console.

ashleygwilliams

so my only real feedback now is that we have a lot of mut when defining the commands- in some cases we conditionally change what command is run, but for many we don't. do they still need to be mut?

ashleygwilliams · 2018-10-09T13:35:26Z

src/bindgen.rs

+    crate_path: &Path,
+    version: &str,
+) -> Result<(), failure::Error> {
+    let mut cmd = Command::new("cargo");


is this mut here necessary?

ashleygwilliams · 2018-10-09T13:35:44Z

src/bindgen.rs

-        .filter(|output| output.status.success())
-        .map(|output| {
-            String::from_utf8_lossy(&output.stdout)
+    let mut cmd = Command::new(bindgen_path);


is this mut here necessary?

ashleygwilliams · 2018-10-09T13:35:56Z

src/build.rs

-    } else {
-        Ok(())
-    }
+    let mut cmd = Command::new("rustup");


is this mut here necessary?

ashleygwilliams · 2018-10-09T13:36:54Z

src/npm.rs

-        Ok(())
-    }
+pub fn npm_pack(log: &Logger, path: &str) -> Result<(), failure::Error> {
+    let mut cmd = Command::new("npm");


is this mut necessary?

fitzgen · 2018-10-09T16:36:36Z

The muts are necessary because the methods for adding arguments etc to a command take &mut self.

Change to INFO when alerting users about missing fields in Cargo.toml Combine filed missing messages into one INFO line Fix bad formating Merge pull request rustwasm#394 from mstallmo/master Change to INFO when alerting users about missing fields Cargo.toml child: Always print everything to our output Also don't buffer the child's stdout and stderr. error: Add stdout to the `Error::Cli` variant refactor: Return failure::Error instead of wasm_pack::error::Error refactor: Import self and use full module path for failure Use full module path for failure to be consistent since it's used like that in other modules. refactor: Return failure::Error instead of wasm_pack::error::Error chore: Run rustfmt chore: Run rustfmt Merge pull request rustwasm#392 from fitzgen/child-process-and-output-management Child process and output management Merge pull request rustwasm#401 from drager/return-failure-error Return `Result<T, failure::Error>` instead of `Result<T, wasm_pack::error::Error>` v0.5.1 Merge pull request rustwasm#404 from rustwasm/0.5.1 v0.5.1 feat(website): bump vers Merge pull request rustwasm#405 from rustwasm/website-update feat(website): bump vers test(command/build): add a test for build command useing local wasm-bindgen Fix typo in test function name for copying the README bugfix(bindgen-target-dir): use PathBuf to join the old code are hard coded path with "/", which may cause error on windows, thus changing to use PathBuf.join. fixing rustwasm#414 change for cargo_metadata Merge branch 'master' into test-build-for-example Merge pull request rustwasm#408 from huangjj27/test-build-for-example test(command/build): add a test for build command Merge pull request rustwasm#412 from mstallmo/typo-fix Fix typo in test function name for copying the README Merge branch 'master' into fix-canonical-paths-on-windows this change is not related to this PR use absolutize remove unused use cargo fmt

fitzgen added 2 commits October 4, 2018 14:59

Create a module for running child processes

6e8e8a6

test: Add a utility for creating null loggers for tests

4fd08dc

fitzgen requested review from alexcrichton and ashleygwilliams October 4, 2018 22:04

Use child::run for spawning child processes everywhere

2fa961d

fitzgen force-pushed the child-process-and-output-management branch from 8ffc5ad to 2fa961d Compare October 4, 2018 22:12

fitzgen added the needs review label Oct 4, 2018

fitzgen added this to the 0.6.0 milestone Oct 4, 2018

fitzgen mentioned this pull request Oct 4, 2018

Most fallible methods should return Result<T, failure::Error> instead of Result<T, wasm_pack::error::Error> #280

Closed

alexcrichton reviewed Oct 5, 2018

View reviewed changes

ashleygwilliams reviewed Oct 5, 2018

View reviewed changes

fitzgen added 2 commits October 5, 2018 15:38

child: Always print everything to our output

1621d18

Also don't buffer the child's stdout and stderr.

error: Add stdout to the Error::Cli variant

e9276e0

alexcrichton approved these changes Oct 5, 2018

View reviewed changes

drager mentioned this pull request Oct 7, 2018

Return Result<T, failure::Error> instead of Result<T, wasm_pack::error::Error> #401

Merged

ashleygwilliams reviewed Oct 9, 2018

View reviewed changes

ashleygwilliams merged commit 2ca946e into rustwasm:master Oct 9, 2018

ashleygwilliams modified the milestones: 0.6.0, 0.5.1 Oct 9, 2018

ashleygwilliams mentioned this pull request Oct 9, 2018

wasm-pack test does not print test results on failure #400

Closed

fitzgen mentioned this pull request Oct 9, 2018

Error messages for spawned processes don't include exit status and/or stdout #291

Closed

konstin mentioned this pull request Oct 10, 2018

[WIP] Use --message-format=json to fix #333 #340

Closed

3 tasks

danwilhelm mentioned this pull request Jan 11, 2019

Empty input prompt when 'login' #486

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Child process and output management #392

Child process and output management #392

fitzgen commented Oct 4, 2018

fitzgen commented Oct 4, 2018

fitzgen commented Oct 4, 2018

ashleygwilliams commented Oct 4, 2018

alexcrichton left a comment

alexcrichton Oct 5, 2018

alexcrichton Oct 5, 2018

alexcrichton Oct 5, 2018

alexcrichton Oct 5, 2018

fitzgen Oct 5, 2018

alexcrichton Oct 5, 2018

fitzgen Oct 5, 2018

alexcrichton Oct 5, 2018

alexcrichton Oct 5, 2018

alexcrichton Oct 5, 2018

ashleygwilliams left a comment

fitzgen commented Oct 5, 2018

fitzgen commented Oct 5, 2018

fitzgen commented Oct 5, 2018

ashleygwilliams left a comment

ashleygwilliams Oct 9, 2018

ashleygwilliams Oct 9, 2018

ashleygwilliams Oct 9, 2018

ashleygwilliams Oct 9, 2018

fitzgen commented Oct 9, 2018

Child process and output management #392

Child process and output management #392

Conversation

fitzgen commented Oct 4, 2018

fitzgen commented Oct 4, 2018

fitzgen commented Oct 4, 2018

ashleygwilliams commented Oct 4, 2018

alexcrichton left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ashleygwilliams left a comment

Choose a reason for hiding this comment

fitzgen commented Oct 5, 2018

fitzgen commented Oct 5, 2018

fitzgen commented Oct 5, 2018

ashleygwilliams left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fitzgen commented Oct 9, 2018