stdout is dropped in sbuild

[edneville]

Hello,

Package build in debian needs to patch away the following assertion:

--- rpassword.orig/tests/piped.rs
+++ rpassword/tests/piped.rs
@@ -28,8 +28,4 @@ fn piped_password() {

     let out = out.wait_with_output().unwrap();
     assert!(out.status.success());
-
-    let stdout = String::from_utf8(out.stdout).unwrap();
-    println!("stdout: {}", stdout);
-    assert!(stdout.ends_with("Password: secret\n"));
 }

Arguably, this is perhaps more related to sbuild, but forwarding for awareness.

[dkg]

To be clear, i think this report is about https://bugs.debian.org/975479, where the reported error during the test is:

test piped_password ... FAILED

failures:

---- piped_password stdout ----
stdout:
running 0 tests

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


thread 'piped_password' panicked at 'assertion failed: stdout.ends_with("Password: secret\n")', tests/piped.rs:34:5
stack backtrace:
   0: std::panicking::begin_panic
             at /usr/src/rustc-1.47.0/library/std/src/panicking.rs:497
   1: piped::piped_password
             at ./tests/piped.rs:34
   2: piped::piped_password::{{closure}}
             at ./tests/piped.rs:8
   3: core::ops::function::FnOnce::call_once
             at /usr/src/rustc-1.47.0/library/core/src/ops/function.rs:227
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

It's not clear to me why this particular patch is the right solution.

@edneville can you explain what you think is at issue here? I don't mind commenting out failing tests where there's a good, well-understood reason to do so. But i don't understand the reason here yet.

[edneville]

As above, stdout is lost (stdout:). I don't currently know a work around for this, I don't think it is a fault in rpassword, but I'm forwarding the commentary mostly for awareness.

[dkg]

What causes the stdout to be lost? Are you saying that you think this is a flaw in sbuild? Or the debian build environment? Or somewhere else?

I see this same failure by unpacking the source for rust-rpassword 5.0.0-1 on debian, and then from the new directory, running the standard debian test with all features:

apt source rust-rpassword
cd rust-rpassword-5.0.0
/usr/share/cargo/bin/cargo-auto-test rpassword 5.0.0 --all-targets --all-features

This is not using sbuild. (the above commandline is derived from the debcargo-generated test suite)

But I also see the same error if i do:

git clone https://github.com/conradkleinespel/rpassword
cd rpassword
git checkout v5.0.0
cargo test --all-targets --all-features

I do not see the errors if i omit --all-targets from the cargo test invocation.

So, it looks like this problem comes up with --all-targets. I admit that I don't really understand that flag for cargo test, or why it might cause this particular failure. Maybe this is worth investigating further?

upstream folks (@conradkleinespel?) can you confirm that the tests work for you when using --all-targets ?

[teythoon]

I found something odd:

cargo test --all-targets --all-features


$ cargo test --all-targets
    Finished test [unoptimized + debuginfo] target(s) in 0.00s
     Running target/debug/deps/rpassword-d876ea8b112128d8

running 1 test
test mock::tests::can_read_from_redirected_input_many_times ... ok

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

     Running target/debug/deps/no_terminal-80dfd3b50166e775

running 1 test
test can_read_from_redirected_input_many_times ... ok

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

     Running target/debug/deps/piped-18bd2072bbd83245

running 1 test
test piped_password ... FAILED

failures:

---- piped_password stdout ----
stdout: 
running 0 tests

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


thread 'piped_password' panicked at 'assertion failed: stdout.ends_with("Password: secret\n")', tests/piped.rs:34:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    piped_password

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

error: test failed, to rerun pass '--test piped'

The test calls an example with pipes to the child. Let's see what it executes:

$ strace -f -e trace=execve target/debug/deps/piped-18bd2072bbd83245
execve("target/debug/deps/piped-18bd2072bbd83245", ["target/debug/deps/piped-18bd2072"...], 0x7fff57676ef8 /* 49 vars */) = 0

running 1 test
strace: Process 3997473 attached
strace: Process 3997474 attached
[pid 3997474] execve("/home/teythoon/repos/pep/rust/rpassword/target/debug/examples/read-password", ["/home/teythoon/repos/pep/rust/rp"...], 0x7fffaed30158 /* 49 vars */) = 0
[pid 3997474] +++ exited with 0 +++
[pid 3997473] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3997474, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
test piped_password ... FAILED

failures:
[pid 3997473] +++ exited with 0 +++

---- piped_password stdout ----
stdout: 
running 0 tests

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


thread 'piped_password' panicked at 'assertion failed: stdout.ends_with("Password: secret\n")', tests/piped.rs:34:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    piped_password

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

+++ exited with 101 +++

Ok, let's call it and see what happens:

$ /home/teythoon/repos/pep/rust/rpassword/target/debug/examples/read-password

running 0 tests

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

That's odd, looking at the example it should prompt for a password:

$ cargo run --example read-password
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `target/debug/examples/read-password`

Password: arst
$ /home/teythoon/repos/pep/rust/rpassword/target/debug/examples/read-password

Password: arst

And now it does!

Really weird, maybe a cargo bug, screwing up file descriptors somewhere?

[teythoon]

To make it explicit, the test runs target/debug/examples/read-password but cargo miscompiles that for some reason, replacing it with what appears to be a test executable with zero tests.

[dkg]

Here is a diff between running target/debug/deps/piped-18bd2072bbd83245 as part of cargo test vs cargo test --all-targets.

i note that the --all-targets test run dynamically loads libm, though the other test run does not. i really don't understand this.

[dkg]

looks to me like when i run cargo test cargo produces: ./target/debug/examples/read_password-420acc0b3e81a06f

but when i run cargo test --all-targets, cargo produces: ./target/debug/examples/read_password-43972f448c6487b3 instead.

(i'm running cargo clean in between these tests)

[teythoon]

We think that cargo compiles the example in cfg(test). This is either a bug in cargo, or a feature, in which case this crate shouldn't expect the example to work.

I guess it is a feature in cargo. Your example can have tests, and you would expect cargo test to run them.

I made an experiment. I tucked #[test] fn test_in_example() {} into examples/read-password.rs and indeed:

[...]
     Running target/debug/examples/read_password-43972f448c6487b3

running 1 test
test test_in_example ... ok
[...]

So yeah, the test is broken and needs fixing.

As a short-term workaround for packaging, simply remove the tests/piped.rs file. The patch proposed by @edneville papers over the issue, suggesting that the test is still run, when in fact it is completely gutted.

[conradkleinespel]

Thanks @dkg @teythoon and @edneville for looking into this, your comments helped me understand where to look. I just pushed a fix as 5.0.1 to crates.io. Hopefully this will make the test pass on Debian.

[dkg]

I finally uploaded 5.0.1 to debian. sorry for the long delay!

[conradkleinespel]

That's great, thanks a lot @dkg 😃