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.

Sign up for GitHub

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

Jump to bottom

When printing build script output (with -vv), prefix output somehow #6158

Closed
luser opened this issue Oct 9, 2018 · 1 comment
Closed

When printing build script output (with -vv), prefix output somehow #6158

luser opened this issue Oct 9, 2018 · 1 comment
Labels
A-build-scripts Area: build.rs scripts C-feature-request Category: proposal for a feature. Before PR, ping rust-lang/cargo if this is not `Feature accepted`

Comments

@luser
Copy link
Contributor

luser commented Oct 9, 2018

I made the Firefox build invoke cargo with -vv so we could see the output of build scripts, which is useful to diagnose issues in CI. However, we build enough Rust code now that it can be difficult to determine what output is from which build script, since several of them can be running at the same time. It would be nice if cargo would prefix the build script output somehow to make it clear where the output originates. Putting [crate] or [crate-fingerprint] at the start of each line would help a lot.

I filed this while looking at a recent bug which contains the confusing output:

40:26.49 thread 'main' panicked at 'cargo:rerun-if-changed=/builds/worker/c-cen-t-lnx64-ntly/build/obj-x86_64-pc-linux-gnu/dist/include/nsBaseHashtable.h

I think this is one build script panicking but failing during panic, and then the output from a different build script being printed on the same line, but it would be nice to have more information here!
@alexcrichton alexcrichton added C-feature-request Category: proposal for a feature. Before PR, ping rust-lang/cargo if this is not `Feature accepted` A-build-scripts Area: build.rs scripts labels Oct 9, 2018
@luser
Copy link
Contributor Author

luser commented Oct 9, 2018

I wrote a patch, but I need to fix some of the tests to match:
luser@3936e04

bors added a commit that referenced this issue Oct 18, 2018
@bors
Auto merge of #6164 - luser:build-script-output-prefix, r=alexcrichton
4076b8d 
Prefix build script output with crate name when running in extra verbose mode. Fixes #6158.

cargo's extra verbose mode is useful for getting detailed information out of
builds in CI where it can be difficult to examine the build environment
after-the-fact. However, when multiple build scripts are running as part of a
build it's not always clear what output is from which build script. This patch
makes cargo prefix each line of build script output with the crate name
in this case.

