diff --git a/apps/arstack_studio/qml/PtpExpertPanel.qml b/apps/arstack_studio/qml/PtpExpertPanel.qml index 1e1fe8bd2..c9e6d437f 100644 --- a/apps/arstack_studio/qml/PtpExpertPanel.qml +++ b/apps/arstack_studio/qml/PtpExpertPanel.qml @@ -365,7 +365,7 @@ SurfacePanel { } Label { Layout.fillWidth: true - text: "Board-internal reasons, not an independently certified PTP/IED lock." + text: "Last 16 board LOCK transitions are retained in RAM; no per-frame logging. Internal evidence only—not an independently verified PTP/IED lock." color: panel.theme.muted font.family: panel.uiFont font.pixelSize: 9 diff --git a/embedded/esp32p4_smv_injector/main/app_main.cpp b/embedded/esp32p4_smv_injector/main/app_main.cpp index 70d410a58..65311773f 100644 --- a/embedded/esp32p4_smv_injector/main/app_main.cpp +++ b/embedded/esp32p4_smv_injector/main/app_main.cpp @@ -1143,8 +1143,25 @@ void publisher_task(void* argument) { const auto phase_ns = g_tx_egress_evidence.summary().last_phase_ns; g_local_sync_evidence.observe(egress, result, phase_ns); portEXIT_CRITICAL(&g_tx_egress_mux); - if (result != ar::iec61850::time_sync::SvTxEvidenceResult::measured) - revoke_sv_auto_claims(SvSyncLossReason::mac_egress); + // Keep the EXACT real descriptor rejection class. This runs + // once every two seconds, never per-frame or in an ISR. + using Evidence = ar::iec61850::time_sync::SvTxEvidenceResult; + if (result != Evidence::measured) { + const auto cause = result == Evidence::transmit_failed + ? SvSyncLossReason::canonical_tx + : result == Evidence::missing_hw_timestamp + ? SvSyncLossReason::mac_missing_timestamp + : result == Evidence::not_a_qualified_epoch + ? SvSyncLossReason::mac_bad_epoch + : result == Evidence::publisher_discontinuity + ? SvSyncLossReason::mac_publisher_discontinuity + : result == Evidence::ptp_clock_discontinuity + ? SvSyncLossReason::mac_ptp_clock_step + : result == Evidence::baseline_established + ? SvSyncLossReason::mac_baseline_reset + : SvSyncLossReason::mac_egress; + revoke_sv_auto_claims(cause); + } } #else const esp_err_t canonical_result = @@ -1445,6 +1462,15 @@ void sv_ptp_phase_observer_task(void* argument) { // An external GM may yield LOCAL or GLOBAL only after both // PTP discipline and this actual SV phase/MAC gate pass. // SOURCE never promotes to GLOBAL through this path. + // Publish measured phase/MAC context BEFORE a lock edge, + // so each ring event snapshots the causally relevant + // observation rather than last second's cached values. + smp_synch_diag_observe( + decision.phase_error_us, decision.observation_uncertainty_us, + mac_pairs, local_acquisition.clean_epochs(), + observation.last_sv_epoch_generation, + decision.accepted && decision.epoch_second_continuous, + decision.software_tracking); const auto stamp_ms = static_cast( esp_timer_get_time() / 1000LL); smp_synch_set_source_local_qualified( @@ -1453,12 +1479,6 @@ void sv_ptp_phase_observer_task(void* argument) { smp_synch_set_receiver_timeline_qualified( stable_local && lease.role == PtpAuthorityRole::receiver, SvSyncLossReason::phase_or_mac, stamp_ms); - smp_synch_diag_observe( - decision.phase_error_us, decision.observation_uncertainty_us, - mac_pairs, local_acquisition.clean_epochs(), - observation.last_sv_epoch_generation, - decision.accepted && decision.epoch_second_continuous, - decision.software_tracking); } else { local_acquisition.reset(); revoke_sv_auto_claims(SvSyncLossReason::publisher_stop); @@ -1539,20 +1559,28 @@ void telemetry_task(void*) { // Auto-surface each change in the flight recorder once per second, // even if the operator forgets to request Inspect SV lock. The full // event ring remains available on demand through Studio. - const auto flight = ar::esp32p4::smv::smp_synch_diag_snapshot(); - if (flight.events != last_flight_events_reported) { - const auto changes = flight.events - last_flight_events_reported; - last_flight_events_reported = flight.events; - if (flight.recent_count > 0U) { + // Do one atomic counter read per second during steady-state LOCK. + // Constructing a 16-event snapshot is only needed after a transition. + if (ar::esp32p4::smv::smp_synch_diag_event_count() != + last_flight_events_reported) { + const auto flight = ar::esp32p4::smv::smp_synch_diag_snapshot(); + if (flight.events != last_flight_events_reported && + flight.recent_count > 0U && + flight.recent[flight.recent_count - 1U].sequence == flight.events) { + const auto changes = flight.events - last_flight_events_reported; + last_flight_events_reported = flight.events; const auto& latest = flight.recent[flight.recent_count - 1U]; ESP_LOGW(kTag, "SVSYNC FLIGHT transitions=%lu latest_seq=%lu state=%s reason=%s " - "uptime_ms=%lu phase_us=%ld uncertainty_us=%lu MACpairs=%lu clean=%lu", + "uptime_ms=%lu event_phase_us=%ld event_MACpairs=%lu " + "phase_us=%ld uncertainty_us=%lu MACpairs=%lu clean=%lu", static_cast(changes), static_cast(latest.sequence), latest.acquired ? "ACQUIRED" : "REVOKED", ar::esp32p4::smv::smp_synch_diag_reason_name(latest.reason), static_cast(latest.monotonic_ms), + static_cast(latest.phase_error_us), + static_cast(latest.mac_pairs), static_cast(flight.phase_error_us), static_cast(flight.uncertainty_us), static_cast(flight.mac_pairs), diff --git a/embedded/esp32p4_smv_injector/main/live_control.cpp b/embedded/esp32p4_smv_injector/main/live_control.cpp index c0fa21e8f..befd163b9 100644 --- a/embedded/esp32p4_smv_injector/main/live_control.cpp +++ b/embedded/esp32p4_smv_injector/main/live_control.cpp @@ -342,11 +342,15 @@ void print_sv_sync_diagnostics() noexcept { } for (std::size_t i = 0U; i < s.recent_count; ++i) { const auto& e = s.recent[i]; - ESP_LOGI(kTag, "SVSYNC EVENT seq=%lu uptime_ms=%lu state=%s reason=%s", + ESP_LOGI(kTag, + "SVSYNC EVENT seq=%lu uptime_ms=%lu state=%s reason=%s " + "event_phase_us=%ld event_MACpairs=%lu", static_cast(e.sequence), static_cast(e.monotonic_ms), e.acquired ? "ACQUIRED" : "REVOKED", - smp_synch_diag_reason_name(e.reason)); + smp_synch_diag_reason_name(e.reason), + static_cast(e.phase_error_us), + static_cast(e.mac_pairs)); } ESP_LOGI(kTag, "SVSYNC END events=%lu", static_cast(s.events)); } diff --git a/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp b/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp index 1b0711a5b..f349049d5 100644 --- a/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp +++ b/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp @@ -9,6 +9,10 @@ #include #include +#if defined(ESP_PLATFORM) +#include "esp_timer.h" +#endif + namespace ar::esp32p4::smv { namespace { @@ -31,6 +35,8 @@ constexpr std::size_t kReasonCount = std::array, kReasonCount> g_cause_counts{}; std::array, kSvSyncFlightEventCapacity> g_event_codes{}; std::array, kSvSyncFlightEventCapacity> g_event_times{}; +std::array, kSvSyncFlightEventCapacity> g_event_phases{}; +std::array, kSvSyncFlightEventCapacity> g_event_mac_pairs{}; std::atomic g_event_sequence{0U}; std::atomic g_acquisition_count{0U}; std::atomic g_loss_count{0U}; @@ -60,7 +66,22 @@ void record_transition(const SvSyncLossReason reason, const auto code = ((seq & 0xFFFFU) << 16U) | (static_cast(reason) << 1U) | (qualified ? 1U : 0U); - g_event_times[slot].store(uptime_ms, std::memory_order_relaxed); + // Invalidate BEFORE replacing timestamp/context. Otherwise a reader + // could observe the previous published code with the next event's time. + g_event_codes[slot].store(0U, std::memory_order_release); + std::uint32_t event_ms = uptime_ms; +#if defined(ESP_PLATFORM) + // Control-plane STOP/mode/GM events need valid uptime even when their + // portable caller did not provide a monotonic timestamp. + if (event_ms == 0U) + event_ms = static_cast(esp_timer_get_time() / 1000LL); +#endif + g_event_times[slot].store(event_ms, std::memory_order_relaxed); + g_event_phases[slot].store( + g_diag_phase_us.load(std::memory_order_relaxed), std::memory_order_relaxed); + g_event_mac_pairs[slot].store( + g_diag_mac_pairs.load(std::memory_order_relaxed), std::memory_order_relaxed); + // A code is a publication marker and carries a 16-bit sequence tag. g_event_codes[slot].store(code, std::memory_order_release); } @@ -195,18 +216,24 @@ SvSyncFlightSnapshot smp_synch_diag_snapshot() noexcept { const auto slot = static_cast( (seq - 1U) % kSvSyncFlightEventCapacity); const auto before = g_event_codes[slot].load(std::memory_order_acquire); - if (((before >> 16U) & 0xFFFFU) != (seq & 0xFFFFU)) continue; + if (before == 0U || + ((before >> 16U) & 0xFFFFU) != (seq & 0xFFFFU)) continue; const auto time = g_event_times[slot].load(std::memory_order_relaxed); + const auto phase = g_event_phases[slot].load(std::memory_order_relaxed); + const auto pairs = g_event_mac_pairs[slot].load(std::memory_order_relaxed); const auto after = g_event_codes[slot].load(std::memory_order_acquire); - if (before != after) continue; // overwritten during read + if (before != after) continue; // concurrent overwrite: skip, never invent s.recent[s.recent_count++] = SvSyncFlightEvent{ - seq, time, + seq, time, phase, pairs, static_cast((before >> 1U) & 0xFFU), (before & 1U) != 0U }; } return s; } +std::uint32_t smp_synch_diag_event_count() noexcept { + return g_event_sequence.load(std::memory_order_acquire); +} const char* smp_synch_diag_reason_name(const SvSyncLossReason reason) noexcept { switch (reason) { case SvSyncLossReason::none: return "ACQUIRED"; @@ -223,6 +250,11 @@ const char* smp_synch_diag_reason_name(const SvSyncLossReason reason) noexcept { case SvSyncLossReason::ptp_stop: return "PTP_STOP"; case SvSyncLossReason::operator_mode: return "OPERATOR_MODE_CHANGE"; case SvSyncLossReason::other: return "UNCLASSIFIED_REVOCATION"; + case SvSyncLossReason::mac_missing_timestamp: return "MAC_HW_TIMESTAMP_MISSING"; + case SvSyncLossReason::mac_bad_epoch: return "MAC_EPOCH_NOT_QUALIFIED"; + case SvSyncLossReason::mac_publisher_discontinuity: return "MAC_PUBLISHER_DISCONTINUITY"; + case SvSyncLossReason::mac_ptp_clock_step: return "MAC_PTP_CLOCK_STEP"; + case SvSyncLossReason::mac_baseline_reset: return "MAC_EVIDENCE_REBASELINE"; case SvSyncLossReason::count: break; } return "UNKNOWN"; diff --git a/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp b/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp index 1a9521508..1d9d1f280 100644 --- a/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp +++ b/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp @@ -40,12 +40,16 @@ enum class SvSyncLossReason : std::uint8_t { none, missed_slot, ethernet_link, observer_stale, mac_egress, canonical_tx, ptp_lease, observer_epoch, phase_or_mac, phase_handoff, publisher_stop, ptp_stop, operator_mode, other, + mac_missing_timestamp, mac_bad_epoch, mac_publisher_discontinuity, + mac_ptp_clock_step, mac_baseline_reset, count }; constexpr std::size_t kSvSyncFlightEventCapacity = 16; struct SvSyncFlightEvent final { std::uint32_t sequence{}; std::uint32_t monotonic_ms{}; + std::int32_t phase_error_us{}; + std::uint32_t mac_pairs{}; SvSyncLossReason reason{SvSyncLossReason::none}; bool acquired{}; }; @@ -70,6 +74,7 @@ void smp_synch_diag_observe(std::int32_t phase_us, std::uint32_t uncertainty_us, std::uint32_t mac_pairs, std::uint32_t clean_epochs, std::uint32_t epoch, bool accepted, bool tracking) noexcept; [[nodiscard]] SvSyncFlightSnapshot smp_synch_diag_snapshot() noexcept; +[[nodiscard]] std::uint32_t smp_synch_diag_event_count() noexcept; [[nodiscard]] const char* smp_synch_diag_reason_name(SvSyncLossReason reason) noexcept; void smp_synch_set_source_local_qualified( bool qualified, SvSyncLossReason reason = SvSyncLossReason::other, diff --git a/tests/test_smp_synch_policy.cpp b/tests/test_smp_synch_policy.cpp index 93987ec72..c3ffc70a7 100644 --- a/tests/test_smp_synch_policy.cpp +++ b/tests/test_smp_synch_policy.cpp @@ -115,6 +115,15 @@ void test_internal_sync_recorder_captures_cause_and_bounded_history() { require(after.recent[after.recent_count-1].reason == SvSyncLossReason::mac_egress && !after.recent[after.recent_count-1].acquired, "newest loss must retain exact cause"); + require(after.recent[after.recent_count-1].phase_error_us == -3 && + after.recent[after.recent_count-1].mac_pairs == 4U && + after.recent[after.recent_count-1].monotonic_ms == 1041U, + "each lock edge must preserve event-local phase, MAC and uptime"); + require(smp_synch_diag_event_count() == after.events, + "fast event count must match full snapshot"); + require(smp_synch_diag_reason_name(SvSyncLossReason::mac_missing_timestamp) != + smp_synch_diag_reason_name(SvSyncLossReason::mac_ptp_clock_step), + "missing TX timestamp and clock step must have distinct labels"); require(after.phase_error_us == -3 && after.uncertainty_us == 2U && after.mac_pairs == 4U && after.clean_epochs == 10U && after.sample_epoch == 101U && after.phase_accepted &&