Request not to suppress the output of build script

[m13253]

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]

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]

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

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

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

[alexcrichton]

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]

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]

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]

@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:

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

[shadowmint]

@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]

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]

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]

@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]

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

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

1. Enable "debug mode" in my source (by switching a boolean / set a config value)
2. Read a char from stdin, this will pause the program. (like a breakpoint)
3. Start gdb and attach to the process.
4. Debug the program line by line.
5. 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]

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

1. 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.
2. 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]

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]

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]

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]

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

[briansmith]

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]

@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]

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]

@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]

+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]

👍 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]

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.