thread 'pipe_from_one_command_to_another' panicked at 'assertion failed: (left == right)

[maminrayej]

I was working to fix the CI on branch tokio-1.20.x (#5999). I've found out sometimes the test tokio full (windows-latest) job fails. It doesn't always fail in the same way. here is one of the failures I saw:
I trimmed the "\0\0\0.." sequence to make the log more readable. (if I counted correctly, it was 361560 \0s in that sequence).

2023-09-13T08:36:48.9539883Z running 5 tests
2023-09-13T08:36:49.2631815Z test pipe_from_one_command_to_another ... FAILED
2023-09-13T08:36:49.2818939Z test status_closes_any_pipes ... ok
2023-09-13T08:36:49.3002809Z test try_wait ... ok
2023-09-13T08:36:49.3203051Z test wait_with_output_captures ... ok
2023-09-13T08:36:50.0538803Z test feed_a_lot ... ok
2023-09-13T08:36:50.0539460Z 
2023-09-13T08:36:50.0539821Z failures:
2023-09-13T08:36:50.0548218Z 
2023-09-13T08:36:50.0553802Z ---- pipe_from_one_command_to_another stdout ----
2023-09-13T08:36:50.0554674Z thread 'pipe_from_one_command_to_another' panicked at 'assertion failed: `(left == right)`
2023-09-13T08:36:50.0555475Z   left: `"hello world! please pipe this message through"`,
2023-09-13T08:36:50.2566512Z  right: `"\0\0\0..."`', tests-integration\tests\process_stdio.rs:196:5
2023-09-13T08:36:50.4080456Z error: test failed, to rerun pass '-p tests-integration --test process_stdio'
2023-09-13T08:36:50.4081116Z stack backtrace:
2023-09-13T08:36:50.4081588Z    0: std::panicking::begin_panic_handler
2023-09-13T08:36:50.4081976Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library\std\src\panicking.rs:584
2023-09-13T08:36:50.4082335Z    1: core::panicking::panic_fmt
2023-09-13T08:36:50.4082700Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library\core\src\panicking.rs:142
2023-09-13T08:36:50.4083049Z    2: core::fmt::Arguments::new_v1
2023-09-13T08:36:50.4084754Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library\core\src\fmt\mod.rs:392
2023-09-13T08:36:50.4085190Z    3: core::panicking::assert_failed_inner
2023-09-13T08:36:50.4085644Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library\core\src\panicking.rs:224
2023-09-13T08:36:50.4086127Z    4: core::panicking::assert_failed<str,alloc::string::String>
2023-09-13T08:36:50.4086616Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\core\src\panicking.rs:181
2023-09-13T08:36:50.4087121Z    5: process_stdio::pipe_from_one_command_to_another::async_block$0
2023-09-13T08:36:50.4087935Z              at .\tests\process_stdio.rs:196
2023-09-13T08:36:50.4088325Z    6: core::future::from_generator::impl$1::poll<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> >
2023-09-13T08:36:50.4088728Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\core\src\future\mod.rs:91
2023-09-13T08:36:50.4089198Z    7: core::future::future::impl$1::poll<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > > >
2023-09-13T08:36:50.4089677Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\core\src\future\future.rs:124
2023-09-13T08:36:50.4090226Z    8: tokio::runtime::basic_scheduler::impl$9::block_on::closure$0::closure$0::closure$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > > > >
2023-09-13T08:36:50.4090758Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:543
2023-09-13T08:36:50.4112477Z    9: tokio::coop::with_budget::closure$0<enum$<core::task::poll::Poll<tuple$<> > >,tokio::runtime::basic_scheduler::impl$9::block_on::closure$0::closure$0::closure_env$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_
2023-09-13T08:36:50.4113367Z              at D:\a\tokio\tokio\tokio\src\coop.rs:102
2023-09-13T08:36:50.4114264Z   10: std::thread::local::LocalKey<core::cell::Cell<tokio::coop::Budget> >::try_with<core::cell::Cell<tokio::coop::Budget>,tokio::coop::with_budget::closure_env$0<enum$<core::task::poll::Poll<tuple$<> > >,tokio::runtime::basic_scheduler::impl$9::block_on::closu
2023-09-13T08:36:50.4114800Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\std\src\thread\local.rs:445
2023-09-13T08:36:50.4115374Z   11: std::thread::local::LocalKey<core::cell::Cell<tokio::coop::Budget> >::with<core::cell::Cell<tokio::coop::Budget>,tokio::coop::with_budget::closure_env$0<enum$<core::task::poll::Poll<tuple$<> > >,tokio::runtime::basic_scheduler::impl$9::block_on::closure$0
2023-09-13T08:36:50.4115901Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\std\src\thread\local.rs:421
2023-09-13T08:36:50.4116182Z   12: tokio::coop::with_budget
2023-09-13T08:36:50.4116579Z              at D:\a\tokio\tokio\tokio\src\coop.rs:95
2023-09-13T08:36:50.4117168Z   13: tokio::coop::budget
2023-09-13T08:36:50.4117551Z              at D:\a\tokio\tokio\tokio\src\coop.rs:72
2023-09-13T08:36:50.4118258Z   14: tokio::runtime::basic_scheduler::impl$9::block_on::closure$0::closure$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > > > >
2023-09-13T08:36:50.4118781Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:543
2023-09-13T08:36:50.4119785Z   15: tokio::runtime::basic_scheduler::Context::enter<enum$<core::task::poll::Poll<tuple$<> > >,tokio::runtime::basic_scheduler::impl$9::block_on::closure$0::closure_env$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe
2023-09-13T08:36:50.4121174Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:367
2023-09-13T08:36:50.4121817Z   16: tokio::runtime::basic_scheduler::impl$9::block_on::closure$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > > > >
2023-09-13T08:36:50.4122328Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:542
2023-09-13T08:36:50.4122849Z   17: tokio::runtime::basic_scheduler::impl$9::enter::closure$0<tokio::runtime::basic_scheduler::impl$9::block_on::closure_env$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_e
2023-09-13T08:36:50.4123350Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:613
2023-09-13T08:36:50.4123888Z   18: tokio::macros::scoped_tls::ScopedKey<tokio::runtime::basic_scheduler::Context>::set<tokio::runtime::basic_scheduler::Context,tokio::runtime::basic_scheduler::impl$9::enter::closure_env$0<tokio::runtime::basic_scheduler::impl$9::block_on::closure_env$0<cor
2023-09-13T08:36:50.4124370Z              at D:\a\tokio\tokio\tokio\src\macros\scoped_tls.rs:61
2023-09-13T08:36:50.4124930Z   19: tokio::runtime::basic_scheduler::CoreGuard::enter<tokio::runtime::basic_scheduler::impl$9::block_on::closure_env$0<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > 
2023-09-13T08:36:50.4125462Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:613
2023-09-13T08:36:50.4125980Z   20: tokio::runtime::basic_scheduler::CoreGuard::block_on<core::pin::Pin<ref_mut$<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > > > >
2023-09-13T08:36:50.4126476Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:533
2023-09-13T08:36:50.4126971Z   21: tokio::runtime::basic_scheduler::BasicScheduler::block_on<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > >
2023-09-13T08:36:50.4127447Z              at D:\a\tokio\tokio\tokio\src\runtime\basic_scheduler.rs:179
2023-09-13T08:36:50.4127909Z   22: tokio::runtime::Runtime::block_on<core::future::from_generator::GenFuture<enum$<process_stdio::pipe_from_one_command_to_another::async_block_env$0> > >
2023-09-13T08:36:50.4128331Z              at D:\a\tokio\tokio\tokio\src\runtime\mod.rs:482
2023-09-13T08:36:50.4128648Z   23: process_stdio::pipe_from_one_command_to_another
2023-09-13T08:36:50.4128913Z              at .\tests\process_stdio.rs:201
2023-09-13T08:36:50.4129235Z   24: process_stdio::pipe_from_one_command_to_another::closure$0
2023-09-13T08:36:50.4129543Z              at .\tests\process_stdio.rs:156
2023-09-13T08:36:50.4129929Z   25: core::ops::function::FnOnce::call_once<process_stdio::pipe_from_one_command_to_another::closure_env$0,tuple$<> >
2023-09-13T08:36:50.4130540Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\core\src\ops\function.rs:248
2023-09-13T08:36:50.4130898Z   26: core::ops::function::FnOnce::call_once
2023-09-13T08:36:50.4131245Z              at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3\library\core\src\ops\function.rs:248
2023-09-13T08:36:50.4131858Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2023-09-13T08:36:50.4132244Z 
2023-09-13T08:36:50.4132250Z 
2023-09-13T08:36:50.4132340Z failures:
2023-09-13T08:36:50.4132601Z     pipe_from_one_command_to_another
2023-09-13T08:36:50.4132766Z 
2023-09-13T08:36:50.4132977Z test result: FAILED. 4 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.10s
2023-09-13T08:36:50.4133418Z 
2023-09-13T08:36:50.4159774Z ##[error]Process completed with exit code 101.
2023-09-13T08:36:50.4651075Z Post job cleanup.
2023-09-13T08:36:50.9793727Z [command]"C:\Program Files\Git\bin\git.exe" version
2023-09-13T08:36:51.0627336Z git version 2.42.0.windows.2
2023-09-13T08:36:51.0737877Z Temporarily overriding HOME='D:\a\_temp\3109a3c8-4446-45ee-8d1b-c94945435457' before making global git config changes
2023-09-13T08:36:51.0738733Z Adding repository directory to the temporary git global config as a safe directory
2023-09-13T08:36:51.0752715Z [command]"C:\Program Files\Git\bin\git.exe" config --global --add safe.directory D:\a\tokio\tokio
2023-09-13T08:36:51.1210726Z [command]"C:\Program Files\Git\bin\git.exe" config --local --name-only --get-regexp core\.sshCommand
2023-09-13T08:36:51.1627135Z [command]"C:\Program Files\Git\bin\git.exe" submodule foreach --recursive "sh -c \"git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :\""
2023-09-13T08:36:51.8879211Z [command]"C:\Program Files\Git\bin\git.exe" config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2023-09-13T08:36:51.9218344Z http.https://github.com/.extraheader
2023-09-13T08:36:51.9264342Z [command]"C:\Program Files\Git\bin\git.exe" config --local --unset-all http.https://github.com/.extraheader
2023-09-13T08:36:51.9652195Z [command]"C:\Program Files\Git\bin\git.exe" submodule foreach --recursive "sh -c \"git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :\""
2023-09-13T08:36:52.5992778Z Cleaning up orphan processes

[azuredream]

Hi @Darksonn,
Still help wanted?
I tried to reproduce this, but couldn't trigger the test.

cargo test --test process_stdio
Running tests/process_stdio.rs (...tokio/tokio/target/debug/deps/process_stdio-8d3f057217eeb3a9)
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

I'd appreciate it if you could share your thought about the root cause or how to debug.

[Darksonn]

Well, the failure seems to be pretty rare, so you would probably need to run it many times to trigger it. Also, I think it might only happen on Windows.

I don't even know if the problem is still here.