Request not to suppress the output of build script

m13253 commented 9 years ago

Sometimes the build script may fail, leaving some useful information (such as the output of GCC) in stdout or stderr. However, I found that Cargo is not displaying the output of my build script.

I request a feature, that the stderr is displayed by default and stdout is displayed when --verbose is on.

Thanks.

alexcrichton commented 9 years ago

This has come up before, and the reason it's all suppressed by default is to tone down the noise of builds. If you're not seeing the output when the script fails, that's definitely a bug though. Do you have an example of this occurring?

m13253 commented 9 years ago

The exmple

I have copied the build.rs from http://doc.crates.io/build-script.html#case-study:-building-some-native-code , as is listed below:

// build.rs

use std::io::Command;
use std::os;

fn main() {
    let out_dir = os::getenv("OUT_DIR").unwrap();

    // note that there are a number of downsides to this approach, the comments
    // below detail how to improve the portability of these commands.
    Command::new("gcc").args(&["src/hello.c", "-c", "-o"])
                       .arg(format!("{}/hello.o", out_dir))
                       .status().unwrap();
    Command::new("ar").args(&["crus", "libhello.a", "hello.o"])
                      .cwd(&Path::new(&out_dir))
                      .status().unwrap();

    println!("cargo:rustc-flags=-L {} -l hello:static", out_dir);
}

Note that the script does not check the status code of GCC or AR.

The problem

And it happened that the source does not compile. However Cargo printed out NOTHING helpful to diagnose this problem:

