test failed in CI: test_omdb_success_cases #8979
Description
I initially reported this as an other instance of #8926. @davepacheco correctly pointed out that I hit that issue and another one, specific to the sp_ereport_ingester output in the OMDB test. That comment is here. It seems like we need to redact more of the output, since it also depends on the exact order in which the sleds are registered with Nexus.
This test failed on a CI run on #8964.
https://github.com/oxidecomputer/omicron/pull/8964/checks?check_run_id=49521809859
Log showing the specific test failure:
Excerpt from the log showing the failure:
8493 2025-09-03T19:06:57.186Z FAIL [ 67.649s] omicron-omdb::test_all_output test_omdb_success_cases
8494 2025-09-03T19:06:57.186Z stdout ───
8495 2025-09-03T19:06:57.186Z
8496 2025-09-03T19:06:57.186Z running 1 test
8497 2025-09-03T19:06:57.186Z running commands with args: ["db", "disks", "list"]
8498 2025-09-03T19:06:57.186Z running commands with args: ["db", "dns", "show"]
8499 2025-09-03T19:06:57.186Z running commands with args: ["db", "dns", "diff", "external", "2"]
8500 2025-09-03T19:06:57.186Z running commands with args: ["db", "dns", "names", "external", "2"]
8501 2025-09-03T19:06:57.186Z running commands with args: ["db", "instances"]
8502 2025-09-03T19:06:57.186Z running commands with args: ["db", "sleds"]
8503 2025-09-03T19:06:57.186Z running commands with args: ["db", "sleds", "-F", "discretionary"]
8504 2025-09-03T19:06:57.186Z running commands with args: ["mgs", "inventory"]
8505 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "doc"]
8506 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "show", "--no-executing-info"]
8507 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "show", "saga_recovery", "--no-executing-info"]
8508 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "show", "blueprint_loader", "blueprint_executor", "--no-executing-info"]
8509 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "show", "dns_internal", "--no-executing-info"]
8510 2025-09-03T19:06:57.186Z running commands with args: ["nexus", "background-tasks", "show", "dns_external", "--no-executing-info"]
8511 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "background-tasks", "show", "all", "--no-executing-info"]
8512 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "chicken-switches", "show", "current"]
8513 2025-09-03T19:06:57.187Z running commands with args: ["-w", "nexus", "chicken-switches", "set", "--planner-enabled", "true"]
8514 2025-09-03T19:06:57.187Z running commands with args: ["-w", "nexus", "chicken-switches", "set", "--add-zones-with-mupdate-override", "false"]
8515 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "chicken-switches", "show", "current"]
8516 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "sagas", "list"]
8517 2025-09-03T19:06:57.187Z running commands with args: ["--destructive", "nexus", "sagas", "demo-create"]
8518 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "sagas", "list"]
8519 2025-09-03T19:06:57.187Z running commands with args: ["--destructive", "nexus", "background-tasks", "activate", "inventory_collection"]
8520 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "blueprints", "list"]
8521 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "blueprints", "show", "7e125e6c-31a0-4a50-b099-a9f970b129c2"]
8522 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "blueprints", "show", "current-target"]
8523 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "blueprints", "diff", "7e125e6c-31a0-4a50-b099-a9f970b129c2", "current-target"]
8524 2025-09-03T19:06:57.187Z running commands with args: ["nexus", "blueprints", "diff", "7e125e6c-31a0-4a50-b099-a9f970b129c2"]
8525 2025-09-03T19:06:57.187Z test test_omdb_success_cases has been running for over 60 seconds
8526 2025-09-03T19:06:57.188Z running commands with args: ["reconfigurator", "export", "/var/tmp/omicron_tmp/.tmpVemesl/reconfigurator-export.out"]
8527 2025-09-03T19:06:57.188Z @@ -1222,19 +1222,31 @@
8528 2025-09-03T19:06:57.188Z
8529 2025-09-03T19:06:57.188Z task: "sp_ereport_ingester"
8530 2025-09-03T19:06:57.188Z configured period: every <REDACTED_DURATION>s
8531 2025-09-03T19:06:57.188Z last completed activation: <REDACTED ITERATIONS>, triggered by <TRIGGERED_BY_REDACTED>
8532 2025-09-03T19:06:57.188Z started at <REDACTED_TIMESTAMP> (<REDACTED DURATION>s ago) and ran for <REDACTED DURATION>ms
8533 2025-09-03T19:06:57.188Z -/!\ errors: 1
8534 2025-09-03T19:06:57.188Z - - failed to resolve MGS addresses: proto error: no records found for Query { name: Name("_mgs._tcp.control-plane.oxide.internal."), query_type: SRV, query_class: IN }
8535 2025-09-03T19:06:57.188Z - total ereports received: 0
8536 2025-09-03T19:06:57.188Z - new ereports ingested: 0
8537 2025-09-03T19:06:57.188Z - total HTTP requests sent: 0
8538 2025-09-03T19:06:57.188Z - total collection errors: 0
8539 2025-09-03T19:06:57.188Z - reporters with ereports: 0
8540 2025-09-03T19:06:57.188Z + total ereports received: 11
8541 2025-09-03T19:06:57.188Z + new ereports ingested: 11
8542 2025-09-03T19:06:57.188Z + total HTTP requests sent: 8
8543 2025-09-03T19:06:57.188Z + total collection errors: 8
8544 2025-09-03T19:06:57.188Z + reporters with ereports: 4
8545 2025-09-03T19:06:57.189Z reporters with collection errors: 0
8546 2025-09-03T19:06:57.189Z
8547 2025-09-03T19:06:57.189Z + service processors:
8548 2025-09-03T19:06:57.189Z + - sled 00: 6 ereports
8549 2025-09-03T19:06:57.189Z + new ereports ingested: 6
8550 2025-09-03T19:06:57.189Z + HTTP requests sent: 2
8551 2025-09-03T19:06:57.189Z + - sled 01: 2 ereports
8552 2025-09-03T19:06:57.189Z + new ereports ingested: 2
8553 2025-09-03T19:06:57.189Z + HTTP requests sent: 2
8554 2025-09-03T19:06:57.189Z + - switch 00: 2 ereports
8555 2025-09-03T19:06:57.189Z + new ereports ingested: 2
8556 2025-09-03T19:06:57.189Z + HTTP requests sent: 2
8557 2025-09-03T19:06:57.189Z + - switch 01: 1 ereports
8558 2025-09-03T19:06:57.189Z + new ereports ingested: 1
8559 2025-09-03T19:06:57.189Z + HTTP requests sent: 2
8560 2025-09-03T19:06:57.189Z +
8561 2025-09-03T19:06:57.189Z task: "support_bundle_collector"
8562 2025-09-03T19:06:57.189Z configured period: every <REDACTED_DURATION>days <REDACTED_DURATION>h <REDACTED_DURATION>m <REDACTED_DURATION>s
8563 2025-09-03T19:06:57.189Z last completed activation: <REDACTED ITERATIONS>, triggered by <TRIGGERED_BY_REDACTED>
8564 2025-09-03T19:06:57.189Z started at <REDACTED_TIMESTAMP> (<REDACTED DURATION>s ago) and ran for <REDACTED DURATION>ms
8565 2025-09-03T19:06:57.189Z Support Bundle Cleanup Report:
8566 2025-09-03T19:06:57.189Z
8567 2025-09-03T19:06:57.189Z test test_omdb_success_cases ... FAILED
8568 2025-09-03T19:06:57.189Z
8569 2025-09-03T19:06:57.189Z failures:
8570 2025-09-03T19:06:57.189Z
8571 2025-09-03T19:06:57.189Z failures:
8572 2025-09-03T19:06:57.189Z test_omdb_success_cases
8573 2025-09-03T19:06:57.189Z
8574 2025-09-03T19:06:57.189Z test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 2 filtered out; finished in 66.95s
8575 2025-09-03T19:06:57.189Z
8576 2025-09-03T19:06:57.189Z stderr ───
8577 2025-09-03T19:06:57.189Z log file: /var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.0.log
8578 2025-09-03T19:06:57.189Z note: configured to log to "/var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.0.log"
8579 2025-09-03T19:06:57.190Z DB URL: postgresql://root@[::1]:58839/omicron?sslmode=disable
8580 2025-09-03T19:06:57.190Z DB address: [::1]:58839
8581 2025-09-03T19:06:57.190Z log file: /var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.2.log
8582 2025-09-03T19:06:57.190Z note: configured to log to "/var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.2.log"
8583 2025-09-03T19:06:57.190Z log file: /var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.3.log
8584 2025-09-03T19:06:57.190Z note: configured to log to "/var/tmp/omicron_tmp/test_all_output-3d6bbe813742e331-test_omdb_success_cases.874.3.log"
8585 2025-09-03T19:06:57.190Z
8586 2025-09-03T19:06:57.190Z thread 'test_omdb_success_cases' panicked at dev-tools/omdb/tests/test_all_output.rs:324:5:
8587 2025-09-03T19:06:57.190Z assertion failed: string doesn't match the contents of file: "tests/successes.out" see diffset above
8588 2025-09-03T19:06:57.190Z set EXPECTORATE=overwrite if these changes are intentional
8589 2025-09-03T19:06:57.190Z stack backtrace:
8590 2025-09-03T19:06:57.190Z 0: __rustc::rust_begin_unwind
8591 2025-09-03T19:06:57.190Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:697:5
8592 2025-09-03T19:06:57.190Z 1: core::panicking::panic_fmt
8593 2025-09-03T19:06:57.249Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panicking.rs:75:14
8594 2025-09-03T19:06:57.249Z 2: expectorate::assert_contents
8595 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/expectorate-1.2.0/src/lib.rs:67:9
8596 2025-09-03T19:06:57.250Z 3: {async_fn#0}
8597 2025-09-03T19:06:57.250Z at ./tests/test_all_output.rs:324:5
8598 2025-09-03T19:06:57.250Z 4: {async_block#0}
8599 2025-09-03T19:06:57.250Z at ./tests/test_all_output.rs:132:1
8600 2025-09-03T19:06:57.250Z 5: poll<&mut dyn core::future::future::Future<Output=()>>
8601 2025-09-03T19:06:57.250Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/future/future.rs:124:9
8602 2025-09-03T19:06:57.250Z 6: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
8603 2025-09-03T19:06:57.250Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/future/future.rs:124:9
8604 2025-09-03T19:06:57.250Z 7: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
8605 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:742:70
8606 2025-09-03T19:06:57.250Z 8: 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=()>>>>>
8607 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:167:5
8608 2025-09-03T19:06:57.250Z 9: 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=()>>>>>
8609 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:133:5
8610 2025-09-03T19:06:57.250Z 10: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
8611 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:742:25
8612 2025-09-03T19:06:57.250Z 11: tokio::runtime::scheduler::current_thread::Context::enter
8613 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:432:19
8614 2025-09-03T19:06:57.250Z 12: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
8615 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:741:44
8616 2025-09-03T19:06:57.250Z 13: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
8617 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:68
8618 2025-09-03T19:06:57.250Z 14: tokio::runtime::context::scoped::Scoped<T>::set
8619 2025-09-03T19:06:57.250Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/scoped.rs:40:9
8620 2025-09-03T19:06:57.251Z 15: tokio::runtime::context::set_scheduler::{{closure}}
8621 2025-09-03T19:06:57.251Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:38
8622 2025-09-03T19:06:57.251Z 16: 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<()>)>
8623 2025-09-03T19:06:57.252Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/local.rs:315:12
8624 2025-09-03T19:06:57.252Z 17: std::thread::local::LocalKey<T>::with
8625 2025-09-03T19:06:57.252Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/local.rs:279:20
8626 2025-09-03T19:06:57.252Z 18: tokio::runtime::context::set_scheduler
8627 2025-09-03T19:06:57.252Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:17
8628 2025-09-03T19:06:57.252Z 19: tokio::runtime::scheduler::current_thread::CoreGuard::enter
8629 2025-09-03T19:06:57.252Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:27
8630 2025-09-03T19:06:57.252Z 20: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
8631 2025-09-03T19:06:57.252Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:729:24
8632 2025-09-03T19:06:57.252Z 21: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
8633 2025-09-03T19:06:57.252Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:200:33
8634 2025-09-03T19:06:57.252Z 22: tokio::runtime::context::runtime::enter_runtime
8635 2025-09-03T19:06:57.252Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/runtime.rs:65:16
8636 2025-09-03T19:06:57.253Z 23: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
8637 2025-09-03T19:06:57.253Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:188:9
8638 2025-09-03T19:06:57.253Z 24: tokio::runtime::runtime::Runtime::block_on_inner
8639 2025-09-03T19:06:57.253Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:356:52
8640 2025-09-03T19:06:57.253Z 25: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
8641 2025-09-03T19:06:57.253Z at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:330:18
8642 2025-09-03T19:06:57.253Z 26: test_omdb_success_cases
8643 2025-09-03T19:06:57.253Z at ./tests/test_all_output.rs:132:1
8644 2025-09-03T19:06:57.253Z 27: test_all_output::test_omdb_success_cases::{{closure}}
8645 2025-09-03T19:06:57.253Z at ./tests/test_all_output.rs:133:70
8646 2025-09-03T19:06:57.253Z 28: core::ops::function::FnOnce::call_once
8647 2025-09-03T19:06:57.253Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/ops/function.rs:250:5
8648 2025-09-03T19:06:57.253Z 29: core::ops::function::FnOnce::call_once
8649 2025-09-03T19:06:57.253Z at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/ops/function.rs:250:5
8650 2025-09-03T19:06:57.253Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.