Doctests doesn't print the assert failure output #51162

farodin91 · 2018-05-29T10:34:28Z

I run the cargo test command on nightly did not get any output on failing assert_eq!() in doctests.

I expected to see this happen:
Output on stable(1.26)

`rustdoc --test ./predicates-rs/src/lib.rs --crate-name predicates -L dependency=./predicates-rs/target/debug/deps -L dependency=./predicates-rs/target/debug/deps --cfg 'feature="default"' --cfg 'feature="regex"' --cfg 'feature="float-cmp"' --cfg 'feature="difference"' --extern float_cmp=./predicates-rs/target/debug/deps/libfloat_cmp-4a42d8413dc12365.rlib --extern regex=./predicates-rs/target/debug/deps/libregex-30b85987be956602.rlib --extern predicates=./predicates-rs/target/debug/deps/libpredicates-f9ff1b22f35b575a.rlib --extern difference=./predicates-rs/target/debug/deps/libdifference-ed04b642d361199c.rlib`

running 42 tests
test src/boolean.rs - boolean::PredicateBooleanExt::not (line 218) ... ok
test src/boolean.rs - boolean::PredicateBooleanExt::and (line 178) ... ok
test src/boolean.rs - boolean::PredicateBooleanExt::or (line 197) ... ok
test src/boxed.rs - boxed::PredicateBoxExt::boxed (line 80) ... ok
test src/float/close.rs - float::close::IsClosePredicate::distance (line 35) ... ok
test src/constant.rs - constant::always (line 41) ... ok
test src/float/close.rs - float::close::IsClosePredicate::epsilon (line 54) ... ok
test src/constant.rs - constant::never (line 62) ... ok
test src/float/close.rs - float::close::IsClosePredicate::ulps (line 71) ... ok
test src/function.rs - function::FnPredicate<F, T>::fn_name (line 36) ... ok
test src/float/close.rs - float::close::is_close (line 104) ... ok
test src/function.rs - function::function (line 78) ... ok
test src/iter.rs - iter::in_iter (line 100) ... ok
test src/iter.rs - iter::InPredicate<T>::sort (line 49) ... ok
test src/iter.rs - iter::in_hash (line 200) ... ok
test src/lib.rs -  (line 34) ... ok
test src/name.rs - name::PredicateNameExt::name (line 59) ... ok
test src/ord.rs - ord::ge (line 215) ... ok
test src/ord.rs - ord::eq (line 70) ... ok
test src/ord.rs - ord::gt (line 238) ... ok
test src/ord.rs - ord::le (line 192) ... ok
test src/ord.rs - ord::lt (line 170) ... ok
test src/ord.rs - ord::ne (line 92) ... ok
test src/path/existence.rs - path::existence::exists (line 38) ... ok
test src/path/existence.rs - path::existence::missing (line 53) ... ok
test src/path/ft.rs - path::ft::is_dir (line 107) ... ok
test src/path/ft.rs - path::ft::is_file (line 87) ... ok
test src/path/ft.rs - path::ft::is_symlink (line 127) ... ok
test src/str/adapters.rs - str::adapters::PredicateSliceExt::from_file_path (line 169) ... FAILED
test src/str/adapters.rs - str::adapters::PredicateStrExt::trim (line 123) ... ok
test src/str/adapters.rs - str::adapters::PredicateStrExt::from_utf8 (line 138) ... ok
test src/str/basics.rs - str::basics::ContainsPredicate::count (line 139) ... ok
test src/str/basics.rs - str::basics::is_empty (line 35) ... ok
test src/str/basics.rs - str::basics::contains (line 191) ... ok
test src/str/basics.rs - str::basics::ends_with (line 110) ... ok
test src/str/basics.rs - str::basics::starts_with (line 70) ... ok
test src/str/difference.rs - str::difference::DifferencePredicate::distance (line 74) ... ok
test src/str/difference.rs - str::difference::DifferencePredicate::split (line 54) ... ok
test src/str/difference.rs - str::difference::diff (line 108) ... ok
test src/str/difference.rs - str::difference::similar (line 131) ... ok
test src/str/regex.rs - str::regex::is_match (line 80) ... ok
test src/str/regex.rs - str::regex::RegexPredicate::count (line 31) ... ok

failures:

---- src/str/adapters.rs - str::adapters::PredicateSliceExt::from_file_path (line 169) stdout ----
        thread 'rustc' panicked at 'test executable failed:

thread 'main' panicked at 'assertion failed: `(left == right)`
  left: `false`,
 right: `true`', src/str/adapters.rs:8:1
note: Run with `RUST_BACKTRACE=1` for a backtrace.

', librustdoc/test.rs:341:17
note: Run with `RUST_BACKTRACE=1` for a backtrace.


failures:
    src/str/adapters.rs - str::adapters::PredicateSliceExt::from_file_path (line 169)

Instead, this happened:
Output on nightly (rustc 1.28.0-nightly (5bf68db 2018-05-28))