$ cargo build --verbose
   Compiling hello v0.0.1 (file:///tmp/hello)
     Running `rustc build.rs --crate-name build-script-build --crate-type bin -C prefer-dynamic -g --out-dir /tmp/hello/target/build/hello-77de99f14f3cb8ca --emit=dep-info,link -L /tmp/hello/target -L /tmp/hello/target/deps`
     Running `/tmp/hello/target/build/hello-77de99f14f3cb8ca/build-script-build`
     Running `rustc /tmp/hello/src/lib.rs --crate-name hello --crate-type lib -g -C metadata=77de99f14f3cb8ca -C extra-filename=-77de99f14f3cb8ca --out-dir /tmp/hello/target --emit=dep-info,link -L /tmp/hello/target -L /tmp/hello/target/deps -L /tmp/hello/target/build/hello-77de99f14f3cb8ca/out -l hello:static`
error: could not find native static library `hello`, perhaps an -L flag is missing?
Could not compile `hello`.

Caused by:
  Process didn't exit successfully: `rustc /tmp/hello/src/lib.rs --crate-name hello --crate-type lib -g -C metadata=77de99f14f3cb8ca -C extra-filename=-77de99f14f3cb8ca --out-dir /tmp/hello/target --emit=dep-info,link -L /tmp/hello/target -L /tmp/hello/target/deps -L /tmp/hello/target/build/hello-77de99f14f3cb8ca/out -l hello:static` (status=101)

I spent an extra hour figuring out where the problem is, having add some extra code to redirect the output of GCC to a log file.

I admit that there is a bug in the build script that the status code should be checked. But anyway, there need to be a way to debug this, or it will be a pain if this happens on a client's computer, causing a complaining mail.

If the user says `--verbose`, do verbose.

I know that printing a lot of garbage messes the terminal. So it is reasonable that the output of build script is suppressed.

But why continuing to suppress the output even if the user says --verbose?

I have read in issue #985 that it may be too noisy with --verbose. That's build.rs's stuff. build.rs should filter the output so only useful messages are shown, which is not Cargo's duty since Cargo know nothing about which message is useful.

Compilation takes time, user may want to see what is going on

In the documentation of Cargo, it explained that build scripts may find an extra library or build a library itself.

On the latter case, it may take time. It is better to tell the user why the compilation sticks at this point.

GCC warnings are really useful

If Cargo displays the output only when the build fails, the GCC warnings will be suppressed.

Just like Rust lints, GCC warnings is usually useful to improve the security of the code.

My idea

stderr is always on, and stdout is off unless --verbose is on
Or alternatively, introduce verbosity level

(P.S. I am really sorry that this post is so long and somewhat offensive)

alexcrichton commented 9 years ago

I think that I should update the example listed to also check that the return code is 0, the real bug here is that the build script should fail if the return code is not 0, which would cause output to show up.

Some other points:

I think I'd probably be fine with a verbosity level. I think that the currently level of --verbose is adequate for most situations, but certainly not all!
If you'd like to see warnings from GCC for something like security, you should really consider turning them into errors rather than relying on Cargo to output them.
I'd be fine with breaking a package down and saying "Running build script" and "building" instead of just one "building foo", but the default set of output for Cargo should be quite small and readable to the extent that it should not output the full output of the build script.

m13253 commented 9 years ago

I think that I should update the example listed to also check that the return code is 0, the real bug here is that the build script should fail if the return code is not 0, which would cause output to show up.

I have already stated that there is a bug in the build script. However if Cargo provides no way to debug this, it will be much more difficult to figure out the build script is wrong. (Since Cargo says "error in linking", most people would probably check the linker at first instead of the build script)

If you'd like to see warnings from GCC for something like security, you should really consider turning them into errors rather than relying on Cargo to output them.

Why aren't Rust warnings treated like this? This is a discrimination against C.

Some other points:

In Rust standard library, std::io::Command suppresses and pipes the output of child processes by default. So if build.rs prints something, it means that he has written extra code to fetch the output GCC and he really wants to print something. Thus, the filter is already done at build.rs side. Cargo no longer need to do filtering if the user asks not to.
Also, if something goes wrong (for example, the build.rs succeed but the linker failed) and a user submitted a bug report to me, which log should I ask him to attach? Probably --verbose is best option. I knew there are ./target/build/*/out but they are spread all around, inconvenient to fit in an email attachment.
Why is --verbose printing out all the command lines but not the output of those child processes? If --verbose is not verbose enough, how can I make Cargo as verbose as it can?
As is known, PyPy is printing out an image of Mandelbrot (one pixel at a time to mean a successful compilation of a module) to entertain the user during the 3-hour compilation. If a library takes an hour to compile (let's say libavformat or libgtk+ or PyPy), why can't build.rs print a simple progress bar?

I'm not convening you to let out the output of build.rs with default configuration. But I request you, please, to let out the output when --verbose is on.

P.S. Maybe a combination of --quiet and --verbose option satisfy some needs?

shadowmint commented 9 years ago

Idly, I've also faced this issue, but broadly speaking I agree with @alexcrichton on it.

There's no way to 'stream' output from a process. It just can't happen. The Process API doesn't support it. The best you can do is block on stdout and stderr in a thread and wait until the process dies. Without an async io story, the very idea of streaming output from the build command is just a non-starter.

...and without that, I don't really see much benefit from being able to push output to stdout on success.

I mean, what's really the use case for 'This C compile passed, but I want to display some output messages'?

If you want to do debugging, just set the build.rs to always fail and it'll print the output to stderr.

If you want a more comprehensive logging solution (eg. log output of the entire build command to a file) you can use a 3rd party logging library for it.

I feel like if you allow build scripts to push output to stdout, everyone will start doing it, and it'll clutter the cargo build --verbose output like crazy.

(To be fair though, cargo does occasionally just hang for various reasons, and it is quite useful to stream build output to make sure, for example, xcode hasn't just spazzed out and stopped doing anything without killing the process, which it does, for example, when building libuv sometimes. ...but like I said, without streaming, there's no way of having any idea what's going on anyway, so... /shrug)

m13253 commented 9 years ago

@shadowmint

Thank you for your note. I have read the code at cargo::ops::cargo_rustc::custom_build::parse.

It seems that Cargo pipes out all the output to a file, read it into the memory as a string and process it. The implementation is fairly simple and straight. However I have two questions appended:

Can't pipe work without async API? Doesn't starting a process and waiting at one end of the pipe work?
Since Cargo only cares about stdout, why don't set InheritFd(2) on stderr on --verbose?

shadowmint commented 9 years ago

@m13253 You can block on the pipe, but that locks the entire thread; cargo runs multiple commands at the same time, and this would halt the entire process it while it performs the build step.

Technically you could create a solution I suppose, where you created a separate thread for each pipe, and used Sender & Receiver to message pass data back to the 'parent' thread. I'm not aware of any existing implementation of that, but I believe it should be technically possible...

Re: stderr output; I think that's just the way Process works. As you said; it (by default) consumes the streams (stderr, stdout). Wouldn't that require changing the Process api to fix?

m13253 commented 9 years ago

Re: stderr output; I think that's just the way Process works. As you said; it (by default) consumes the streams (stderr, stdout). Wouldn't that require changing the Process api to fix?

In order to pass stderr, we'll just need to add a .stderr(InheritFd(2)) after Command::new. However I can't understand the way Cargo's source is organized. Could you help?

kornelski commented 9 years ago

Ugghh, debugging of build scripts is such a pain :(

I can't run the script directly from /target/build/*/build-script-build, because it won't get all the env vars it needs. And I can't even print the env vars :)

