investigate pre-prod warning: `imitate_layer_access` warns about `dropping ValuesReconstructState while some IOs have not been completed`

[problame]

This is not a potential corruption, because it's on a read where the result is not used, rather than a write that might conflict with something else in the background.

This should be straightforward to fix, as the backtrace below points to where it's happening. We should fix whatever in this code path is not polling an I/O future to completion.

environment=pre-prod

2025-03-18T18:59:27.055981Z  WARN eviction_task{tenant_id=7204b99abc0569d5be74c6c09d49c4f5 shard_id=0000 timeline_id=4ce47203fcee9dd236c4d2a062c8e91b}:eviction_iteration{policy_kind="OnlyImitiate"}:imitate_layer_accesses:imitate_synthetic_size_calculation_worker:gather_inputs:find_gc_cutoffs{timeline_id=4ce47203fcee9dd236c4d2a062c8e91b}: dropping ValuesReconstructState while some IOs have not been completed num_active_ios=1 sidecar_task_id=None backtrace=   0: std::backtrace_rs::backtrace::libunwind::trace
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5
   1: std::backtrace_rs::backtrace::trace_unsynchronized
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2: std::backtrace::Backtrace::create
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/backtrace.rs:331:13
   3: <pageserver::tenant::storage_layer::ValuesReconstructState as core::ops::drop::Drop>::drop
             at /home/nonroot/pageserver/src/tenant/storage_layer.rs:597:24
   4: core::ptr::drop_in_place<pageserver::tenant::storage_layer::ValuesReconstructState>
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/ptr/mod.rs:523:1
   5: core::ptr::drop_in_place<pageserver::tenant::timeline::Timeline::get::{{closure}}>
             at /home/nonroot/pageserver/src/tenant/timeline.rs:1150:5
   6: core::ptr::drop_in_place<pageserver::pgdatadir_mapping::<impl pageserver::tenant::timeline::Timeline>::is_latest_commit_timestamp_ge_than::{{closure}}>
             at /home/nonroot/pageserver/src/pgdatadir_mapping.rs:801:14
   7: core::ptr::drop_in_place<pageserver::pgdatadir_mapping::<impl pageserver::tenant::timeline::Timeline>::find_lsn_for_timestamp::{{closure}}>
             at /home/nonroot/pageserver/src/pgdatadir_mapping.rs:721:22
   8: core::ptr::drop_in_place<pageserver::tenant::timeline::Timeline::find_gc_time_cutoff::{{closure}}>
             at /home/nonroot/pageserver/src/tenant/timeline.rs:5816:93
   9: core::ptr::drop_in_place<pageserver::tenant::timeline::Timeline::find_gc_cutoffs::{{closure}}::{{closure}}>
             at /home/nonroot/pageserver/src/tenant/timeline.rs:5921:80
  10: core::mem::manually_drop::ManuallyDrop<T>::drop
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/mem/manually_drop.rs:256:18
  11: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop::__drop_inner
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:285:22
  12: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/pin-project-lite-0.2.13/src/lib.rs:1300:17
  13: core::ptr::drop_in_place<tracing::instrument::Instrumented<pageserver::tenant::timeline::Timeline::find_gc_cutoffs::{{closure}}::{{closure}}>>
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/ptr/mod.rs:523:1
  14: core::ptr::drop_in_place<pageserver::tenant::timeline::Timeline::find_gc_cutoffs::{{closure}}>
             at /home/nonroot/pageserver/src/tenant/timeline.rs:5890:66
  15: core::ptr::drop_in_place<pageserver::tenant::Tenant::refresh_gc_info_internal::{{closure}}>
             at /home/nonroot/pageserver/src/tenant.rs:4624:22
  16: core::mem::manually_drop::ManuallyDrop<T>::drop
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/mem/manually_drop.rs:256:18
  17: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop::__drop_inner
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:285:22
  18: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/pin-project-lite-0.2.13/src/lib.rs:1300:17
  19: core::ptr::drop_in_place<tracing::instrument::Instrumented<pageserver::tenant::size::gather_inputs::{{closure}}>>
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/ptr/mod.rs:523:1
  20: core::ptr::drop_in_place<(tokio_util::sync::cancellation_token::WaitForCancellationFuture,tracing::instrument::Instrumented<pageserver::tenant::size::gather_inputs::{{closure}}>)>
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/ptr/mod.rs:523:1
  21: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::imitate_synthetic_size_calculation_worker::{{closure}}::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:548:9
  22: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321:9
  23: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::imitate_synthetic_size_calculation_worker::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:499:5
  24: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::imitate_layer_accesses::{{closure}}::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:429:22
  25: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321:9
  26: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::imitate_layer_accesses::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:363:5
  27: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::imitiate_only::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:321:14
  28: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::eviction_iteration::{{closure}}::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:147:22
  29: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321:9
  30: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::eviction_iteration::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:118:5
  31: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::eviction_task::{{closure}}::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:102:18
  32: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321:9
  33: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::eviction_task::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:77:5
  34: pageserver::tenant::timeline::eviction_task::<impl pageserver::tenant::timeline::Timeline>::launch_eviction_task::{{closure}}
             at /home/nonroot/pageserver/src/tenant/timeline/eviction_task.rs:71:50
  35: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::future::future::Future>::poll
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panic/unwind_safe.rs:297:9
  36: <futures_util::future::future::catch_unwind::CatchUnwind<Fut> as core::future::future::Future>::poll::{{closure}}
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/catch_unwind.rs:37:42
  37: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panic/unwind_safe.rs:272:9
  38: std::panicking::try::do_call
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:584:40
  39: std::panicking::try
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:547:19
  40: std::panic::catch_unwind
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panic.rs:358:14
  41: <futures_util::future::future::catch_unwind::CatchUnwind<Fut> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/catch_unwind.rs:37:9
  42: pageserver::task_mgr::task_wrapper::{{closure}}::{{closure}}
             at /home/nonroot/pageserver/src/task_mgr.rs:476:62
  43: <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll::{{closure}}
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:391:31
  44: tokio::task::task_local::LocalKey<T>::scope_inner
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:217:19
  45: <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:387:19
  46: <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll::{{closure}}
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:391:31
  47: tokio::task::task_local::LocalKey<T>::scope_inner
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:217:19
  48: <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/task/task_local.rs:387:19
  49: pageserver::task_mgr::task_wrapper::{{closure}}
             at /home/nonroot/pageserver/src/task_mgr.rs:501:9
  50: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/future/future.rs:124:9
  51: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/core.rs:331:17
  52: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/loom/std/unsafe_cell.rs:16:9
  53: tokio::runtime::task::core::Core<T,S>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/core.rs:320:30
  54: tokio::runtime::task::harness::poll_future::{{closure}}
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:532:19
  55: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panic/unwind_safe.rs:272:9
  56: std::panicking::try::do_call
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:584:40
  57: std::panicking::try
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:547:19
  58: std::panic::catch_unwind
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panic.rs:358:14
  59: tokio::runtime::task::harness::poll_future
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:520:18
  60: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:209:27
  61: tokio::runtime::task::harness::Harness<T,S>::poll
             at /home/nonroot/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:154:15
  62: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
  63: tokio::runtime::scheduler::multi_thread::worker::Context::run
  64: tokio::runtime::context::runtime::enter_runtime
  65: tokio::runtime::scheduler::multi_thread::worker::run