rustdoc --test ./predicates-rs/src/lib.rs --crate-name predicates -L dependency=./predicates-rs/target/debug/deps -L dependency=./predicates-rs/target/debug/deps --cfg 'feature="float-cmp"' --cfg 'feature="default"' --cfg 'feature="regex"' --cfg 'feature="difference"' --extern difference=./predicates-rs/target/debug/deps/libdifference-cf1e9088133b4a68.rlib --extern float_cmp=./predicates-rs/target/debug/deps/libfloat_cmp-0d3ec5c6568f6886.rlib --extern predicates=./predicates-rs/target/debug/deps/libpredicates-6e0d49cf47babc04.rlib --extern regex=./predicates-rs/target/debug/deps/libregex-5aa34502a8174bb1.rlib

running 42 tests
test src/boolean.rs - boolean::PredicateBooleanExt::not (line 218) ... ok
test src/boolean.rs - boolean::PredicateBooleanExt::or (line 197) ... ok
test src/boolean.rs - boolean::PredicateBooleanExt::and (line 178) ... ok
test src/boxed.rs - boxed::PredicateBoxExt::boxed (line 80) ... ok
test src/float/close.rs - float::close::IsClosePredicate::distance (line 35) ... ok
test src/float/close.rs - float::close::IsClosePredicate::epsilon (line 54) ... ok
test src/constant.rs - constant::always (line 41) ... ok
test src/constant.rs - constant::never (line 62) ... ok
test src/float/close.rs - float::close::IsClosePredicate::ulps (line 71) ... ok
test src/function.rs - function::FnPredicate<F, T>::fn_name (line 36) ... ok
test src/float/close.rs - float::close::is_close (line 104) ... ok
test src/function.rs - function::function (line 78) ... ok
test src/iter.rs - iter::InPredicate<T>::sort (line 49) ... ok
test src/iter.rs - iter::in_hash (line 200) ... ok
test src/iter.rs - iter::in_iter (line 100) ... ok
test src/name.rs - name::PredicateNameExt::name (line 59) ... ok
test src/lib.rs -  (line 34) ... ok
test src/ord.rs - ord::eq (line 70) ... ok
test src/ord.rs - ord::ge (line 215) ... ok
test src/ord.rs - ord::gt (line 238) ... ok
test src/ord.rs - ord::le (line 192) ... ok
test src/ord.rs - ord::lt (line 170) ... ok
test src/ord.rs - ord::ne (line 92) ... ok
test src/path/existence.rs - path::existence::exists (line 38) ... ok
test src/path/existence.rs - path::existence::missing (line 53) ... ok
test src/path/ft.rs - path::ft::is_dir (line 107) ... ok
test src/path/ft.rs - path::ft::is_file (line 87) ... ok
test src/path/ft.rs - path::ft::is_symlink (line 127) ... ok
test src/str/adapters.rs - str::adapters::PredicateSliceExt::from_file_path (line 169) ... FAILED
test src/str/adapters.rs - str::adapters::PredicateStrExt::from_utf8 (line 138) ... ok
test src/str/adapters.rs - str::adapters::PredicateStrExt::trim (line 123) ... ok
test src/str/basics.rs - str::basics::ContainsPredicate::count (line 139) ... ok
test src/str/basics.rs - str::basics::contains (line 191) ... ok
test src/str/basics.rs - str::basics::is_empty (line 35) ... ok
test src/str/basics.rs - str::basics::ends_with (line 110) ... ok
test src/str/basics.rs - str::basics::starts_with (line 70) ... ok
test src/str/difference.rs - str::difference::DifferencePredicate::distance (line 74) ... ok
test src/str/difference.rs - str::difference::DifferencePredicate::split (line 54) ... ok
test src/str/difference.rs - str::difference::diff (line 108) ... ok
test src/str/difference.rs - str::difference::similar (line 131) ... ok
test src/str/regex.rs - str::regex::RegexPredicate::count (line 31) ... ok
test src/str/regex.rs - str::regex::is_match (line 80) ... ok

failures:

failures:
    src/str/adapters.rs - str::adapters::PredicateSliceExt::from_file_path (line 169)

test result: FAILED. 41 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

We verified that it works on a nightly from 20-04-2018.

Meta

rustc --version --verbose:
rustc 1.28.0-nightly (5bf68db 2018-05-28)
binary: rustc
commit-hash: 5bf68db
commit-date: 2018-05-28
host: x86_64-unknown-linux-gnu
release: 1.28.0-nightly
LLVM version: 6.0

The text was updated successfully, but these errors were encountered:

GuillaumeGomez · 2018-05-31T12:03:32Z

Do you know where it could come from @QuietMisdreavus? I don't remember us updating this part of rustdoc since a few months.

QuietMisdreavus · 2018-05-31T13:55:46Z

Bisecting:

/// ```
/// panic!("oh no");
/// ```
pub struct SomeStruct;

$ rustdoc +nightly-2018-05-13 --test j.rs

running 1 test
test j.rs - SomeStruct (line 1) ... FAILED

failures:

---- j.rs - SomeStruct (line 1) stdout ----
        thread 'j.rs - SomeStruct (line 1)' panicked at 'test executable failed:

