scylladb/scylla-rust-driver

`test_tracing` is probably flaky with Cassandra

wprzytula opened this issue · 1 comments

It failed twice in an unrelated pull request (#955).

Logs:
https://github.com/scylladb/scylla-rust-driver/actions/runs/8267645061
https://github.com/scylladb/scylla-rust-driver/actions/runs/8269633516

Example:

---- transport::session_test::test_tracing stdout ----
Unique name: test_rust_1710345586_63
thread 'transport::session_test::test_tracing' panicked at scylla/src/transport/session_test.rs:1062:5:
No rows for tracing with this session id!
stack backtrace:
// initial frames omitted
  19:     0x563ae10baa96 - scylla::transport::session_test::assert_in_tracing_table::{{closure}}::hd4586b50cedb3ae9
                               at /home/runner/work/scylla-rust-driver/scylla-rust-driver/scylla/src/transport/session_test.rs:1062:5
  20:     0x563ae10b6de4 - scylla::transport::session_test::test_tracing_prepare::{{closure}}::hf62a9c69a433c71e
                               at /home/runner/work/scylla-rust-driver/scylla-rust-driver/scylla/src/transport/session_test.rs:924:54
  21:     0x563ae10d3dc2 - scylla::transport::session_test::test_tracing::{{closure}}::h1f54523201107fee
                               at /home/runner/work/scylla-rust-driver/scylla-rust-driver/scylla/src/transport/session_test.rs:854:48
  22:     0x563ae0e4c8f8 - <core::pin::Pin<P> as core::future::future::Future>::poll::hd7cfb3aeff23cadd
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/future/future.rs:124:9
  23:     0x563ae0e4cd8b - <core::pin::Pin<P> as core::future::future::Future>::poll::hf117c9ba3dcd69b6
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/future/future.rs:124:9
  24:     0x563ae076f834 - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::{{closure}}::h0b3a7e8eafd583ce
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:659:57
  25:     0x563ae076f76a - tokio::runtime::coop::with_budget::h78d70fa39d0ef170
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/coop.rs:107:5
  26:     0x563ae076f76a - tokio::runtime::coop::budget::h59dfbe4c218c436c
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/coop.rs:73:5
  27:     0x563ae076f76a - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::h844aed0b31b819e6
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:659:25
  28:     0x563ae076e3ec - tokio::runtime::scheduler::current_thread::Context::enter::hccda4e68809c9a72
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:404:19
  29:     0x563ae076ef5e - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::haa4c6f519e92555e
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:658:36
  30:     0x563ae076ec6b - tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}::h32e21bb7f52ed9d6
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:737:68
  31:     0x563ae10fe29b - tokio::runtime::context::scoped::Scoped<T>::set::hc0599220d65f0ebb
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context/scoped.rs:40:9
  32:     0x563ae07e5419 - tokio::runtime::context::set_scheduler::{{closure}}::hb0516ecc898f2643
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context.rs:176:26
  33:     0x563ae0a779c6 - std::thread::local::LocalKey<T>::try_with::h9afabac36ee26a0f
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/local.rs:270:16
  34:     0x563ae0a6de5a - std::thread::local::LocalKey<T>::with::h01e6595188bf62f4
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/local.rs:246:9
  35:     0x563ae07e53cd - tokio::runtime::context::set_scheduler::hd125b8ea9ff33108
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context.rs:176:9
  36:     0x563ae076ea00 - tokio::runtime::scheduler::current_thread::CoreGuard::enter::he5f51e66f8f22c41
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:737:27
  37:     0x563ae076ec9d - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::h50687e20fb0100ef
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:646:19
  38:     0x563ae07666ed - tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}::h74aabcc47f6c8f7c
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:175:28
  39:     0x563ae010b11a - tokio::runtime::context::runtime::enter_runtime::he9fcdcca03bba6f5
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context/runtime.rs:65:16
  40:     0x563ae07665fe - tokio::runtime::scheduler::current_thread::CurrentThread::block_on::hbd4575f9a361a8a4
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/current_thread/mod.rs:167:9
  41:     0x563ae0fd026d - tokio::runtime::runtime::Runtime::block_on::h6e6152f84a2d7cbd
                               at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/runtime.rs:348:47
  42:     0x563ae0ab6f76 - scylla::transport::session_test::test_tracing::hc26e957d2c28b869
                               at /home/runner/work/scylla-rust-driver/scylla-rust-driver/scylla/src/transport/session_test.rs:858:5
  43:     0x563ae10d3107 - scylla::transport::session_test::test_tracing::{{closure}}::h1d6e8a7ef470c804
                               at /home/runner/work/scylla-rust-driver/scylla-rust-driver/scylla/src/transport/session_test.rs:838:24
  44:     0x563ae0c119f6 - core::ops::function::FnOnce::call_once::hee6fe66e50dfa79c
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  45:     0x563ae158d83f - core::ops::function::FnOnce::call_once::h8dc6907944022cf6
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  46:     0x563ae158d83f - test::__rust_begin_short_backtrace::haae1a87433f1efb3
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:627:18
  47:     0x563ae158c5c1 - test::run_test_in_process::{{closure}}::h8c7decfa7c14e152
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:650:60
  48:     0x563ae158c5c1 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h19e6ff056d9d21e9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panic/unwind_safe.rs:272:9
  49:     0x563ae158c5c1 - std::panicking::try::do_call::h89c848fcaa37c035
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  50:     0x563ae158c5c1 - std::panicking::try::h57ab3dc74e2839b8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  51:     0x563ae158c5c1 - std::panic::catch_unwind::hfb6a1b1abc120fb9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  52:     0x563ae158c5c1 - test::run_test_in_process::h5ae2f9875edd562d
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:650:27
  53:     0x563ae158c5c1 - test::run_test::{{closure}}::h35d7300d8928a067
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:573:43
  54:     0x563ae15538f6 - test::run_test::{{closure}}::h7525ced405d23d1b
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:601:41
  55:     0x563ae15538f6 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4e7db78ce05afad8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:155:18
  56:     0x563ae1558957 - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hcfbcb64f1a1b3482
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/mod.rs:529:17
  57:     0x563ae1558957 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h9d89c5c4108bd689
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panic/unwind_safe.rs:272:9
  58:     0x563ae1558957 - std::panicking::try::do_call::h8a4869bc94ec50c9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  59:     0x563ae1558957 - std::panicking::try::h9a576f20ff81ac30
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  60:     0x563ae1558957 - std::panic::catch_unwind::hbcb4e3f860ef9830
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  61:     0x563ae1558957 - std::thread::Builder::spawn_unchecked_::{{closure}}::h93c79a6be1505948
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/mod.rs:528:30
  62:     0x563ae1558957 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h426d96740c81bdaf
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  63:     0x563ae1872a55 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h12de4fc57affb195
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/alloc/src/boxed.rs:2015:9
  64:     0x563ae1872a55 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h3c619f45059d5cf1
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/alloc/src/boxed.rs:2015:9
  65:     0x563ae1872a55 - std::sys::unix::thread::Thread::new::thread_start::hbac657605e4b7389
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys/unix/thread.rs:108:17
  66:     0x7fc151a94ac3 - <unknown>
  67:     0x7fc151b26850 - <unknown>
  68:                0x0 - <unknown>


failures:
    transport::session_test::test_tracing
async fn assert_in_tracing_table(session: &Session, tracing_uuid: Uuid) {
    let mut traces_query = Query::new("SELECT * FROM system_traces.sessions WHERE session_id = ?");
    traces_query.config.consistency = Some(Consistency::One);

    // Tracing info might not be immediately available
    // If rows are empty perform 8 retries with a 32ms wait in between

    for _ in 0..8 {
        let rows_num = session
            .query(traces_query.clone(), (tracing_uuid,))
            .await
            .unwrap()
            .rows_num()
            .unwrap();

        if rows_num > 0 {
            // Ok there was some row for this tracing_uuid
            return;
        }

        // Otherwise retry
        tokio::time::sleep(std::time::Duration::from_millis(32)).await;
    }

    // If all retries failed panic with an error
    panic!("No rows for tracing with this session id!");
}

Perhaps Cassandra is too slow and needs more time for those entries to appear? We could increase sleep / retry amount here.