Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

test_tracing is probably flaky with Cassandra #957

Closed
wprzytula opened this issue Mar 14, 2024 · 1 comment · Fixed by #966
Closed

test_tracing is probably flaky with Cassandra #957

wprzytula opened this issue Mar 14, 2024 · 1 comment · Fixed by #966

Comments

@wprzytula
Copy link
Collaborator

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
@Lorak-mmk
Copy link
Collaborator 

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.

@Lorak-mmk Lorak-mmk mentioned this issue Mar 19, 2024
Merged
8 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

session_test: Increase tracing info timeout Lorak-mmk/scylla-rust-driver
2 participants
@Lorak-mmk @wprzytula