Test flake in oximeter-db client::tests::test_ensure_schema_walks_through_multiple_steps_replicated #8170
Description
6534 2025-05-14T01:41:25.776Z FAIL [ 4.455s] oximeter-db client::tests::test_ensure_schema_walks_through_multiple_steps_replicated
6535 2025-05-14T01:41:25.776Z ──── STDOUT: oximeter-db client::tests::test_ensure_schema_walks_through_multiple_steps_replicated
6536 2025-05-14T01:41:25.776Z
6537 2025-05-14T01:41:25.777Z running 1 test
6538 2025-05-14T01:41:25.777Z test client::tests::test_ensure_schema_walks_through_multiple_steps_replicated ... FAILED
6539 2025-05-14T01:41:25.777Z
6540 2025-05-14T01:41:25.777Z failures:
6541 2025-05-14T01:41:25.777Z
6542 2025-05-14T01:41:25.777Z failures:
6543 2025-05-14T01:41:25.777Z client::tests::test_ensure_schema_walks_through_multiple_steps_replicated
6544 2025-05-14T01:41:25.777Z
6545 2025-05-14T01:41:25.777Z test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 245 filtered out; finished in 4.36s
6546 2025-05-14T01:41:25.777Z
6547 2025-05-14T01:41:25.850Z ──── STDERR: oximeter-db client::tests::test_ensure_schema_walks_through_multiple_steps_replicated
6548 2025-05-14T01:41:25.850Z log file: /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.0.log
6549 2025-05-14T01:41:25.850Z note: configured to log to "/var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.0.log"
6550 2025-05-14T01:41:25.850Z
6551 2025-05-14T01:41:25.850Z thread 'client::tests::test_ensure_schema_walks_through_multiple_steps_replicated' panicked at oximeter/db/src/client/mod.rs:4157:64:
6552 2025-05-14T01:41:25.850Z called `Result::unwrap()` on an `Err` value: Native(Exception { exceptions: [Exception { code: 999, name: "Coordination::Exception", message: "Coordination::Exception: All connection tries failed while connecting to ZooKeeper. nodes: [::1]:9181, [::1]:9183, [::1]:9182\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9181 (version 23.8.7.1), [::1]:9181\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9183 (version 23.8.7.1), [::1]:9183\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9182 (version 23.8.7.1), [::1]:9182\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9181 (version 23.8.7.1), [::1]:9181\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9183 (version 23.8.7.1), [::1]:9183\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9182 (version 23.8.7.1), [::1]:9182\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9181 (version 23.8.7.1), [::1]:9181\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9183 (version 23.8.7.1), [::1]:9183\nPoco::Exception. Code: 1000, e.code() = 146, Connection refused: [::1]:9182 (version 23.8.7.1), [::1]:9182\n", stack_trace: "0. StackTrace::tryCapture() @ 0x000000000f9acdb7 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n1. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000f97f7df in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n2. DB::Exception::Exception<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&>(int, FormatStringHelperImpl<std::type_identity<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&>::type>, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&) @ 0x000000000a7857f7 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n3. Coordination::Exception::Exception<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&>(Coordination::Error, FormatStringHelperImpl<std::type_identity<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&>::type>, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&) @ 0x0000000014e3842d in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n4. Coordination::ZooKeeper::connect(std::vector<Coordination::ZooKeeper::Node, std::allocator<Coordination::ZooKeeper::Node> > const&, Poco::Timespan) @ 0x000000001648290a in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n5. Coordination::ZooKeeper::ZooKeeper(std::vector<Coordination::ZooKeeper::Node, std::allocator<Coordination::ZooKeeper::Node> > const&, zkutil::ZooKeeperArgs const&, std::shared_ptr<DB::ZooKeeperLog>, std::optional<std::function<void (unsigned long, Coordination::ZooKeeper::Node const&)> >&&) @ 0x000000001648050b in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n6. zkutil::ZooKeeper::init(zkutil::ZooKeeperArgs) @ 0x0000000016449829 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n7. zkutil::ZooKeeper::ZooKeeper(Poco::Util::AbstractConfiguration const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::shared_ptr<DB::ZooKeeperLog>) @ 0x000000001644b0a3 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n8. DB::Context::getZooKeeper() const @ 0x0000000014755b49 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n9. DB::DDLWorker::getAndSetZooKeeper() @ 0x0000000014792b4a in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n10. DB::DDLWorker::enqueueQuery[abi:cxx11](DB::DDLLogEntry&) @ 0x00000000147a099c in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n11. DB::executeDDLQueryOnCluster(std::shared_ptr<DB::IAST> const&, std::shared_ptr<DB::Context const>, DB::DDLQueryOnClusterParams const&) @ 0x0000000014a4b2e7 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n12. DB::InterpreterCreateQuery::executeQueryOnCluster(DB::ASTCreateQuery&) @ 0x00000000148189e1 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n13. DB::InterpreterCreateQuery::execute() @ 0x0000000014820819 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n14. DB::executeQueryImpl(char const*, char const*, std::shared_ptr<DB::Context>, bool, DB::QueryProcessingStage::Enum, DB::ReadBuffer*) @ 0x0000000014a5f949 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n15. DB::executeQuery(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::shared_ptr<DB::Context>, bool, DB::QueryProcessingStage::Enum) @ 0x0000000014a5bd46 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n16. DB::TCPHandler::runImpl() @ 0x00000000153fbaaa in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n17. DB::TCPHandler::run() @ 0x000000001540bc5c in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n18. Poco::Net::TCPServerConnection::start() @ 0x00000000187a058c in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n19. Poco::Net::TCPServerDispatcher::run() @ 0x00000000187a0a61 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n20. Poco::PooledThread::run() @ 0x0000000018805972 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n21. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000018803425 in /work/oxidecomputer/omicron/out/clickhouse/clickhouse\n22. _thrp_setup @ 0x0000000000116767 in /lib/amd64/libc.so.1\n", nested: false }] })
6553 2025-05-14T01:41:25.850Z stack backtrace:
6554 2025-05-14T01:41:25.850Z 0: rust_begin_unwind
6555 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/std/src/panicking.rs:695:5
6556 2025-05-14T01:41:25.850Z 1: core::panicking::panic_fmt
6557 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/panicking.rs:75:14
6558 2025-05-14T01:41:25.850Z 2: core::result::unwrap_failed
6559 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/result.rs:1704:5
6560 2025-05-14T01:41:25.850Z 3: unwrap<(), oximeter_db::Error>
6561 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/result.rs:1109:23
6562 2025-05-14T01:41:25.850Z 4: {async_fn#0}
6563 2025-05-14T01:41:25.850Z at ./src/client/mod.rs:4157:9
6564 2025-05-14T01:41:25.850Z 5: {async_block#0}
6565 2025-05-14T01:41:25.850Z at ./src/client/mod.rs:4291:10
6566 2025-05-14T01:41:25.850Z 6: poll<&mut dyn core::future::future::Future<Output=()>>
6567 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/future/future.rs:124:9
6568 2025-05-14T01:41:25.850Z 7: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6569 2025-05-14T01:41:25.850Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/future/future.rs:124:9
6570 2025-05-14T01:41:25.850Z 8: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6571 2025-05-14T01:41:25.850Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:729:57
6572 2025-05-14T01:41:25.850Z 9: with_budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure#0}::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
6573 2025-05-14T01:41:25.850Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/coop.rs:107:5
6574 2025-05-14T01:41:25.850Z 10: budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure#0}::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
6575 2025-05-14T01:41:25.850Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/coop.rs:73:5
6576 2025-05-14T01:41:25.850Z 11: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6577 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:729:25
6578 2025-05-14T01:41:25.851Z 12: tokio::runtime::scheduler::current_thread::Context::enter
6579 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:428:19
6580 2025-05-14T01:41:25.851Z 13: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6581 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:728:36
6582 2025-05-14T01:41:25.851Z 14: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
6583 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:807:68
6584 2025-05-14T01:41:25.851Z 15: tokio::runtime::context::scoped::Scoped<T>::set
6585 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/context/scoped.rs:40:9
6586 2025-05-14T01:41:25.851Z 16: tokio::runtime::context::set_scheduler::{{closure}}
6587 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/context.rs:180:26
6588 2025-05-14T01:41:25.851Z 17: try_with<tokio::runtime::context::Context, tokio::runtime::context::set_scheduler::{closure_env#0}<(alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core, alloc::alloc::Global>, core::option::Option<()>), tokio::runtime::scheduler::current_thread::{impl#8}::enter::{closure_env#0}<tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>, core::option::Option<()>>>, (alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core, alloc::alloc::Global>, core::option::Option<()>)>
6589 2025-05-14T01:41:25.851Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/std/src/thread/local.rs:310:12
6590 2025-05-14T01:41:25.851Z 18: std::thread::local::LocalKey<T>::with
6591 2025-05-14T01:41:25.851Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/std/src/thread/local.rs:274:15
6592 2025-05-14T01:41:25.851Z 19: tokio::runtime::context::set_scheduler
6593 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/context.rs:180:9
6594 2025-05-14T01:41:25.851Z 20: tokio::runtime::scheduler::current_thread::CoreGuard::enter
6595 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:807:27
6596 2025-05-14T01:41:25.851Z 21: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
6597 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:716:19
6598 2025-05-14T01:41:25.851Z 22: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6599 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:196:28
6600 2025-05-14T01:41:25.851Z 23: tokio::runtime::context::runtime::enter_runtime
6601 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/context/runtime.rs:65:16
6602 2025-05-14T01:41:25.851Z 24: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6603 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/scheduler/current_thread/mod.rs:184:9
6604 2025-05-14T01:41:25.851Z 25: tokio::runtime::runtime::Runtime::block_on_inner
6605 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/runtime.rs:368:47
6606 2025-05-14T01:41:25.851Z 26: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6607 2025-05-14T01:41:25.851Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.1/src/runtime/runtime.rs:342:13
6608 2025-05-14T01:41:25.851Z 27: test_ensure_schema_walks_through_multiple_steps_replicated
6609 2025-05-14T01:41:25.851Z at ./src/client/mod.rs:4293:9
6610 2025-05-14T01:41:25.851Z 28: oximeter_db::client::tests::test_ensure_schema_walks_through_multiple_steps_replicated::{{closure}}
6611 2025-05-14T01:41:25.851Z at ./src/client/mod.rs:4280:74
6612 2025-05-14T01:41:25.851Z 29: core::ops::function::FnOnce::call_once
6613 2025-05-14T01:41:25.851Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/ops/function.rs:250:5
6614 2025-05-14T01:41:25.851Z 30: core::ops::function::FnOnce::call_once
6615 2025-05-14T01:41:25.851Z at /rustc/05f9846f893b09a1be1fc8560e33fc3c815cfecb/library/core/src/ops/function.rs:250:5
6616 2025-05-14T01:41:25.851Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
6617 2025-05-14T01:41:25.851Z WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 16484) and a temporary directory leaked, /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.4-clickhouse-fgDTKD)
6618 2025-05-14T01:41:25.852Z failed to clean up ClickHouse data dir:
6619 2025-05-14T01:41:25.852Z - /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.4-clickhouse-fgDTKD: File exists (os error 17)
6620 2025-05-14T01:41:25.852Z WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 16487) and a temporary directory leaked, /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.5-clickhouse-gCPVKS)
6621 2025-05-14T01:41:25.852Z failed to clean up ClickHouse data dir:
6622 2025-05-14T01:41:25.852Z - /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.5-clickhouse-gCPVKS: File exists (os error 17)
6623 2025-05-14T01:41:25.852Z WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 16476) and a temporary directory leaked, /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.1-clickhouse-iFcRob)
6624 2025-05-14T01:41:25.852Z failed to clean up ClickHouse data dir:
6625 2025-05-14T01:41:25.852Z - /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.1-clickhouse-iFcRob: File exists (os error 17)
6626 2025-05-14T01:41:25.852Z WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 16477) and a temporary directory leaked, /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.2-clickhouse-QHo06T)
6627 2025-05-14T01:41:25.852Z failed to clean up ClickHouse data dir:
6628 2025-05-14T01:41:25.852Z - /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.2-clickhouse-QHo06T: File exists (os error 17)
6629 2025-05-14T01:41:25.852Z WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 16482) and a temporary directory leaked, /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.3-clickhouse-y2UGSY)
6630 2025-05-14T01:41:25.852Z failed to clean up ClickHouse data dir:
6631 2025-05-14T01:41:25.852Z - /var/tmp/omicron_tmp/oximeter_db-11d8f51cb75f441f-test_ensure_schema_walks_through_multiple_steps_replicated.16475.3-clickhouse-y2UGSY: File exists (os error 17)
This looks like it failed because of:
All connection tries failed while connecting to ZooKeeper. nodes: [::1]:9181, [::1]:9183, [::1]:9182