[ding-young]

Hi, may I give it a try on this issue?

[problame]

Hey @ding-young , sure, give it a try.

It's probably some tokio::select! that stops running the size calculation future to completion.
Size calculation should be sensitive to Timeline::cancel/Tenant::cancel nowadays, so, it might be as simple as getting rid of that tokio::select!.

[problame]

@VladLazar found another occurence in

• pagserver: dropping out of read path with active IOs #12006

I noticed a bunch of these last week: dropping ValuesReconstructState while some IOs have not been completed. Full log example here. I don't think all of them are around restarts.

Discussion in bug triage:

Christian's suggestion is that we should fix this by always polling to completion.

Vlad suggests that lsn-by-timestamp is a common cause of this. Also synthetic size calculation, which uses a tokio::select for timeouts.

[arpad-m]

Related: #12369. But it's a new regression as my PR added another select (which is sadly needed as we are doing reads when we already know that we are cancelling, but we haven't cancelled yet).

[ding-young]

Are there any specific test setups or tips for reproducing this warning message locally? I’ve been keeping an eye on this issue, but it's been challenging to reproduce the exact scenario locally.

[arpad-m]

I don't think we need to come up with reproducers, it's enough to remove select here in the specific instances.

The idea is to pass a per-request cancellation token via RequestContext, then select on that one, and properly abort things if the cancellation fired. I'll do a PR for that.