So it's a black box that's calling a bunch of commands with arguments I'm not sure about, and something doesn't work right, and maybe it has printed why… but I can't see it!

The way I write them is:

let result = cmd.output().unwrap();
std::io::File::create(&Path::new("/tmp/sucks1")).write(&result.output[]).unwrap();
std::io::File::create(&Path::new("/tmp/sucks2")).write(&result.error[]).unwrap();

rm -f /tmp/sucks*; cargo build; cat /tmp/sucks*

Surely, there must be a better way.

shadowmint commented 9 years ago

@pornel Once again, if the build script fails, cargo reports the output stderr; so you can totally debug the output and dump the env vars if you want to. Just add:

panic!("nope");

For example a build.rs of:

use std::os::env;
use std::io::Command;
use std::str::from_utf8;
fn main() {
  for value in env().iter() {
    println!("{} -> {}", value.0, value.1);
  }
  let out = Command::new("ls").output().unwrap().output;
  let out_str = from_utf8(out.as_slice());
  println!("{:?}", out_str);
  println!("Hi!");
  panic!("Nope");
}

I'm sure we'll see a growth of 'build helper' libraries as we go past 1.0 to help with the tedious tasks. Personally I use https://github.com/shadowmint/rust-script for this, but there are a few others around. Perhaps you can pull the pieces you need out of them for your build script?

m13253 commented 9 years ago

Yes, panic!() is possible. But it didn't solve the problem.

For example I usually prefer this procedure to debug this kind of script:

Enable "debug mode" in my source (by switching a boolean / set a config value)
Read a char from stdin, this will pause the program. (like a breakpoint)
Start gdb and attach to the process.
Debug the program line by line.
Print things into stderr so that I can see immediately.

Cargo only consumes stdout, but it is managing both stdin and stderr, making this method unavailable.

There should be a way that I can use gdb for instant debugging.

Anyway, I can still achieve the goal by starting a new XTerm (or AllocConsole on Windows). However this will decrease user experience even more, and is oppose to the original design of Cargo.

kornelski commented 9 years ago

@shadowmint Ok, it's good to know that panic! is a workaround for that, but:

It's not documented. "panic" is not mentioned on http://doc.crates.io/build-script.html. The paragraph about output only applies to lines starting with cargo:. Documentation only briefly describes happy path, and only has pseudocode examples.
Having a workaround doesn't solve the problem of cargo being unfriendly and frustrating to newcommers like me. "printf debugging" is the simplest thing that tends to work everywhere, and I have strong expectation that at least --verbose (or other switch documented in -h) should print it.

alexcrichton commented 9 years ago

From @larsbergstrom in #1324

Currently, custom build commands are not printed and their output appears to also be only available to Cargo. It would be great if compiling with --verbose also printed that output.

In Servo, we very frequently shell out to a makefile in these custom build steps, and not being able to see the steps makes it quite difficult to debug them (especially since it can be challenging to recreate the exact lines that cargo passes in, due to the hash-specific directory names, etc.).

shadowmint commented 9 years ago

Cargo does print the custom build commands:

Running `/Users/doug/dev/rust-all/rust-sys-ruv/target/build/uv-ec54d3eb248926fd/build-script-build`
Running `/Users/doug/dev/rust-all/rust-sys-ruv/target/build/ruv-5686775bd2f9a443/build-script-build`

It just doesn't print the output or the list of env variables passed to them.

Once again, I find myself skeptical that logging the output will be useful unless there's a way to stream that output line by line as the build command generates it. ...and even then, unless the build command invokes commands correctly, it will still work exactly the same way (people just use read_to_end() all the time).

