tokio/file-io test is non-deterministic

[RalfJung]

./miri run --dep tests/pass-dep/tokio/file-io.rs -Zmiri-disable-isolation -Zmiri-many-seeds fails on seed 40 for me. Overall, around 90% of seeds seem to fail. No idea why this did not explode earlier, maybe the distribution changed recently.

tests/pass-dep/tokio/file-io.rs has failed on rustc CI; it seems to be non-deterministic. I haven't yet been able to reproduce this locally. (The reproducer I had before was completely bogus.)

@tiif can you look into this? This is causing issues for rustc CI so it is somewhat urgent.

[RalfJung]

This seems to just always fail on PR CI now for patches that don't change library... which is odd since it seems like then it shouldn't have landed in the first place?

[RalfJung]

Indeed this already has a 90% failure rate at Miri commit df96d5e, almost four months ago. No idea how we were so lucky to never see this before...

[Noratrieb]

For reference, the full stderr

Details

2025-06-01T09:00:53.4367241Z Execute `./miri test --bless` to update `tests/pass-dep/tokio/file-io.stderr` to the actual output
2025-06-01T09:00:53.4367763Z +++ <stderr output>
2025-06-01T09:00:53.4367926Z 
2025-06-01T09:00:53.4368244Z thread 'main' panicked at tests/pass-dep/tokio/file-io.rs:24:5:
2025-06-01T09:00:53.4368676Z assertion `left == right` failed
2025-06-01T09:00:53.4368953Z   left: 0
2025-06-01T09:00:53.4369173Z  right: 10
2025-06-01T09:00:53.4369387Z stack backtrace:
2025-06-01T09:00:53.4369685Z    0: std::panicking::begin_panic_handler
2025-06-01T09:00:53.4370052Z              at /checkout/library/std/src/panicking.rs:697:5
2025-06-01T09:00:53.4370426Z    1: core::panicking::panic_fmt
2025-06-01T09:00:53.4370779Z              at /checkout/library/core/src/panicking.rs:75:14
2025-06-01T09:00:53.4371236Z    2: core::panicking::assert_failed_inner
2025-06-01T09:00:53.4371619Z              at /checkout/library/core/src/panicking.rs:432:17
2025-06-01T09:00:53.4372008Z    3: core::panicking::assert_failed::<u64, u64>
2025-06-01T09:00:53.4372406Z              at /checkout/library/core/src/panicking.rs:387:5
2025-06-01T09:00:53.4372780Z    4: test_create_and_write::{closure#0}
2025-06-01T09:00:53.4373143Z              at tests/pass-dep/tokio/file-io.rs:24:5
2025-06-01T09:00:53.4373495Z    5: main::{closure#0}
2025-06-01T09:00:53.4373778Z              at tests/pass-dep/tokio/file-io.rs:14:29
2025-06-01T09:00:53.4374444Z    6: tokio::runtime::park::CachedParkThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}
2025-06-01T09:00:53.4375307Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/park.rs:284:60
2025-06-01T09:00:53.4376387Z    7: tokio::task::coop::with_budget::<std::task::Poll<()>, {closure@tokio::runtime::park::CachedParkThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}>
2025-06-01T09:00:53.4377457Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/task/coop/mod.rs:167:5
2025-06-01T09:00:53.4378495Z    8: tokio::task::coop::budget::<std::task::Poll<()>, {closure@tokio::runtime::park::CachedParkThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}>
2025-06-01T09:00:53.4379535Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/task/coop/mod.rs:133:5
2025-06-01T09:00:53.4380350Z    9: tokio::runtime::park::CachedParkThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4381152Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/park.rs:284:31
2025-06-01T09:00:53.4382038Z   10: tokio::runtime::context::blocking::BlockingRegionGuard::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4382981Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/context/blocking.rs:66:9
2025-06-01T09:00:53.4383934Z   11: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}
2025-06-01T09:00:53.4384953Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/scheduler/multi_thread/mod.rs:87:13
2025-06-01T09:00:53.4386208Z   12: tokio::runtime::context::runtime::enter_runtime::<{closure@tokio::runtime::scheduler::multi_thread::MultiThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}, ()>
2025-06-01T09:00:53.4387396Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/context/runtime.rs:65:16
2025-06-01T09:00:53.4388311Z   13: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4389267Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/scheduler/multi_thread/mod.rs:86:9
2025-06-01T09:00:53.4390115Z   14: tokio::runtime::Runtime::block_on_inner::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4390900Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/runtime.rs:370:45
2025-06-01T09:00:53.4391733Z   15: tokio::runtime::Runtime::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4392485Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/runtime.rs:342:13
2025-06-01T09:00:53.4393044Z   16: main
2025-06-01T09:00:53.4393296Z              at tests/pass-dep/tokio/file-io.rs:15:5
2025-06-01T09:00:53.4393703Z   17: <fn() as std::ops::FnOnce<()>>::call_once - shim(fn())
2025-06-01T09:00:53.4394138Z              at /checkout/library/core/src/ops/function.rs:250:5
2025-06-01T09:00:53.4394733Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2025-06-01T09:00:53.4395114Z 
2025-06-01T09:00:53.4395135Z 
2025-06-01T09:00:53.4395229Z full stderr:
2025-06-01T09:00:53.4395359Z 
2025-06-01T09:00:53.4395557Z thread 'main' panicked at tests/pass-dep/tokio/file-io.rs:24:5:
2025-06-01T09:00:53.4395984Z assertion `left == right` failed
2025-06-01T09:00:53.4396274Z   left: 0
2025-06-01T09:00:53.4396478Z  right: 10
2025-06-01T09:00:53.4396706Z stack backtrace:
2025-06-01T09:00:53.4396962Z    0: std::panicking::begin_panic_handler
2025-06-01T09:00:53.4397344Z              at /checkout/library/std/src/panicking.rs:697:5
2025-06-01T09:00:53.4397707Z    1: core::panicking::panic_fmt
2025-06-01T09:00:53.4398065Z              at /checkout/library/core/src/panicking.rs:75:14
2025-06-01T09:00:53.4398460Z    2: core::panicking::assert_failed_inner
2025-06-01T09:00:53.4398837Z              at /checkout/library/core/src/panicking.rs:432:17
2025-06-01T09:00:53.4399249Z    3: core::panicking::assert_failed::<u64, u64>
2025-06-01T09:00:53.4399633Z              at /checkout/library/core/src/panicking.rs:387:5
2025-06-01T09:00:53.4400019Z    4: test_create_and_write::{closure#0}
2025-06-01T09:00:53.4400364Z              at tests/pass-dep/tokio/file-io.rs:24:5
2025-06-01T09:00:53.4400711Z    5: main::{closure#0}
2025-06-01T09:00:53.4401013Z              at tests/pass-dep/tokio/file-io.rs:14:29
2025-06-01T09:00:53.4401930Z    6: tokio::runtime::park::CachedParkThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}
2025-06-01T09:00:53.4402813Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/park.rs:284:60
2025-06-01T09:00:53.4403887Z    7: tokio::task::coop::with_budget::<std::task::Poll<()>, {closure@tokio::runtime::park::CachedParkThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}>
2025-06-01T09:00:53.4404937Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/task/coop/mod.rs:167:5
2025-06-01T09:00:53.4406077Z    8: tokio::task::coop::budget::<std::task::Poll<()>, {closure@tokio::runtime::park::CachedParkThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}>
2025-06-01T09:00:53.4407125Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/task/coop/mod.rs:133:5
2025-06-01T09:00:53.4407940Z    9: tokio::runtime::park::CachedParkThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4408752Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/park.rs:284:31
2025-06-01T09:00:53.4409622Z   10: tokio::runtime::context::blocking::BlockingRegionGuard::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4410557Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/context/blocking.rs:66:9
2025-06-01T09:00:53.4411533Z   11: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}
2025-06-01T09:00:53.4412529Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/scheduler/multi_thread/mod.rs:87:13
2025-06-01T09:00:53.4413932Z   12: tokio::runtime::context::runtime::enter_runtime::<{closure@tokio::runtime::scheduler::multi_thread::MultiThread::block_on<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>::{closure#0}}, ()>
2025-06-01T09:00:53.4415141Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/context/runtime.rs:65:16
2025-06-01T09:00:53.4416045Z   13: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4417004Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/scheduler/multi_thread/mod.rs:86:9
2025-06-01T09:00:53.4417955Z   14: tokio::runtime::Runtime::block_on_inner::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4418735Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/runtime.rs:370:45
2025-06-01T09:00:53.4419507Z   15: tokio::runtime::Runtime::block_on::<{async block@tests/pass-dep/tokio/file-io.rs:12:1: 12:15}>
2025-06-01T09:00:53.4420278Z              at /cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/runtime.rs:342:13
2025-06-01T09:00:53.4420825Z   16: main
2025-06-01T09:00:53.4421091Z              at tests/pass-dep/tokio/file-io.rs:15:5
2025-06-01T09:00:53.4421482Z   17: <fn() as std::ops::FnOnce<()>>::call_once - shim(fn())
2025-06-01T09:00:53.4421909Z              at /checkout/library/core/src/ops/function.rs:250:5
2025-06-01T09:00:53.4422434Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[Noratrieb]

Hm, this uses .write()

miri/tests/pass-dep/tokio/file-io.rs

Line 23 in 7f439a2

file.write(b"some bytes").await?;

which is not known for being guaranteed to write all the bytes :D

[Noratrieb]

I don't know why, but I can't reproduce all the failures on my computer, it works reliable there.. what makes us different? #4368 should fix it but I haven't been able to check whether that's true on my computer

[tiif]

Yeah I can look into this. But finding the root cause of this might take some time.

Since it is causing problem for rustc CI, maybe it'd be good to disable this test for now?

[RalfJung]

I can't reproduce all the failures on my computer,

How are you trying to reproduce it?
What OS are you on?

[Noratrieb]

I'm on Linux (NixOS). Looking at the Miri code, it just forwards to the host write, so I'm not surprised that writes all the bytes reliably every time on my system and often in CI. I'm surprised that it fails that reliably on your system :D.

Maybe it would make sense for Miri to inject short writes into write and short reads into read to detect this kind of bug more reliably.

[Noratrieb]

Oh, so that's not even the bug. That's disappointing.

[RalfJung]

Ah true for files we do forward to the host, I forgot that this is not a socket.

Maybe it would make sense for Miri to inject short writes into write and short reads into read to detect this kind of bug more reliably.

Yeah that would make sense.