From 726c14632e500da6e96955fac94edf5a982730de Mon Sep 17 00:00:00 2001 From: Cameron Brooks Date: Tue, 14 Jul 2026 09:32:54 -0400 Subject: [PATCH 1/2] feat(health): real per-device last_seen and I/O counters Track cumulative per-address statistics in the CRUMBS session, where every attempt is visible and the existing mutex already serializes: ok/failed operation counts, retried_attempts (every attempt beyond an operation's first), and the timestamp of the last successful operation. Argument/state validation failures never touch the wire and are not counted. device_health() now surfaces them per device: last_seen is the real last-contact time (probes included) instead of the provider-start constant stamped on every device, and io_ok / io_failed / io_retried_attempts land in DeviceHealth.metrics. Devices with no successful contact yet - including missing-expected devices - leave last_seen unset rather than fabricated. The retry counter is the observability half of the DCMT saga: retries that eventually succeed no longer erase the underlying failures from health output (a ~30% per-transaction failure rate hid behind the retry policy for weeks, feastorg/Slice_DCMT#3). Closes #87 --- CHANGELOG.md | 17 +++++ src/core/bread_provider_runtime.cpp | 22 +++++-- src/crumbs/session.cpp | 40 ++++++++++-- src/crumbs/session.hpp | 35 +++++++++++ tests/unit/crumbs_session_test.cpp | 96 +++++++++++++++++++++++++++++ tests/unit/shell_test.cpp | 35 ++++++++++- 6 files changed, 232 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 860cb2e..7e03f59 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,23 @@ commit messages only. ## [Unreleased] +### Added + +- Real per-device health (#87): `DeviceHealth.last_seen` is now the wall-clock + time of the last successful CRUMBS operation against the device's address + (probes included), and three new per-device metrics expose the session's + cumulative I/O counters — `io_ok`, `io_failed`, and `io_retried_attempts`. + The retry counter records every attempt beyond an operation's first, so + intermittent bus trouble that the retry policy masks stays visible in health + output instead of silently disappearing (the mechanism that hid a ~30% + per-transaction failure rate for weeks, see feastorg/Slice_DCMT#3). + +### Changed + +- `last_seen` is no longer fabricated: devices with no successful contact yet + (including missing-expected devices) leave it unset, replacing the previous + provider-start-time constant stamped on every device. + ## [0.3.2] - 2026-07-14 ### Changed diff --git a/src/core/bread_provider_runtime.cpp b/src/core/bread_provider_runtime.cpp index f635c60..f253df3 100644 --- a/src/core/bread_provider_runtime.cpp +++ b/src/core/bread_provider_runtime.cpp @@ -8,6 +8,7 @@ #include "anolis/provider_sdk/result.hpp" #include "config/provider_config.hpp" #include "core/runtime_state.hpp" +#include "crumbs/session.hpp" #include "devices/common/device_adapter.hpp" #include "devices/common/inventory.hpp" #include "protocol.pb.h" @@ -83,26 +84,37 @@ sdk::ReadinessReport BreadProviderRuntime::readiness() const { } sdk::DeviceHealthExtra BreadProviderRuntime::device_health(const std::string& device_id) const { - // Restore bread's pre-migration per-device health (SDK#9) from one snapshot. - // last_seen is the startup constant to_timestamp(started_at) — bread has no real - // per-device heartbeat yet (tracked in anolis-provider-bread#87). + // Per-device health (#87): last_seen is the wall-clock time of the last + // successful CRUMBS operation against the device's address, and the io_* + // metrics expose the session's cumulative counters — including retries + // that eventually succeeded, so intermittent bus trouble is visible here + // instead of hiding behind the retry policy. const runtime::RuntimeState state = runtime::snapshot(); sdk::DeviceHealthExtra extra; if (const inventory::InventoryDevice* device = inventory::find_device(state.devices, device_id)) { extra.metrics["address"] = device->descriptor.address(); extra.metrics["type_id"] = device->descriptor.type_id(); extra.metrics["inventory"] = state.inventory_mode; - extra.last_seen = to_timestamp(state.started_at); + if (crumbs::Session* session = runtime::session()) { + const crumbs::AddressStats stats = session->stats_for(static_cast(device->address)); + extra.metrics["io_ok"] = std::to_string(stats.ok); + extra.metrics["io_failed"] = std::to_string(stats.failed); + extra.metrics["io_retried_attempts"] = std::to_string(stats.retried_attempts); + if (stats.has_success) { + extra.last_seen = to_timestamp(stats.last_success); + } + } + // No successful contact yet -> last_seen stays unset (never fabricated). return extra; } // Missing-expected devices surface on get_health (readiness() maps them to // failed_devices); they are NOT in the live inventory, so branch on the // missing-expected set rather than a find_device lookup (which returns null). + // There has been no contact with a missing device, so last_seen stays unset. for (const auto& missing_id : state.missing_expected_ids) { if (missing_id == device_id) { extra.metrics["inventory"] = state.inventory_mode; extra.metrics["missing"] = "true"; - extra.last_seen = to_timestamp(state.started_at); break; } } diff --git a/src/crumbs/session.cpp b/src/crumbs/session.cpp index 8c85eaf..6fe52c2 100644 --- a/src/crumbs/session.cpp +++ b/src/crumbs/session.cpp @@ -136,7 +136,10 @@ SessionStatus Session::send(uint8_t address, const RawFrame &frame) { return SessionStatus::failure(SessionErrorCode::NotOpen, "CRUMBS session is not open"); } - return execute_with_retry(options_, "send", address, [&]() { return transport_.send(address, frame); }); + SessionStatus status = + execute_with_retry(options_, "send", address, [&]() { return transport_.send(address, frame); }); + record_outcome(address, status); + return status; } SessionStatus Session::read(uint8_t address, RawFrame &frame) { @@ -152,7 +155,10 @@ SessionStatus Session::read(uint8_t address, RawFrame &frame) { const uint32_t timeout_us = options_.timeout_ms > (UINT32_MAX / 1000u) ? UINT32_MAX : options_.timeout_ms * 1000u; - return execute_with_retry(options_, "read", address, [&]() { return transport_.read(address, frame, timeout_us); }); + SessionStatus status = execute_with_retry(options_, "read", address, + [&]() { return transport_.read(address, frame, timeout_us); }); + record_outcome(address, status); + return status; } SessionStatus Session::query_read(uint8_t address, uint8_t reply_opcode, RawFrame &out) { @@ -175,15 +181,37 @@ SessionStatus Session::query_read(uint8_t address, uint8_t reply_opcode, RawFram // Hold the session lock across send → delay → read so the SET_REPLY query // sequence cannot interleave with another caller on the shared bus. - return execute_with_retry(options_, "query_read", address, [&]() { - SessionStatus status = transport_.send(address, query); - if (!status) { - return status; + SessionStatus status = execute_with_retry(options_, "query_read", address, [&]() { + SessionStatus attempt = transport_.send(address, query); + if (!attempt) { + return attempt; } transport_.delay_us(options_.query_delay_us); return transport_.read(address, out, timeout_us); }); + record_outcome(address, status); + return status; +} + +AddressStats Session::stats_for(uint8_t address) const { + std::lock_guard lock(mutex_); + const auto it = stats_.find(address); + return it == stats_.end() ? AddressStats{} : it->second; +} + +void Session::record_outcome(uint8_t address, const SessionStatus &status) { + AddressStats &stats = stats_[address]; + if (status.attempts > 1) { + stats.retried_attempts += static_cast(status.attempts - 1); + } + if (status.ok()) { + ++stats.ok; + stats.has_success = true; + stats.last_success = std::chrono::system_clock::now(); + } else { + ++stats.failed; + } } SessionStatus Session::validate_open_options() const { diff --git a/src/crumbs/session.hpp b/src/crumbs/session.hpp index bcba17f..5c72fa9 100644 --- a/src/crumbs/session.hpp +++ b/src/crumbs/session.hpp @@ -6,8 +6,10 @@ * provider. */ +#include #include #include +#include #include #include #include @@ -88,6 +90,25 @@ struct ScanResult { uint8_t type_id = 0; }; +/** + * @brief Cumulative per-address I/O statistics kept by `Session`. + * + * Counters are attempt-aware: `retried_attempts` counts every attempt beyond + * an operation's first, so failures that a later retry masks stay visible in + * health output instead of disappearing into a success. Only operations that + * reached the transport are counted; argument/state validation failures are + * not I/O. + */ +struct AddressStats { + uint64_t ok = 0; + uint64_t failed = 0; + uint64_t retried_attempts = 0; + bool has_success = false; + /** @brief Wall-clock time of the last successful operation; meaningful only + * when `has_success` is true. */ + std::chrono::system_clock::time_point last_success{}; +}; + /** * @brief Session-level transport options derived from provider config. */ @@ -184,15 +205,29 @@ class Session { */ SessionStatus query_read(uint8_t address, uint8_t reply_opcode, RawFrame &out); + /** + * @brief Return a copy of the cumulative I/O statistics for one address. + * + * Feeds per-device health (`DeviceHealth.last_seen` and the io_* metrics, + * anolis-provider-bread#87). Returns zeroed stats for an address this + * session has never performed I/O against. + */ + AddressStats stats_for(uint8_t address) const; + private: SessionStatus validate_open_options() const; SessionStatus validate_scan_options(const ScanOptions &options) const; SessionStatus validate_address(uint8_t address) const; SessionStatus validate_frame(const RawFrame &frame) const; + /** @brief Record one completed transport operation. Caller must hold + * `mutex_`. */ + void record_outcome(uint8_t address, const SessionStatus &status); + Transport &transport_; SessionOptions options_; mutable std::mutex mutex_; + std::map stats_; }; /** @brief Build session transport options from resolved provider config. */ diff --git a/tests/unit/crumbs_session_test.cpp b/tests/unit/crumbs_session_test.cpp index dfae86e..310519f 100644 --- a/tests/unit/crumbs_session_test.cpp +++ b/tests/unit/crumbs_session_test.cpp @@ -209,5 +209,101 @@ TEST(CrumbsSessionTest, RejectsOversizedPayloadBeforeTransportCall) { EXPECT_EQ(transport.send_calls, 0); } +// --------------------------------------------------------------------------- +// Per-address I/O statistics (#87) — the counters behind DeviceHealth. +// --------------------------------------------------------------------------- + +TEST(CrumbsSessionStats, SuccessSetsLastSeenAndCountsOk) { + FakeTransport transport; + Session session(transport, SessionOptions{"/dev/i2c-1", 10000u, 100u, 2}); + ASSERT_TRUE(session.open()); + + // Never-contacted address starts zeroed with no last_success. + AddressStats before = session.stats_for(0x08u); + EXPECT_EQ(before.ok, 0U); + EXPECT_FALSE(before.has_success); + + transport.read_actions.push_back({SessionStatus::success(), RawFrame{0x01, 0x80, {0x11}}}); + RawFrame reply; + ASSERT_TRUE(session.query_read(0x08u, 0x80u, reply)); + + const AddressStats after = session.stats_for(0x08u); + EXPECT_EQ(after.ok, 1U); + EXPECT_EQ(after.failed, 0U); + EXPECT_EQ(after.retried_attempts, 0U); + EXPECT_TRUE(after.has_success); + EXPECT_GT(after.last_success.time_since_epoch().count(), 0); +} + +TEST(CrumbsSessionStats, MaskedRetryStaysVisibleInRetriedAttempts) { + FakeTransport transport; + Session session(transport, SessionOptions{"/dev/i2c-1", 10000u, 100u, 2}); + ASSERT_TRUE(session.open()); + + // Attempt 1 fails on the wire, attempt 2 succeeds — the operation reports + // success, but the flakiness must not vanish from the stats. + transport.send_actions.push_back(SessionStatus::failure(SessionErrorCode::WriteFailed, "temporary NACK")); + transport.send_actions.push_back(SessionStatus::success()); + transport.read_actions.push_back({SessionStatus::success(), RawFrame{0x01, 0x80, {0x11}}}); + + RawFrame reply; + ASSERT_TRUE(session.query_read(0x08u, 0x80u, reply)); + + const AddressStats stats = session.stats_for(0x08u); + EXPECT_EQ(stats.ok, 1U); + EXPECT_EQ(stats.failed, 0U); + EXPECT_EQ(stats.retried_attempts, 1U); + EXPECT_TRUE(stats.has_success); +} + +TEST(CrumbsSessionStats, ExhaustedRetriesCountOneFailure) { + FakeTransport transport; + Session session(transport, SessionOptions{"/dev/i2c-1", 10000u, 100u, 1}); + ASSERT_TRUE(session.open()); + + transport.send_actions.push_back(SessionStatus::failure(SessionErrorCode::WriteFailed, "NACK")); + transport.send_actions.push_back(SessionStatus::failure(SessionErrorCode::WriteFailed, "NACK")); + + RawFrame frame{0x01, 0x02, {0xAA}}; + EXPECT_FALSE(session.send(0x08u, frame)); + + const AddressStats stats = session.stats_for(0x08u); + EXPECT_EQ(stats.ok, 0U); + EXPECT_EQ(stats.failed, 1U); + EXPECT_EQ(stats.retried_attempts, 1U); + EXPECT_FALSE(stats.has_success); +} + +TEST(CrumbsSessionStats, ValidationFailuresAreNotIo) { + FakeTransport transport; + Session session(transport, SessionOptions{"/dev/i2c-1", 10000u, 100u, 1}); + ASSERT_TRUE(session.open()); + + RawFrame oversized; + oversized.payload.resize(kMaxPayloadBytes + 1u, 0xAAu); + EXPECT_FALSE(session.send(0x08u, oversized)); + + const AddressStats stats = session.stats_for(0x08u); + EXPECT_EQ(stats.ok, 0U); + EXPECT_EQ(stats.failed, 0U); +} + +TEST(CrumbsSessionStats, StatsAreTrackedPerAddress) { + FakeTransport transport; + Session session(transport, SessionOptions{"/dev/i2c-1", 10000u, 100u, 1}); + ASSERT_TRUE(session.open()); + + RawFrame frame{0x01, 0x02, {0xAA}}; + ASSERT_TRUE(session.send(0x08u, frame)); + transport.send_actions.push_back(SessionStatus::failure(SessionErrorCode::WriteFailed, "NACK")); + transport.send_actions.push_back(SessionStatus::failure(SessionErrorCode::WriteFailed, "NACK")); + EXPECT_FALSE(session.send(0x09u, frame)); + + EXPECT_EQ(session.stats_for(0x08u).ok, 1U); + EXPECT_EQ(session.stats_for(0x08u).failed, 0U); + EXPECT_EQ(session.stats_for(0x09u).ok, 0U); + EXPECT_EQ(session.stats_for(0x09u).failed, 1U); +} + } // namespace } // namespace anolis_provider_bread::crumbs \ No newline at end of file diff --git a/tests/unit/shell_test.cpp b/tests/unit/shell_test.cpp index 2021f53..be3eec7 100644 --- a/tests/unit/shell_test.cpp +++ b/tests/unit/shell_test.cpp @@ -332,7 +332,12 @@ TEST(ShellTest, SupportsHelloInventoryAndHealth) { EXPECT_EQ(rlht_health->metrics().at("type_id"), "bread.rlht"); EXPECT_EQ(rlht_health->metrics().at("inventory"), "config_seeded"); EXPECT_FALSE(rlht_health->metrics().at("address").empty()); - EXPECT_TRUE(rlht_health->has_last_seen()); + // #87: last_seen is a real contact timestamp now. Config-seeded mock + // inventory has had NO device I/O yet, so it must be unset (never the + // old started_at fabrication), and the io counters must read zero. + EXPECT_FALSE(rlht_health->has_last_seen()); + EXPECT_EQ(rlht_health->metrics().at("io_ok"), "0"); + EXPECT_EQ(rlht_health->metrics().at("io_failed"), "0"); } { @@ -370,7 +375,8 @@ TEST(ShellTest, SupportsHelloInventoryAndHealth) { ASSERT_NE(gh_rlht, nullptr); EXPECT_EQ(gh_rlht->metrics().at("type_id"), "bread.rlht"); EXPECT_EQ(gh_rlht->metrics().at("inventory"), "config_seeded"); - EXPECT_TRUE(gh_rlht->has_last_seen()); + // Still no device I/O at this point — last_seen stays unset (#87). + EXPECT_FALSE(gh_rlht->has_last_seen()); } { @@ -397,6 +403,31 @@ TEST(ShellTest, SupportsHelloInventoryAndHealth) { EXPECT_DOUBLE_EQ(response.read_signals().values(0).value().double_value(), 25.0); } + { + SCOPED_TRACE("get_health_after_read"); + // #87: the successful read above is real device contact — last_seen must + // now be set and the io_ok counter must have moved, for rlht0 only. + anolis::deviceprovider::v1::Request get_health; + get_health.set_request_id(7); + get_health.mutable_get_health(); + const auto response = session.send(get_health); + ASSERT_EQ(response.status().code(), anolis::deviceprovider::v1::Status::CODE_OK); + const anolis::deviceprovider::v1::DeviceHealth *rlht = nullptr; + const anolis::deviceprovider::v1::DeviceHealth *dcmt = nullptr; + for (const auto &dh : response.get_health().devices()) { + if (dh.device_id() == "rlht0") rlht = &dh; + if (dh.device_id() == "dcmt0") dcmt = &dh; + } + ASSERT_NE(rlht, nullptr); + ASSERT_NE(dcmt, nullptr); + EXPECT_TRUE(rlht->has_last_seen()); + EXPECT_NE(rlht->metrics().at("io_ok"), "0"); + EXPECT_EQ(rlht->metrics().at("io_failed"), "0"); + // dcmt0 has still had no contact. + EXPECT_FALSE(dcmt->has_last_seen()); + EXPECT_EQ(dcmt->metrics().at("io_ok"), "0"); + } + { SCOPED_TRACE("call_mock_backend"); // Well-formed call: passes argument validation, then the mock session From 05a6d8cbf28ac9a450a6b210154aafe636f23a8d Mon Sep 17 00:00:00 2001 From: Cameron Brooks Date: Tue, 14 Jul 2026 09:39:59 -0400 Subject: [PATCH 2/2] style: wrap session read retry call per clang-format --- src/crumbs/session.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/crumbs/session.cpp b/src/crumbs/session.cpp index 6fe52c2..fc04aa1 100644 --- a/src/crumbs/session.cpp +++ b/src/crumbs/session.cpp @@ -155,8 +155,8 @@ SessionStatus Session::read(uint8_t address, RawFrame &frame) { const uint32_t timeout_us = options_.timeout_ms > (UINT32_MAX / 1000u) ? UINT32_MAX : options_.timeout_ms * 1000u; - SessionStatus status = execute_with_retry(options_, "read", address, - [&]() { return transport_.read(address, frame, timeout_us); }); + SessionStatus status = + execute_with_retry(options_, "read", address, [&]() { return transport_.read(address, frame, timeout_us); }); record_outcome(address, status); return status; }