I put together [a simple test crate](https://github.com/luser/snippet/tree/build-script-output) for this. Building that crate on my machine with stable cargo produces:
```
luser@eye7:/build/snippet$ cargo build -vv
   Compiling one v0.1.0 (file:///build/snippet/one)
   Compiling two v0.1.0 (file:///build/snippet/two)
       Fresh itoa v0.3.4
     Running `rustc --crate-name build_script_build one/build.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8e5ff38061b98562 -C extra-filename=-8e5ff38061b98562 --out-dir /build/snippet/target/debug/build/one-8e5ff38061b98562 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name build_script_build two/build.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=fcd8c089040e6ff4 -C extra-filename=-fcd8c089040e6ff4 --out-dir /build/snippet/target/debug/build/two-fcd8c089040e6ff4 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `/build/snippet/target/debug/build/two-fcd8c089040e6ff4/build-script-build`
     Running `/build/snippet/target/debug/build/one-8e5ff38061b98562/build-script-build`
Error 0
Output 0
Output 0
Error 0
Output 1
Error 1
Error 1
Output 1
Error 2
Output 2
Error 2
Output 2
Error 3
Output 3
Error 3
Output 3
Error 4
Error 4
Output 4
Output 4
Error 5
Error 5
Output 5
Output 5
Error 6
Output 6
Error 6
Output 6
Error 7
Output 7
Error 7
Output 7
Error 8
Error 8
Output 8
Output 8
Error 9
Output 9
Error 9
Output 9
     Running `rustc --crate-name two two/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=904ea56f5613ae62 -C extra-filename=-904ea56f5613ae62 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name one one/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=c2b76a52468c9a0b -C extra-filename=-c2b76a52468c9a0b --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
   Compiling snippet v0.1.4-alpha.0 (file:///build/snippet)
     Running `rustc --crate-name snippet src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=a5c6abeab1e38e11 -C extra-filename=-a5c6abeab1e38e11 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
     Running `rustc --crate-name snippet src/main.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8b5a0b44264aa67c -C extra-filename=-8b5a0b44264aa67c --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern snippet=/build/snippet/target/debug/deps/libsnippet-a5c6abeab1e38e11.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
    Finished dev [unoptimized + debuginfo] target(s) in 0.76s
```

Building that crate with my local cargo including this change produces:
```
luser@eye7:/build/snippet$ /build/cargo/target/debug/cargo build -vv
   Compiling one v0.1.0 (/build/snippet/one)
   Compiling two v0.1.0 (/build/snippet/two)
   Compiling itoa v0.3.4
     Running `rustc --crate-name build_script_build one/build.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8e5ff38061b98562 -C extra-filename=-8e5ff38061b98562 --out-dir /build/snippet/target/debug/build/one-8e5ff38061b98562 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name build_script_build two/build.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=fcd8c089040e6ff4 -C extra-filename=-fcd8c089040e6ff4 --out-dir /build/snippet/target/debug/build/two-fcd8c089040e6ff4 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name itoa /home/luser/.cargo/registry/src/github.com-1ecc6299db9ec823/itoa-0.3.4/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=327a92d5ddd56b4a -C extra-filename=-327a92d5ddd56b4a --out-dir /build/snippet/target/debug/deps -L dependency=/build/snippet/target/debug/deps --cap-lints warn`
     Running `/build/snippet/target/debug/build/one-8e5ff38061b98562/build-script-build`
     Running `/build/snippet/target/debug/build/two-fcd8c089040e6ff4/build-script-build`
[one-e779b28932bbd20b] Error 0
[one-e779b28932bbd20b] Output 0
[one-e779b28932bbd20b] Output 1
[one-e779b28932bbd20b] Error 1
[two-adc2191c38bf9afc] Error 0
[two-adc2191c38bf9afc] Output 0
[one-e779b28932bbd20b] Error 2
[one-e779b28932bbd20b] Output 2
[two-adc2191c38bf9afc] Error 1
[two-adc2191c38bf9afc] Output 1
[one-e779b28932bbd20b] Output 3
[one-e779b28932bbd20b] Error 3
[two-adc2191c38bf9afc] Error 2
[two-adc2191c38bf9afc] Output 2
[one-e779b28932bbd20b] Error 4
[one-e779b28932bbd20b] Output 4
[two-adc2191c38bf9afc] Error 3
[two-adc2191c38bf9afc] Output 3
[one-e779b28932bbd20b] Error 5
[one-e779b28932bbd20b] Output 5
[two-adc2191c38bf9afc] Error 4
[two-adc2191c38bf9afc] Output 4
[one-e779b28932bbd20b] Error 6
[one-e779b28932bbd20b] Output 6
[two-adc2191c38bf9afc] Error 5
[two-adc2191c38bf9afc] Output 5
[one-e779b28932bbd20b] Error 7
[one-e779b28932bbd20b] Output 7
[two-adc2191c38bf9afc] Error 6
[two-adc2191c38bf9afc] Output 6
[one-e779b28932bbd20b] Error 8
[one-e779b28932bbd20b] Output 8
[two-adc2191c38bf9afc] Error 7
[two-adc2191c38bf9afc] Output 7
[one-e779b28932bbd20b] Error 9
[one-e779b28932bbd20b] Output 9
[two-adc2191c38bf9afc] Output 8
[two-adc2191c38bf9afc] Error 8
     Running `rustc --crate-name one one/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=c2b76a52468c9a0b -C extra-filename=-c2b76a52468c9a0b --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
[two-adc2191c38bf9afc] Error 9
[two-adc2191c38bf9afc] Output 9
     Running `rustc --crate-name two two/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=904ea56f5613ae62 -C extra-filename=-904ea56f5613ae62 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
   Compiling snippet v0.1.4-alpha.0 (/build/snippet)
     Running `rustc --crate-name snippet src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=a5c6abeab1e38e11 -C extra-filename=-a5c6abeab1e38e11 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
     Running `rustc --crate-name snippet src/main.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8b5a0b44264aa67c -C extra-filename=-8b5a0b44264aa67c --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern snippet=/build/snippet/target/debug/deps/libsnippet-a5c6abeab1e38e11.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
    Finished dev [unoptimized + debuginfo] target(s) in 0.90s
```
I used `invocation_name` here for no particular reason other than it was being used by the build plan code immediately above, but since that includes the fingerprint it might be nicer to use just `pkg_name`?
bors added a commit that referenced this issue Oct 19, 2018
@bors
Auto merge of #6164 - luser:build-script-output-prefix, r=alexcrichton
4ed9373 
Prefix build script output with crate name when running in extra verbose mode. Fixes #6158.

cargo's extra verbose mode is useful for getting detailed information out of
builds in CI where it can be difficult to examine the build environment
after-the-fact. However, when multiple build scripts are running as part of a
build it's not always clear what output is from which build script. This patch
makes cargo prefix each line of build script output with the crate name
in this case.

I put together [a simple test crate](https://github.com/luser/snippet/tree/build-script-output) for this. Building that crate on my machine with stable cargo produces:
```
luser@eye7:/build/snippet$ cargo build -vv
   Compiling one v0.1.0 (file:///build/snippet/one)
   Compiling two v0.1.0 (file:///build/snippet/two)
       Fresh itoa v0.3.4
     Running `rustc --crate-name build_script_build one/build.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8e5ff38061b98562 -C extra-filename=-8e5ff38061b98562 --out-dir /build/snippet/target/debug/build/one-8e5ff38061b98562 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name build_script_build two/build.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=fcd8c089040e6ff4 -C extra-filename=-fcd8c089040e6ff4 --out-dir /build/snippet/target/debug/build/two-fcd8c089040e6ff4 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `/build/snippet/target/debug/build/two-fcd8c089040e6ff4/build-script-build`
     Running `/build/snippet/target/debug/build/one-8e5ff38061b98562/build-script-build`
Error 0
Output 0
Output 0
Error 0
Output 1
Error 1
Error 1
Output 1
Error 2
Output 2
Error 2
Output 2
Error 3
Output 3
Error 3
Output 3
Error 4
Error 4
Output 4
Output 4
Error 5
Error 5
Output 5
Output 5
Error 6
Output 6
Error 6
Output 6
Error 7
Output 7
Error 7
Output 7
Error 8
Error 8
Output 8
Output 8
Error 9
Output 9
Error 9
Output 9
     Running `rustc --crate-name two two/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=904ea56f5613ae62 -C extra-filename=-904ea56f5613ae62 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name one one/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=c2b76a52468c9a0b -C extra-filename=-c2b76a52468c9a0b --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
   Compiling snippet v0.1.4-alpha.0 (file:///build/snippet)
     Running `rustc --crate-name snippet src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=a5c6abeab1e38e11 -C extra-filename=-a5c6abeab1e38e11 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
     Running `rustc --crate-name snippet src/main.rs --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8b5a0b44264aa67c -C extra-filename=-8b5a0b44264aa67c --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern snippet=/build/snippet/target/debug/deps/libsnippet-a5c6abeab1e38e11.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
    Finished dev [unoptimized + debuginfo] target(s) in 0.76s
```

Building that crate with my local cargo including this change produces:
```
luser@eye7:/build/snippet$ /build/cargo/target/debug/cargo build -vv
   Compiling one v0.1.0 (/build/snippet/one)
   Compiling two v0.1.0 (/build/snippet/two)
   Compiling itoa v0.3.4
     Running `rustc --crate-name build_script_build one/build.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8e5ff38061b98562 -C extra-filename=-8e5ff38061b98562 --out-dir /build/snippet/target/debug/build/one-8e5ff38061b98562 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name build_script_build two/build.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=fcd8c089040e6ff4 -C extra-filename=-fcd8c089040e6ff4 --out-dir /build/snippet/target/debug/build/two-fcd8c089040e6ff4 -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
     Running `rustc --crate-name itoa /home/luser/.cargo/registry/src/github.com-1ecc6299db9ec823/itoa-0.3.4/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=327a92d5ddd56b4a -C extra-filename=-327a92d5ddd56b4a --out-dir /build/snippet/target/debug/deps -L dependency=/build/snippet/target/debug/deps --cap-lints warn`
     Running `/build/snippet/target/debug/build/one-8e5ff38061b98562/build-script-build`
     Running `/build/snippet/target/debug/build/two-fcd8c089040e6ff4/build-script-build`
[one-e779b28932bbd20b] Error 0
[one-e779b28932bbd20b] Output 0
[one-e779b28932bbd20b] Output 1
[one-e779b28932bbd20b] Error 1
[two-adc2191c38bf9afc] Error 0
[two-adc2191c38bf9afc] Output 0
[one-e779b28932bbd20b] Error 2
[one-e779b28932bbd20b] Output 2
[two-adc2191c38bf9afc] Error 1
[two-adc2191c38bf9afc] Output 1
[one-e779b28932bbd20b] Output 3
[one-e779b28932bbd20b] Error 3
[two-adc2191c38bf9afc] Error 2
[two-adc2191c38bf9afc] Output 2
[one-e779b28932bbd20b] Error 4
[one-e779b28932bbd20b] Output 4
[two-adc2191c38bf9afc] Error 3
[two-adc2191c38bf9afc] Output 3
[one-e779b28932bbd20b] Error 5
[one-e779b28932bbd20b] Output 5
[two-adc2191c38bf9afc] Error 4
[two-adc2191c38bf9afc] Output 4
[one-e779b28932bbd20b] Error 6
[one-e779b28932bbd20b] Output 6
[two-adc2191c38bf9afc] Error 5
[two-adc2191c38bf9afc] Output 5
[one-e779b28932bbd20b] Error 7
[one-e779b28932bbd20b] Output 7
[two-adc2191c38bf9afc] Error 6
[two-adc2191c38bf9afc] Output 6
[one-e779b28932bbd20b] Error 8
[one-e779b28932bbd20b] Output 8
[two-adc2191c38bf9afc] Error 7
[two-adc2191c38bf9afc] Output 7
[one-e779b28932bbd20b] Error 9
[one-e779b28932bbd20b] Output 9
[two-adc2191c38bf9afc] Output 8
[two-adc2191c38bf9afc] Error 8
     Running `rustc --crate-name one one/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=c2b76a52468c9a0b -C extra-filename=-c2b76a52468c9a0b --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
[two-adc2191c38bf9afc] Error 9
[two-adc2191c38bf9afc] Output 9
     Running `rustc --crate-name two two/src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=904ea56f5613ae62 -C extra-filename=-904ea56f5613ae62 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps`
   Compiling snippet v0.1.4-alpha.0 (/build/snippet)
     Running `rustc --crate-name snippet src/lib.rs --color always --crate-type lib --emit=dep-info,link -C debuginfo=2 -C metadata=a5c6abeab1e38e11 -C extra-filename=-a5c6abeab1e38e11 --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
     Running `rustc --crate-name snippet src/main.rs --color always --crate-type bin --emit=dep-info,link -C debuginfo=2 -C metadata=8b5a0b44264aa67c -C extra-filename=-8b5a0b44264aa67c --out-dir /build/snippet/target/debug/deps -C incremental=/build/snippet/target/debug/incremental -L dependency=/build/snippet/target/debug/deps --extern itoa=/build/snippet/target/debug/deps/libitoa-327a92d5ddd56b4a.rlib --extern one=/build/snippet/target/debug/deps/libone-c2b76a52468c9a0b.rlib --extern snippet=/build/snippet/target/debug/deps/libsnippet-a5c6abeab1e38e11.rlib --extern two=/build/snippet/target/debug/deps/libtwo-904ea56f5613ae62.rlib`
    Finished dev [unoptimized + debuginfo] target(s) in 0.90s
```
I used `invocation_name` here for no particular reason other than it was being used by the build plan code immediately above, but since that includes the fingerprint it might be nicer to use just `pkg_name`?
@bors bors closed this as completed in 20920c0 Oct 19, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-build-scripts Area: build.rs scripts C-feature-request Category: proposal for a feature. Before PR, ping rust-lang/cargo if this is not `Feature accepted`
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@alexcrichton @luser