cargo test does not capture stdout/stderr in tokio::spawn async blocks

[parasyte]

Version

tokio = "=0.2.0-alpha.6"

Platform

Darwin JayMBP.kodewerx.org 18.7.0 Darwin Kernel Version 18.7.0: Tue Aug 20 16:57:14 PDT 2019; root:xnu-4903.271.2~2/RELEASE_X86_64 x86_64

Description

cargo test captures logs from stdout/stderr by using an undocumented function pair that internally manipulates the way print! and friends work. When running a test using the Tokio runtime, any uses of the print! family macros do not get captured.

My actual tests have a more complex setup to allow running multiple async tests in parallel. But this minimal example demonstrates the issue.

#[cfg(test)]
mod tests {
    use std::time::Duration;
    use tokio::runtime::Runtime;

    #[test]
    fn async_test() {
        let rt = Runtime::new().unwrap();
        rt.block_on(async {
            println!("This should be captured by the test runner.");
 
            tokio::spawn(async {
                println!("This should also be captured by the test runner.");
            });

            println!("Wait a little while...");
            tokio::timer::delay_for(Duration::from_millis(10)).await;

            println!("All of this text should have been captured.");
        });
    }
}

Expected result:

running 1 test
test tests::async_test ... ok

Actual result:

running 1 test
This should also be captured by the test runner.
test tests::async_test ... ok

When running without capture, you will see all output printed as expected:

$ cargo test -- --nocapture

running 1 test
This should be captured by the test runner.
Wait a little while...
This should also be captured by the test runner.
All of this text should have been captured.
test tests::async_test ... ok

[DoumanAsh]

I think it is rust's bug, not tokio?

Most probably using single threaded runtime or tokio::test would mitigate it

[parasyte]

IIRC, I ran the same test with the current_thread executor and it didn't change the result. That's why I created the ticket. I could have misinterpreted things while testing, but that is how I remember it.

[DoumanAsh]

That would be strange... I'd need to check it.
tokio itself shouldn't do by itself anything like rustc's testing framework, so we'd need to understand how exactly rustc's test generator does capture thing

[parasyte]

I ran a similar test on both std::thread and tokio::runtime::current_thread. The issue is reproduced in the former case, but not the latter. Closing this ticket since it's clearly not caused by Tokio.

#[test]
fn std_println() {
    use std::thread;

    println!("This should be captured by the test runner.");

    thread::spawn(move || {
        println!("This should also be captured by the test runner.");
    });

    println!("Wait a little while...");
    thread::sleep(Duration::from_millis(10));

    println!("All of this text should have been captured.");
}

#[test]
fn tokio_current_thread_println() {
    use tokio::runtime::current_thread::Runtime;

    let mut rt = Runtime::new().unwrap();
    rt.block_on(async {
        println!("This should be captured by the test runner.");

        tokio::spawn(async {
            println!("This should also be captured by the test runner.");
        });

        println!("Wait a little while...");
        tokio::timer::delay_for(Duration::from_millis(10)).await;

        println!("All of this text should have been captured.");
    });
}

rust-lang/rust#42474