Really, there's no benefit is having cargo run to the end, and then spit out the output to stderr and stdout at the end; the issue with cargo is while its running you want some visibility about what it's actually doing, so you can debug scripts.

For example, if cargo hangs due to xcode ( >___< ) you have no visibility of what happened or why it stopped.

I use a custom file logger for this; but clearly this is a troublesome pain point for people.

Perhaps we can change the way cargo works (although I'm worried about breaking changes here... but still...) so that instead of using env variables, all the arguments are passed on the command line.

This would allow you to trivially run your build script in 'stand alone' mode, by running:

build/ruv-5686775bd2f9a443/build-script-build --OUT_DIR=... --libfoo=...

Running these outside of cargo would then print stdout & stderr as you go; although doubtless people will continue to discover that when build.rs invokes make, or other tools via Command it doesn't usefully log it's output for exactly the same reason.

NB. though that as recently raised in irc, windows has a command line length limit that might make this infeasible.

comex commented 9 years ago

I just found this obnoxious in a case where my build script succeeded, but screwed up generated link flags, causing the library link to fail. I resorted to dup2ing /dev/tty to stderr :P

jdub commented 9 years ago

User perspective: First time hacking on a build script helper (@alexcrichton's gcc-rs), and I slammed straight into this. :smiley:

briansmith commented 9 years ago

Once again, I find myself skeptical that logging the output will be useful unless there's a way to stream that output line by line as the build command generates it. ...and even then, unless the build command invokes commands correctly, it will still work exactly the same way (people just use read_to_end() all the time).

It would be tremendously helpful on build bots like Travis, Jenkins, AppVeyor, etc. Imagine that you are developing a wrapper around a native library, and you're trying to use Travis, etc. to set up builds for a platform that you don't even have access to locally. The build logs are critical to getting that situation to work. More generally, verbose build logs from buildbots are much preferred over quiet logs from buildbots.

IMO, --verbose should do this.

shadowmint commented 9 years ago

@briansmith how do propose to do this, technically?

I've said my piece; if you want to hack on it, the code is here: https://github.com/rust-lang/cargo/blob/master/src/cargo/ops/cargo_rustc/custom_build.rs#L149

The execution engine is here: https://github.com/rust-lang/cargo/blob/master/src/cargo/util/process_builder.rs#L89

Try it and see how it works out for you?

I found that without streaming output, having 'log on failure' vs 'log on success' made no tangible difference.

alexcrichton commented 9 years ago

It may be possible to have cargo both stream and capture the output via some pipe trickery on Windows/Unix, and I may also be pretty ok with doing this on multiple -v flags, e.g.:

# Only show commands run
cargo build -v
# Show output of all all commands run (build scripts) as well
cargo build -vv

larsbergstrom commented 9 years ago

@alexcrichton That double-v support would be fantastic. I'm pretty sure we would use it by default on our builds for pretty much everything on the builders on Servo, for exactly the reasons @briansmith outlines above. Right now, we have to have an admin log into the build machine, cargo build -v to get the execution line, then try to invoke stuff in the right directory to hopefully get the output (assuming we're lucky enough that it isn't something that only happens on a first-time build through the project!).

cc @metajack

vvanders commented 8 years ago

+1 on -vv showing script output.

When running Travis CI I really dislike the idea of having to introduce another build failure(by committing a panic!("fail");) in order to see build script output.

meh commented 8 years ago

:+1: on -vv or any other way.

Travis is killing my jobs because I'm building ffmpeg from the build.rs and it takes more than 10 minutes.

dagit commented 8 years ago

I just wasted a considerable chunk of my weekend trying to debug a build-script. And it was all because of this 'feature'.

The default way things work now is really terrible, especially for new users. When the script panics you get to see some stdout/stderr, which lead me to believe that stdout/stderr can be printed from the build-script. I spent the rest of my time trying to figure out why I can see it sometimes and other runs it seems to be missing. I thought cargo was linking in the old build script or something.

I agree with the other commenters here that this should be changed. Verbose should mean verbose.

adimarco commented 8 years ago

:+1: on a flag of any kind to show build script output.

briansmith commented 8 years ago

This has caused me tons of trouble. For a very long time, I thought my Travis CI builds were cross-compiling to x86, but they in fact weren't. The consequence was that the tests passed when actually my 32-bit builds were broken. I would have noticed this much sooner if the build script output had been in the Travis CI logs. When it comes ti CI, there should always be an option to show all the build script output.

pnkfelix commented 8 years ago

@alexcrichton an alternative approach that might placate a lot of people here (including me): currently all build script output is effectively suppressed. What if there were some prefix that one could include on a line of output from the build script that tells cargo: "Hey, you should report this line of output (minus the leading marker prefix) to the end user of cargo when you get the chance."

(I say "when you get the chance" because I don't particular care if the output is immediately streamed from the process or if one has to wait until the cargo run has finished.)

In my particular use case, there is one build script I have that has some internal safe-guards when it detects non-fatal oddities in the inputs it is processing. I want the build script to have the option of emitting a warning in such cases without killing the build.

alexcrichton commented 8 years ago

@pnkfelix that seems reasonable, yeah, although I'd still prefer that kind of output to not be emitted during a default cargo build (e.g. no verbose flags). Upstream dependencies and what they're doing in general shouldn't be cluttering up the build output, but path dependencies could potentially emit that kind of information.

For this issue I would personally prefer to tackle this as:

cargo build - stays the same as it is today
cargo build -v - same as today plus perhaps something like what @pnkfelix is thinking
cargo build -vv - same as -v plus streaming of all build scripts' output

I'd want to discuss a little more before having -v dump everything, but it's plausible still I think.

kornelski commented 8 years ago

Could -v at least not suppress stderr? I'm most interested in catching errors that didn't fail the build (e.g. things failing in a bash script without set -e, or commands that react to invalid flags by ignoring them with a warning).

Another option could be for -v to output everything for the current (top-level) package being built, but not dependencies. -vv would be required to disable output suppression from builds of dependencies.

When I develop my own package I really really want to see everything. The build that I'm working on with output suppressed isn't "clean" for me. It's opaque and hiding from me things that I deliberately printed, because I wanted to keep an eye on them.

jonas-schievink commented 8 years ago

I'd prefer the build script to be able to tell cargo "Just let me talk, okay?", which just makes cargo pass all output through (or maybe on a line-by-line basis, dropping all cargo: lines). This way, if I want to build LLVM or something equally large in my build script, I can do so without the user wondering what cargo is doing. Requiring the user to call cargo build -v isn't an option in this case, because the default will still be confusing. Or am I supposed to use a different build system for this use case?

alexcrichton commented 8 years ago

@pornel I'd be amenable to something that distinguishes based on whether it's a "current crate" or not, that would help with not having to worry about upstream scripts producing way too much output.

I also personally think that a clean output on a normal cargo build is typically still what you want by default. As a developer you'll likely pass -v if you want but anyone who checks out the code is unlikely to want to be inundated with output.

@jonas-schievink yeah I agree that cases like building LLVM are pretty bad today. I'd be wary of an upstream script arbitrarily deciding to pollute my terminal with output, however. If that key were available to local scripts, however, it may work well? (local in this case means "path dependencies").

One thing I'd be wary of is that the only way I'd know of to implement streaming output is to have a thread reading a pipe and both recording the data and writing it back to stdout. Doing that on all invocations and/or doing it lazily (e.g. dynamically deciding whether the stdout path is taken) may be somewhat expensive. As I type this though I'm remembering that wait_with_output in libstd spawns threads to do this already, and it's not any problem with Cargo today, so it's probably not something to worry about.

pnkfelix commented 8 years ago

I also personally think that a clean output on a normal cargo build is typically still what you want by default. As a developer you'll likely pass -v if you want but anyone who checks out the code is unlikely to want to be inundated with output.

My first instinct is that we would be better off having that be a convention but not something that is strictly enforced by cargo itself.

To elaborate: the main example of a place where I think non-fatal but non-hidden warnings would be relevant, at least for the current crate and its build script, is when you are doing code generation. (Two cases of this: tango and parser-generators. I think it is important for a code generator to have the option of telling the user "hey the input you just fed into me is technically acceptable, but has some questionable bits."
The main reason that I don't want this hidden behind a -v switch is that the end user may not even realize that they should be passing that switch when they are doing development on that particular crate.

However, maybe we can find a middle ground that both of us could accept: If the build script is also given some way to inspect whether -v was passed in to cargo, then I would be happy, because then I would:

If the -v is absent and the warning scenario crops up, the build script can fatally stop the build (and the error message printed would suggest passing the -v flag on a subsequent cargo invocation to learn why this happened).
If the -v is present and the warning scenario crops up, the build script can emit the warning but not terminate the build.

Then again, this "middle ground" opens the door to bugs where the build products generated by the build script are predicated on whether -v was passed to cargo, which may be distasteful.

So which of those two paths sound worse to you, @alexcrichton ?

alexcrichton commented 8 years ago

Ah yeah having -v affect the build output like that seems like it would be a little too surprising to me to stomach. I wonder, however, if we could have a scheme such as:

Add a new key, cargo:warning=foo to build script output
On normal builds, path dependencies will have warnings printed. This means that basically anything you're working on will have warnings. Note that the warnings are not streamed, however.
On cargo build -v, print warnings for all dependencies.
On cargo build -vv, stream output to the console for all build scripts.

It seems like that may solve the case of parser generators because you likely care about warnings if you're working on them? It would also solve the concurrent output scenario by default as warnings aren't streamed (but rather printed after the fact). It'd then also have a mode for streaming everything to keep up to date with output.

pnkfelix commented 8 years ago

@alexcrichton

I assume by "path dependencies" you are including the current crate as well as things listed via http://doc.crates.io/guide.html#path-dependencies ?

I agree that would resolve my use case of generated source code, and sounds reasonable overall to me.

I might also say we might consider including "git dependencies" for lack of a better term, since those might be even more unstable than locally developed code.
The main point would be that once a crate has been published to crates.io itself, then cargo without -v won't report any cargo:warning=... messages from that crates build script when it is compiled as a dependency.

alexcrichton commented 8 years ago

@pnkfelix ah yeah that's what I mean, we currently use the same metric for determining whether to pass --cap-lints. It's basically a heuristic for "code that you are locally working on".

I'd be a little hesitant to apply it to git dependencies as well because projects like Servo depend on a lot of git repositories, not all of which you're actively working on. It does seem like a possible extension, however!

I agree though that once something has been published I personally view it as important that we shouldn't be printing out tons of warnings that were left in by accident or something like that.

indiv0 commented 8 years ago

Any updates on this?

Twinklebear commented 8 years ago

This would be really helpful for projects that mix Rust and native code, e.g. ispc-rs where you'd want to see warnings from the ispc compiler when running the build script since it will tell you about possible performance issues and so on.

aldanor commented 8 years ago

I concur with @Twinklebear, would be very helpful when working with native code, especially when there's a long chain of crate dependencies. Would be nice to be able to temporarily suppress output muting, at least for simplifying debugging the build process.

Or maybe there could be markers to print things to stdout/stderr that cargo could pick up? Like

// build.rs

fn main() {
    println!("cargo:stderr = A very important warning");

    // or even
    println!("cargo:suppress-output = false");
    do_some_stuff();
    println!("cargo:suppress-output = true");
}

alexcrichton commented 8 years ago

I've talked with a few others and https://github.com/rust-lang/cargo/issues/1106#issuecomment-179360074 seems like the most plausible route for this. That being said, streaming output is very difficult to do unfortunately so it may take some time to implement.

I've got a work in progress branch but it'll take some time to flesh it out.

allentc commented 8 years ago

I've run into a subtle problem working with the Piston game engine under Window 7 64-bit which led me to search for dumping build script output and ended up here. Building PistonDevelopers/piston-examples (52168ed) works and the next revision (d95e446) fails with a SDL2 linking problem. The difference is that one of the many dependencies of the Piston stack has changed the linker search path, but it isn't the module that actually links to the SDL2 native library... so naturally I'd like to examine the build script output and figure out which dependency is involved and perhaps work up a reliable solution.

The ability to easily examine build script output will prove to be essential for this sort of problem. An important property will be to output not only the build script output but to also clearly and unambiguously attribute each contribution to a source; a big pile of output composed together with no indication of what came from where will only frustrate.

larsbergstrom commented 8 years ago

@alexcrichton Thanks, that will be great!

We're in the middle of another SM upgrade that has been horribly complicated by this, as it required a bunch of native deps and something somewhere has changed how it's pulling in / linking things, and debugging the native build scripts all across Servo is quite the pain since we don't have any way to generate & search it in a centralized fashion.

rust-lang / cargo