thread 'main' panicked at 'oh no', j.rs:3:1
note: Run with `RUST_BACKTRACE=1` for a backtrace.

', librustdoc/test.rs:356:17
note: Run with `RUST_BACKTRACE=1` for a backtrace.


failures:
    j.rs - SomeStruct (line 1)

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

$ rustdoc +nightly-2018-05-14 --test j.rs

running 1 test
test j.rs - SomeStruct (line 1) ... FAILED

failures:

failures:
    j.rs - SomeStruct (line 1)

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

The only change in src/librustdoc/test.rs in that span was #50235, which touched way more than just rustdoc. cc @Zoxc

tko · 2018-06-16T13:35:11Z

@QuietMisdreavus looks to me there's a io::set_panic call that should probably be paired with another call to return its original value.

rust/src/librustdoc/test.rs

Lines 267 to 268 in 61ba018

    
           let old = io::set_panic(Some(box Sink(data.clone()))); 
        
           let _bomb = Bomb(data.clone(), old.unwrap_or(box io::stdout()));

pietroalbini · 2018-06-28T21:21:21Z

Ping @QuietMisdreavus, is there any update on this?

QuietMisdreavus · 2018-07-09T02:53:11Z

I walked PR-by-PR between those nightlies and found that it was in fact #50235 that caused this. However, that PR doesn't seem to have changed anything about panic handling, or the way things are printed? @rust-lang/compiler I'm a bit lost for what's happening here.

Mark-Simulacrum · 2018-07-09T03:07:49Z

I think set_panic needs to happen inside each thread and it looks like we might be compiling/running tests inside different threads now in some fashion? I seem to recall such similar behavior last time I looked at a similar issue where the panics during std's tests are printed despite normally being swallowed...

michaelwoerister · 2018-07-09T07:42:15Z

cc @Zoxc, this is probably not setting some thread-local state?

Zoxc · 2018-07-09T08:25:22Z

I think the _bomb variable here is the problem. Previously its destructor was ran after the running the test, while now it runs after compilation.

QuietMisdreavus · 2018-07-09T15:39:40Z

@Zoxc Looks like that was it! Moving the set_panic and _bomb to outside the thread pool (so they drop at the end of the function, like you say) seems to fix it. I've opened #52181 to do this.

rustdoc: set panic output before starting compiler thread pool When the compiler was updated to run on a thread pool, rustdoc's processing of compiler/doctest stderr/stdout was moved into each compiler thread. However, this caused output of the test to be lost if the test failed at *runtime* instead of compile time. This change sets up the `set_panic` call and output bomb before starting the compiler thread pool, so that the `Drop` call that writes back to the test's stdout happens after the test runs, not just after it compiles. Fixes #51162

rustdoc: set panic output before starting compiler thread pool When the compiler was updated to run on a thread pool, rustdoc's processing of compiler/doctest stderr/stdout was moved into each compiler thread. However, this caused output of the test to be lost if the test failed at *runtime* instead of compile time. This change sets up the `set_panic` call and output bomb before starting the compiler thread pool, so that the `Drop` call that writes back to the test's stdout happens after the test runs, not just after it compiles. Fixes rust-lang/rust#51162

GuillaumeGomez added regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. A-docs Area: Documentation for any part of the project, including the compiler, standard library, and tools labels May 31, 2018

QuietMisdreavus self-assigned this May 31, 2018

pietroalbini added regression-from-stable-to-beta Performance or correctness regression from stable to beta. and removed regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. labels Jun 20, 2018

pietroalbini added this to the 1.28 milestone Jun 20, 2018

ehuss mentioned this issue Jun 26, 2018

Add a way to debug or get panic information from failing doctests rust-lang/cargo#5642

Closed

QuietMisdreavus mentioned this issue Jul 9, 2018

rustdoc: set panic output before starting compiler thread pool #52181

Merged

bors closed this as completed in #52181 Jul 24, 2018

thegreatape mentioned this issue Feb 11, 2020

No output from failures during cargo test neon-bindings/neon#487

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Doctests doesn't print the assert failure output #51162

Doctests doesn't print the assert failure output #51162

farodin91 commented May 29, 2018

GuillaumeGomez commented May 31, 2018

QuietMisdreavus commented May 31, 2018

tko commented Jun 16, 2018

pietroalbini commented Jun 28, 2018

QuietMisdreavus commented Jul 9, 2018

Mark-Simulacrum commented Jul 9, 2018

michaelwoerister commented Jul 9, 2018

Zoxc commented Jul 9, 2018

QuietMisdreavus commented Jul 9, 2018

Doctests doesn't print the assert failure output #51162

Doctests doesn't print the assert failure output #51162

Comments

farodin91 commented May 29, 2018

Meta

GuillaumeGomez commented May 31, 2018

QuietMisdreavus commented May 31, 2018

tko commented Jun 16, 2018

pietroalbini commented Jun 28, 2018

QuietMisdreavus commented Jul 9, 2018

Mark-Simulacrum commented Jul 9, 2018

michaelwoerister commented Jul 9, 2018

Zoxc commented Jul 9, 2018

QuietMisdreavus commented Jul 9, 2018