From 021a57214518eba25f085b31d041983ff8e1238f Mon Sep 17 00:00:00 2001 From: Scott Lamb Date: Thu, 20 Oct 2022 22:16:55 -0700 Subject: [PATCH] Address CI failures I'm not sure what changed. We have a `Cargo.lock`, and these runs were with identical code: https://github.com/scottlamb/retina/actions/runs/3148795378 passed https://github.com/scottlamb/retina/actions/runs/3148801810 failed Nonetheless, the failures started happening on CI (and not my local machine). Something changed with respect to the other futures are polled or something. Not having a keepalive future prevents tokio from "auto-advancing" the paused time (a misfeature IMHO). There's still some advance I think from background_teardown's timeout_at, but that's late enough to not cause the same test failure. Failure below. ``` ---- client::tests::simple stdout ---- thread 'client::tests::simple' panicked at 'assertion failed: `(left == right)` left: `Options`, right: `Teardown`', src/client/mod.rs:2547:17 stack backtrace: 0: rust_begin_unwind at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/panicking.rs:584:5 1: core::panicking::panic_fmt at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/panicking.rs:142:14 error: test failed, to rerun pass '-p retina --lib' 2: core::panicking::assert_failed_inner 3: core::panicking::assert_failed at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/panicking.rs:181:5 4: retina::client::tests::req_response::{{closure}} at ./src/client/mod.rs:2547:17 5: as core::future::future::Future>::poll at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/future/mod.rs:91:19 6: as core::future::future::Future>::poll at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/future/maybe_done.rs:68:48 7: retina::client::tests::simple::{{closure}}::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/macros/join.rs:116:24 8: as core::future::future::Future>::poll at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/future/poll_fn.rs:38:9 9: retina::client::tests::simple::{{closure}} at ./src/client/mod.rs:2651:9 10: as core::future::future::Future>::poll at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/future/mod.rs:91:19 11: as core::future::future::Future>::poll at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/future/future.rs:124:9 12: tokio::runtime::basic_scheduler::CoreGuard::block_on::{{closure}}::{{closure}}::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:508:48 13: tokio::coop::with_budget::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/coop.rs:102:9 14: std::thread::local::LocalKey::try_with at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:445:16 15: std::thread::local::LocalKey::with at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/std/src/thread/local.rs:421:9 16: tokio::coop::with_budget at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/coop.rs:95:5 17: tokio::coop::budget at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/coop.rs:72:5 18: tokio::runtime::basic_scheduler::CoreGuard::block_on::{{closure}}::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:508:25 19: tokio::runtime::basic_scheduler::Context::enter at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:362:19 20: tokio::runtime::basic_scheduler::CoreGuard::block_on::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:507:36 21: tokio::runtime::basic_scheduler::CoreGuard::enter::{{closure}} at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:565:57 22: tokio::macros::scoped_tls::ScopedKey::set at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/macros/scoped_tls.rs:61:9 23: tokio::runtime::basic_scheduler::CoreGuard::enter at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:565:27 24: tokio::runtime::basic_scheduler::CoreGuard::block_on at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:498:9 25: tokio::runtime::basic_scheduler::BasicScheduler::block_on at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/basic_scheduler.rs:174:24 26: tokio::runtime::Runtime::block_on at /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.19.2/src/runtime/mod.rs:480:46 27: retina::client::tests::simple at ./src/client/mod.rs:2664:9 28: retina::client::tests::simple::{{closure}} at ./src/client/mod.rs:2561:11 29: core::ops::function::FnOnce::call_once at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/ops/function.rs:248:5 30: core::ops::function::FnOnce::call_once at /rustc/a55dd71d5fb0ec5a6a3a9e8c27b2127ba491ce52/library/core/src/ops/function.rs:248:5 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. ``` --- src/client/mod.rs | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/src/client/mod.rs b/src/client/mod.rs index 2e2c62b..6a6b966 100644 --- a/src/client/mod.rs +++ b/src/client/mod.rs @@ -2377,11 +2377,11 @@ impl futures::Stream for Session { } // Then check if it's time for a new keepalive. - if matches!( - self.0.keepalive_timer.as_mut().unwrap().as_mut().poll(cx), - Poll::Ready(()) - ) { - self.as_mut().handle_keepalive_timer(cx)?; + // Note: in production keepalive_timer is always Some. Tests may disable it. + if let Some(t) = self.0.keepalive_timer.as_mut() { + if matches!(t.as_mut().poll(cx), Poll::Ready(())) { + self.as_mut().handle_keepalive_timer(cx)?; + } } // Then finish flushing the current keepalive if necessary. @@ -2608,6 +2608,11 @@ mod tests { let session = session.unwrap(); tokio::pin!(session); + // XXX: tokio will "auto-advance" paused time when timers are polled. + // This is not great for this test. Disable keepalives to prevent it. + // + session.0.keepalive_timer = None; + // Packets: first ignored one (unassigned channel), then one passed through. tokio::join!( async { @@ -2658,8 +2663,9 @@ mod tests { ); assert_eq!(group.stale_sessions().num_sessions, 0); - // elapsed is not zero because tokio advances the time unnecessarily, grr. - // https://github.com/tokio-rs/tokio/issues/3108 + // XXX: tokio will "auto-advance" paused time when timers are polled, + // including background_teardown's timer_at, so elapsed > 0. + // let elapsed = tokio::time::Instant::now() - drop_time; assert!( elapsed < std::time::Duration::from_secs(60),