diff --git a/apps/arstack_studio/qml/PtpExpertPanel.qml b/apps/arstack_studio/qml/PtpExpertPanel.qml index 14fb81763..1e1fe8bd2 100644 --- a/apps/arstack_studio/qml/PtpExpertPanel.qml +++ b/apps/arstack_studio/qml/PtpExpertPanel.qml @@ -297,6 +297,18 @@ SurfacePanel { enabled: panel.session && panel.device.deviceVerified && !panel.session.updatingFirmware onClicked: panel.session.requestPtpRefresh() } + CalmButton { + theme: panel.theme + uiFont: panel.uiFont + text: "Inspect SV lock" + enabled: panel.session && panel.device.deviceVerified && + !panel.session.updatingFirmware + onClicked: { + if (!panel.session.requestSyncDiagnostics() && panel.controller) + panel.controller.showMessage( + "SV lock inspection is waiting for an active configuration transaction to finish.", true) + } + } CalmButton { theme: panel.theme uiFont: panel.uiFont @@ -321,6 +333,47 @@ SurfacePanel { } } + Rectangle { + Layout.fillWidth: true + radius: 8 + color: panel.theme.surface2 + border.width: 1 + border.color: panel.theme.lineSoft + implicitHeight: flightContent.implicitHeight + 24 + ColumnLayout { + id: flightContent + anchors.left: parent.left + anchors.right: parent.right + anchors.top: parent.top + anchors.margins: 12 + spacing: 6 + Label { + Layout.fillWidth: true + text: "SV LOCK · INTERNAL FLIGHT RECORDER" + color: panel.theme.text + font.family: panel.uiFont + font.pixelSize: 10 + font.weight: Font.DemiBold + } + Label { + Layout.fillWidth: true + text: panel.device.syncDiagnostics + color: panel.theme.textSoft + font.family: panel.monoFont + font.pixelSize: 9 + wrapMode: Text.WrapAnywhere + } + Label { + Layout.fillWidth: true + text: "Board-internal reasons, not an independently certified PTP/IED lock." + color: panel.theme.muted + font.family: panel.uiFont + font.pixelSize: 9 + wrapMode: Text.WordWrap + } + } + } + Rectangle { Layout.fillWidth: true implicitHeight: 102 diff --git a/apps/arstack_studio/qml/SvCapturePanel.qml b/apps/arstack_studio/qml/SvCapturePanel.qml index 1d82c503f..e729c46b8 100644 --- a/apps/arstack_studio/qml/SvCapturePanel.qml +++ b/apps/arstack_studio/qml/SvCapturePanel.qml @@ -42,7 +42,8 @@ Rectangle { "ptp_offset_ns": panel.device ? panel.device.ptpOffsetNs : "", "device_fps": panel.device ? panel.device.fps : "", "device_missed": panel.device ? panel.device.missed : "", - "device_tx_failures": panel.device ? panel.device.txFailures : "" + "device_tx_failures": panel.device ? panel.device.txFailures : "", + "onboard_sync_flight_UNVERIFIED": panel.device ? panel.device.syncFlightLatest : "" } } diff --git a/apps/arstack_studio/src/DeviceController.cpp b/apps/arstack_studio/src/DeviceController.cpp index 2fe48ed7f..de3bd25dc 100644 --- a/apps/arstack_studio/src/DeviceController.cpp +++ b/apps/arstack_studio/src/DeviceController.cpp @@ -1682,6 +1682,29 @@ void DeviceController::processLine(const QString& rawLine) { if (line.isEmpty()) return; appendLog(QStringLiteral("←"), line); + // Explicit on-board flight recorder response. Do not poll from the + // UI render path or treat historical reports as new lock evidence. + const auto flightPos = line.indexOf(QStringLiteral("SVSYNC ")); + if (flightPos >= 0) { + const QString flightLine = line.mid(flightPos).trimmed(); + if (flightLine.startsWith(QStringLiteral("SVSYNC FLIGHT "))) { + syncFlightLatest_ = flightLine; + // Firmware emits one bounded fault summary from its telemetry + // task when a lock edge occurs. Surface it even if Inspect has + // not been clicked, never as a declaration of physical PASS. + syncDiagnostics_ = flightLine + QLatin1Char('\n') + syncDiagnostics_; + } + if (flightLine.startsWith(QStringLiteral("SVSYNC DIAG "))) + syncDiagnostics_ = flightLine; + else if (flightLine.startsWith(QStringLiteral("SVSYNC CAUSE ")) || + flightLine.startsWith(QStringLiteral("SVSYNC EVENT "))) + syncDiagnostics_ += QLatin1Char('\n') + flightLine; + // END marks a complete snapshot, never a certification. + if (syncDiagnostics_.size() > 6000) + syncDiagnostics_ = syncDiagnostics_.right(6000); + emit syncDiagnosticsChanged(); + } + // Only the owner of the current session+boot may advance commit -> readback -> START. // Regexes search through ESP-IDF log prefixes; all token fields are matched strictly. const auto scenarioCommitted = kScenarioCommitExpression.match(line); @@ -1946,6 +1969,10 @@ void DeviceController::resetTelemetry() { void DeviceController::resetPtpState() { resetPtpStartup(); + syncDiagnostics_ = QStringLiteral( + "No current-board SV lock evidence. Select Inspect SV lock after verification."); + syncFlightLatest_.clear(); + emit syncDiagnosticsChanged(); ptpAvailable_ = false; ptpRunning_ = false; ptpStatus_ = QStringLiteral("Waiting for device"); diff --git a/apps/arstack_studio/src/DeviceController.hpp b/apps/arstack_studio/src/DeviceController.hpp index c80e465d7..1021c8f59 100644 --- a/apps/arstack_studio/src/DeviceController.hpp +++ b/apps/arstack_studio/src/DeviceController.hpp @@ -54,6 +54,8 @@ class DeviceController : public QObject { Q_PROPERTY(QString portName READ portName NOTIFY connectedChanged) Q_PROPERTY(QString lastError READ lastError NOTIFY lastErrorChanged) Q_PROPERTY(QString logText READ logText NOTIFY logTextChanged) + Q_PROPERTY(QString syncDiagnostics READ syncDiagnostics NOTIFY syncDiagnosticsChanged) + Q_PROPERTY(QString syncFlightLatest READ syncFlightLatest NOTIFY syncDiagnosticsChanged) Q_PROPERTY(QString fps READ fps NOTIFY telemetryChanged) Q_PROPERTY(QString missed READ missed NOTIFY telemetryChanged) Q_PROPERTY(QString txFailures READ txFailures NOTIFY telemetryChanged) @@ -139,6 +141,8 @@ class DeviceController : public QObject { [[nodiscard]] QString portName() const; [[nodiscard]] QString lastError() const; [[nodiscard]] QString logText() const; + [[nodiscard]] QString syncDiagnostics() const { return syncDiagnostics_; } + [[nodiscard]] QString syncFlightLatest() const { return syncFlightLatest_; } [[nodiscard]] QString fps() const; [[nodiscard]] QString missed() const; [[nodiscard]] QString txFailures() const; @@ -259,6 +263,7 @@ class DeviceController : public QObject { return sendCommand(QStringLiteral("PROFILE PTPROLE %1").arg(role)); } + bool sendPtpDiagnostics() { return sendCommand(QStringLiteral("PTP DIAG")); } bool sendSmpSynchShow() { return sendCommand(QStringLiteral("PROFILE SHOW")); } @@ -287,6 +292,7 @@ class DeviceController : public QObject { void runningChanged(); void lastErrorChanged(); void logTextChanged(); + void syncDiagnosticsChanged(); void telemetryChanged(); void profileStateChanged(); void profileDeploymentProgress(); @@ -389,6 +395,8 @@ class DeviceController : public QObject { DeviceIdentity identity_; QString lastError_; QString logText_; + QString syncDiagnostics_{QStringLiteral("Select Inspect SV lock to read on-board causes.")}; + QString syncFlightLatest_; QString fps_{QStringLiteral("—")}; QString missed_{QStringLiteral("—")}; QString txFailures_{QStringLiteral("—")}; diff --git a/apps/arstack_studio/src/SmartSessionController.cpp b/apps/arstack_studio/src/SmartSessionController.cpp index 506fff1ad..8596c5dc8 100644 --- a/apps/arstack_studio/src/SmartSessionController.cpp +++ b/apps/arstack_studio/src/SmartSessionController.cpp @@ -458,6 +458,16 @@ bool SmartSessionController::requestPtpRefresh() { return ptp && sync; } +bool SmartSessionController::requestSyncDiagnostics() { + // Read-only operator request; serialize behind the existing device + // session. Never interleave with START/CFG or firmware port handoff. + if (!deviceControlAvailable() || device_ == nullptr || + device_->ptpStarting() || device_->profileDeploying() || + profileSyncStage_ == ProfileSyncStage::deploying || + device_->scenarioApplying() || updateRequested_) return false; + return device_->sendPtpDiagnostics(); +} + bool SmartSessionController::requestPtpRole(const QString& role) { return deviceControlAvailable() && device_ != nullptr && device_->setPtpRole(role); } @@ -973,6 +983,8 @@ QString SmartSessionController::diagnosticsText() const { add(QStringLiteral("SMV missed reported"), device_->missed()); add(QStringLiteral("SMV TX failures reported"), device_->txFailures()); add(QStringLiteral("PTP status reported"), device_->ptpStatus()); + add(QStringLiteral("SV sync internal flight recorder (not physical proof)"), + device_->syncDiagnostics()); add(QStringLiteral("PTP role reported"), device_->ptpRole()); add(QStringLiteral("PTP discipline reported"), device_->ptpDiscipline()); add(QStringLiteral("SMPSYNCH value reported"), device_->smpSynchValue()); diff --git a/apps/arstack_studio/src/SmartSessionController.hpp b/apps/arstack_studio/src/SmartSessionController.hpp index aa9678d36..6cd1b5a22 100644 --- a/apps/arstack_studio/src/SmartSessionController.hpp +++ b/apps/arstack_studio/src/SmartSessionController.hpp @@ -196,6 +196,7 @@ class SmartSessionController : public QObject { double clipPercent); Q_INVOKABLE bool requestZero(); Q_INVOKABLE bool requestPtpRefresh(); + Q_INVOKABLE bool requestSyncDiagnostics(); Q_INVOKABLE bool requestPtpRole(const QString& role); Q_INVOKABLE bool requestSmpSynch(const QString& mode); Q_INVOKABLE bool requestConfigurePtp(const QVariantMap& profile); diff --git a/apps/arstack_studio/tests/check_operator_workspace.py b/apps/arstack_studio/tests/check_operator_workspace.py index 4e5e8766f..2ef92f5fe 100644 --- a/apps/arstack_studio/tests/check_operator_workspace.py +++ b/apps/arstack_studio/tests/check_operator_workspace.py @@ -425,6 +425,26 @@ def main() -> None: "QDesktopServices::openUrl(" in capture_cpp and "QString findDumpcap()" in capture_cpp, "Studio capture results must derive from production wire decoder with click-only setup") + ptp_src = source("PtpExpertPanel.qml") + ptp_fw = (STUDIO.parent.parent / "embedded/esp32p4_smv_injector/main/live_control.cpp").read_text(encoding="utf-8") + ptp_sync = (STUDIO.parent.parent / "embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp").read_text(encoding="utf-8") + dev_h = (STUDIO / "src/DeviceController.hpp").read_text(encoding="utf-8") + dev_cpp = (STUDIO / "src/DeviceController.cpp").read_text(encoding="utf-8") + session_h = (STUDIO / "src/SmartSessionController.hpp").read_text(encoding="utf-8") + require('text: "Inspect SV lock"' in ptp_src and + "panel.session.requestSyncDiagnostics()" in ptp_src and + "panel.device.syncDiagnostics" in ptp_src and + 'std::strcmp(subcommand, "DIAG")' in ptp_fw and + '"SVSYNC EVENT seq=' in ptp_fw and + "record_transition(" in ptp_sync and + "Q_PROPERTY(QString syncDiagnostics" in dev_h and + "SVSYNC DIAG " in dev_cpp and + "requestSyncDiagnostics()" in session_h and + "onboard_sync_flight_UNVERIFIED" in capture_ui and + "syncFlightLatest" in dev_h and + "syncFlightLatest_ = flightLine" in dev_cpp, + "Studio must expose the physical firmware's internal, reason-coded " + "lock flight recorder in Time Sync and correlate it passively with Capture") print("Studio operator workspace contract: PASS") diff --git a/embedded/esp32p4_smv_injector/main/app_main.cpp b/embedded/esp32p4_smv_injector/main/app_main.cpp index 28ecc10dd..70d410a58 100644 --- a/embedded/esp32p4_smv_injector/main/app_main.cpp +++ b/embedded/esp32p4_smv_injector/main/app_main.cpp @@ -79,6 +79,8 @@ using ar::esp32p4::smv::SvSyncPolicyMode; using ar::esp32p4::smv::smp_synch_set_source_local_qualified; using ar::esp32p4::smv::smp_synch_source_local_qualified; using ar::esp32p4::smv::smp_synch_set_receiver_timeline_qualified; +using ar::esp32p4::smv::smp_synch_diag_observe; +using ar::esp32p4::smv::SvSyncLossReason; using ar::esp32p4::smv::smp_synch_receiver_timeline_qualified; using ar::esp32p4::smv::take_start_request; using ar::iec61850::ethernet::MacAddress; @@ -127,9 +129,16 @@ constexpr std::uint32_t kTimerResolutionHz = 1000000U; // receiver invalidation INSIDE the same conditional as SOURCE invalidation: // clearing it unconditionally after a valid sparse MAC TX stamp would make // RECEIVER qualification impossible at every evidence epoch. -inline void revoke_sv_auto_claims() noexcept { - smp_synch_set_source_local_qualified(false); - smp_synch_set_receiver_timeline_qualified(false); +inline void revoke_sv_auto_claims( + const SvSyncLossReason reason = SvSyncLossReason::other) noexcept { + // Only timestamp an actual lock transition; ordinary 4kHz frame + // processing keeps its existing work budget. + const bool was_qualified = smp_synch_source_local_qualified() || + smp_synch_receiver_timeline_qualified(); + const auto ms = was_qualified + ? static_cast(esp_timer_get_time() / 1000LL) : 0U; + smp_synch_set_source_local_qualified(false, reason, ms); + smp_synch_set_receiver_timeline_qualified(false, reason, ms); } EventGroupHandle_t g_link_events = nullptr; @@ -711,7 +720,7 @@ void stop_sample_clock(gptimer_handle_t& timer) noexcept { #endif // Release the wire claim before teardown; old MAC evidence never // survives STOP/START, even when the same SOURCE later restarts. - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::publisher_stop); if (timer == nullptr) return; #if AR_SV_PTP_PHASE_SUPPORTED // Serialize teardown with the non-ISR phase observer, so a GPTimer @@ -982,7 +991,7 @@ void publisher_task(void* argument) { 1U, std::memory_order_release); g_sample_clock_context.phase_authority_valid.store( false, std::memory_order_release); - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::missed_slot); #endif missed_slots = static_cast(pending_ticks - 1U); canonical_sample_count = static_cast( @@ -1009,7 +1018,7 @@ void publisher_task(void* argument) { 1U, std::memory_order_release); g_sample_clock_context.phase_authority_valid.store( false, std::memory_order_release); - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::ethernet_link); #endif #if CONFIG_AR_SMV_BROADCAST_MIRROR ++local.mirror_fail; @@ -1019,20 +1028,27 @@ void publisher_task(void* argument) { // After qualification, consult the lightweight SOURCE freshness // authority on each frame; a stopped/faulted PTP source must not // continue advertising previously measured local synchronization. - if ((smp_synch_source_local_qualified() || - smp_synch_receiver_timeline_qualified()) && - (!g_sample_clock_context.phase_authority_valid.load( - std::memory_order_acquire) || - !ar::iec61850::time_sync::SvPhaseObservationFreshness::fresh( - g_sample_clock_context.last_phase_observed_epoch.load( - std::memory_order_acquire), - g_sample_clock_context.epoch_generation.load( - std::memory_order_acquire)) || - (g_sample_clock_context.armed_ptp_clock.role == - PtpAuthorityRole::source && - ar_ptp_lab_source_generation() != - g_sample_clock_context.armed_ptp_clock.generation))) { - revoke_sv_auto_claims(); + if (smp_synch_source_local_qualified() || + smp_synch_receiver_timeline_qualified()) { + const bool phase_ok = g_sample_clock_context.phase_authority_valid.load( + std::memory_order_acquire); + const bool observer_fresh = + ar::iec61850::time_sync::SvPhaseObservationFreshness::fresh( + g_sample_clock_context.last_phase_observed_epoch.load( + std::memory_order_acquire), + g_sample_clock_context.epoch_generation.load( + std::memory_order_acquire)); + const bool source_generation_ok = + g_sample_clock_context.armed_ptp_clock.role != + PtpAuthorityRole::source || + ar_ptp_lab_source_generation() == + g_sample_clock_context.armed_ptp_clock.generation; + if (!source_generation_ok) + revoke_sv_auto_claims(SvSyncLossReason::ptp_lease); + else if (!observer_fresh) + revoke_sv_auto_claims(SvSyncLossReason::observer_stale); + else if (!phase_ok) + revoke_sv_auto_claims(SvSyncLossReason::phase_or_mac); } #endif const auto sync_decision = smp_synch_lab_decision(); @@ -1128,7 +1144,7 @@ void publisher_task(void* argument) { 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(); + revoke_sv_auto_claims(SvSyncLossReason::mac_egress); } #else const esp_err_t canonical_result = @@ -1147,7 +1163,7 @@ void publisher_task(void* argument) { 1U, std::memory_order_release); g_sample_clock_context.phase_authority_valid.store( false, std::memory_order_release); - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::canonical_tx); #endif } @@ -1209,7 +1225,7 @@ void revoke_sv_phase_session(const std::uint32_t expected_session) noexcept { false, std::memory_order_release); g_sample_clock_context.requested_slew_ticks.store( 0, std::memory_order_relaxed); - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::ptp_lease); } xSemaphoreGive(g_phase_timer_mutex); } @@ -1429,13 +1445,23 @@ 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. + const auto stamp_ms = static_cast( + esp_timer_get_time() / 1000LL); smp_synch_set_source_local_qualified( - stable_local && lease.role == PtpAuthorityRole::source); + stable_local && lease.role == PtpAuthorityRole::source, + SvSyncLossReason::phase_or_mac, stamp_ms); smp_synch_set_receiver_timeline_qualified( - stable_local && lease.role == PtpAuthorityRole::receiver); + 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(); + revoke_sv_auto_claims(SvSyncLossReason::publisher_stop); } committed = true; } else if (session_matches) { @@ -1454,7 +1480,7 @@ void sv_ptp_phase_observer_task(void* argument) { g_sample_clock_context.requested_slew_ticks.store( 0, std::memory_order_relaxed); local_acquisition.reset(); - revoke_sv_auto_claims(); + revoke_sv_auto_claims(SvSyncLossReason::phase_handoff); } xSemaphoreGive(g_phase_timer_mutex); if (!committed) { @@ -1502,12 +1528,37 @@ void telemetry_task(void*) { std::int64_t previous_tick_time_us = 0; bool rate_baseline_valid = false; TimingStats baseline_stats{}; + std::uint32_t last_flight_events_reported = 0U; #if AR_SV_TX_EGRESS_SUPPORTED std::uint32_t previously_reported_egress = 0U; #endif while (true) { vTaskDelay(pdMS_TO_TICKS(1000)); + // No serial logging on the real-time publisher or phase ISR. + // 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) { + 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", + 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(flight.phase_error_us), + static_cast(flight.uncertainty_us), + static_cast(flight.mac_pairs), + static_cast(flight.clean_epochs)); + } + } TimingStats snapshot{}; portENTER_CRITICAL(&g_stats_mux); snapshot = g_interval_stats; diff --git a/embedded/esp32p4_smv_injector/main/live_control.cpp b/embedded/esp32p4_smv_injector/main/live_control.cpp index 261bde4e7..c0fa21e8f 100644 --- a/embedded/esp32p4_smv_injector/main/live_control.cpp +++ b/embedded/esp32p4_smv_injector/main/live_control.cpp @@ -3,6 +3,7 @@ #include "live_control.hpp" #include "ethernet_port.h" #include "profile_control.hpp" +#include "smp_synch_lab.hpp" #include "ariec61850/sampled_values/live_signal_transaction.hpp" #include "esp_app_desc.h" @@ -238,7 +239,7 @@ void print_help() noexcept { ESP_LOGI(kTag, " ENABLE <0|1>"); ESP_LOGI(kTag, " QUALITY "); ESP_LOGI(kTag, " SHAPE CT <0|1> "); - ESP_LOGI(kTag, " PTP SHOW | PTP START | PTP STOP"); + ESP_LOGI(kTag, " PTP SHOW | PTP DIAG | PTP START | PTP STOP"); ESP_LOGI(kTag, " PTP CONFIG "); ESP_LOGI(kTag, "GUI profile deployment uses bounded PROFILE subcommands while STOPPED."); } @@ -311,6 +312,45 @@ void print_ptp_state() noexcept { #endif } +void print_sv_sync_diagnostics() noexcept { + // Operator-triggered read-only snapshot of the ACTUAL internal gate. + // Never read MAC descriptors or add any polling to the 4kHz publisher. + const auto s = smp_synch_diag_snapshot(); + ESP_LOGI(kTag, + "SVSYNC DIAG events=%lu acquired=%lu revoked=%lu source=%u receiver=%u " + "phase_us=%ld uncertainty_us=%lu mac_pairs=%lu clean=%lu epoch=%lu " + "accepted=%u tracking=%u", + static_cast(s.events), + static_cast(s.acquisitions), + static_cast(s.losses), + smp_synch_source_local_qualified() ? 1U : 0U, + smp_synch_receiver_timeline_qualified() ? 1U : 0U, + static_cast(s.phase_error_us), + static_cast(s.uncertainty_us), + static_cast(s.mac_pairs), + static_cast(s.clean_epochs), + static_cast(s.sample_epoch), + s.phase_accepted ? 1U : 0U, + s.software_tracking ? 1U : 0U); + for (std::size_t i = 1U; + i < static_cast(SvSyncLossReason::count); ++i) { + if (s.cause_counts[i] == 0U) continue; + const auto reason = static_cast(i); + ESP_LOGI(kTag, "SVSYNC CAUSE reason=%s count=%lu", + smp_synch_diag_reason_name(reason), + static_cast(s.cause_counts[i])); + } + 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", + static_cast(e.sequence), + static_cast(e.monotonic_ms), + e.acquired ? "ACQUIRED" : "REVOKED", + smp_synch_diag_reason_name(e.reason)); + } + ESP_LOGI(kTag, "SVSYNC END events=%lu", static_cast(s.events)); +} + void handle_ptp_command(char* save) noexcept { char* subcommand = strtok_r(nullptr, kTokenDelimiters.data(), &save); if (subcommand == nullptr) { @@ -324,6 +364,11 @@ void handle_ptp_command(char* save) noexcept { else print_ptp_state(); return; } + if (std::strcmp(subcommand, "DIAG") == 0) { + if (has_extra_token(&save)) ESP_LOGE(kTag, "Usage: PTP DIAG"); + else print_sv_sync_diagnostics(); + return; + } #if CONFIG_AR_PTP_LAB_TX if (std::strcmp(subcommand, "START") == 0) { if (has_extra_token(&save)) { diff --git a/embedded/esp32p4_smv_injector/main/ptp_mode_facade.cpp b/embedded/esp32p4_smv_injector/main/ptp_mode_facade.cpp index d1a20d682..d3df56967 100644 --- a/embedded/esp32p4_smv_injector/main/ptp_mode_facade.cpp +++ b/embedded/esp32p4_smv_injector/main/ptp_mode_facade.cpp @@ -125,8 +125,10 @@ void fill_p2_defaults(ar_ptp_lab_config_t& config) noexcept { void stop_active_ptp_roles() noexcept { // Operator STOP or role handoff revokes the transmitted AUTO local-sync // claim immediately, independent of the slower phase observer cadence. - smp_synch_set_source_local_qualified(false); - smp_synch_set_receiver_timeline_qualified(false); + smp_synch_set_source_local_qualified( + false, ar::esp32p4::smv::SvSyncLossReason::ptp_stop); + smp_synch_set_receiver_timeline_qualified( + false, ar::esp32p4::smv::SvSyncLossReason::ptp_stop); if (ar_ptp_source_runtime_active()) { ar_ptp_source_stop(); } @@ -295,8 +297,10 @@ extern "C" void ar_ptp_lab_start(const esp_eth_handle_t eth_handle) { extern "C" void ar_ptp_lab_stop(void) { // A PTP stop must revoke both live SV timing claims BEFORE asynchronous // task teardown can complete, including external-GM receiver claims. - ar::esp32p4::smv::smp_synch_set_source_local_qualified(false); - ar::esp32p4::smv::smp_synch_set_receiver_timeline_qualified(false); + ar::esp32p4::smv::smp_synch_set_source_local_qualified( + false, ar::esp32p4::smv::SvSyncLossReason::ptp_stop); + ar::esp32p4::smv::smp_synch_set_receiver_timeline_qualified( + false, ar::esp32p4::smv::SvSyncLossReason::ptp_stop); // Publish the cancellation immediately. If START/config owns the // slot, that owner drains STOP at the atomic release boundary. if (ar::esp32p4::smv::g_role_control.request_stop_and_try_acquire()) { diff --git a/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp b/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp index bc3ea7779..1b0711a5b 100644 --- a/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp +++ b/embedded/esp32p4_smv_injector/main/smp_synch_lab.cpp @@ -3,6 +3,8 @@ #include "smp_synch_lab.hpp" #include "ariec61850/time_sync/sv_ptp_epoch.hpp" +#include +#include #include #include #include @@ -21,6 +23,47 @@ std::atomic g_measured_value{-1}; std::atomic_bool g_sv_timeline_phase_qualified{false}; std::atomic_bool g_source_local_qualified{false}; +// Fixed 16-event on-board flight recorder. Two 32-bit atomic words per +// slot avoid 64-bit atomics (not guaranteed lock-free on ESP32-P4). A +// sequence-stamped entry is published LAST with release ordering. +constexpr std::size_t kReasonCount = + static_cast(SvSyncLossReason::count); +std::array, kReasonCount> g_cause_counts{}; +std::array, kSvSyncFlightEventCapacity> g_event_codes{}; +std::array, kSvSyncFlightEventCapacity> g_event_times{}; +std::atomic g_event_sequence{0U}; +std::atomic g_acquisition_count{0U}; +std::atomic g_loss_count{0U}; +std::atomic g_diag_phase_us{0}; +std::atomic g_diag_uncertainty_us{0U}; +std::atomic g_diag_mac_pairs{0U}; +std::atomic g_diag_clean_epochs{0U}; +std::atomic g_diag_epoch{0U}; +std::atomic_bool g_diag_accepted{false}; +std::atomic_bool g_diag_tracking{false}; +static_assert(std::atomic::is_always_lock_free); +static_assert(std::atomic::is_always_lock_free); + +void record_transition(const SvSyncLossReason reason, + const bool qualified, + const std::uint32_t uptime_ms) noexcept { + if (qualified) g_acquisition_count.fetch_add(1U, std::memory_order_relaxed); + else { + g_loss_count.fetch_add(1U, std::memory_order_relaxed); + const auto cause = static_cast(reason); + if (cause < kReasonCount) + g_cause_counts[cause].fetch_add(1U, std::memory_order_relaxed); + } + const auto seq = g_event_sequence.fetch_add(1U, std::memory_order_acq_rel) + 1U; + const auto slot = static_cast( + (seq - 1U) % kSvSyncFlightEventCapacity); + const auto code = ((seq & 0xFFFFU) << 16U) | + (static_cast(reason) << 1U) | + (qualified ? 1U : 0U); + g_event_times[slot].store(uptime_ms, std::memory_order_relaxed); + g_event_codes[slot].store(code, std::memory_order_release); +} + [[nodiscard]] std::optional measured_value() noexcept { const int raw = g_measured_value.load(std::memory_order_acquire); switch (raw) { @@ -58,8 +101,8 @@ void smp_synch_lab_set_mode(const SvSyncPolicyMode mode) noexcept { if (old != static_cast(mode)) { // Single serial control-plane writer. Revoke BEFORE exposing AUTO, // never allow even one 4kHz wire frame to inherit stale override proof. - g_source_local_qualified.store(false, std::memory_order_release); - g_sv_timeline_phase_qualified.store(false, std::memory_order_release); + smp_synch_set_source_local_qualified(false, SvSyncLossReason::operator_mode); + smp_synch_set_receiver_timeline_qualified(false, SvSyncLossReason::operator_mode); } g_mode.store(static_cast(mode), std::memory_order_release); } @@ -86,7 +129,8 @@ void smp_synch_lab_set_measured(const std::optional value) noexce // A LOST/UNLOCKED PTP receiver invalidates the SV timeline proof, // not merely the visible measured-PTP value. Relock must establish // fresh phase and MAC evidence before AUTO may promote again. - g_sv_timeline_phase_qualified.store(false, std::memory_order_release); + smp_synch_set_receiver_timeline_qualified( + false, SvSyncLossReason::ptp_lease); g_measured_value.store( value.has_value() ? 0 : -1, std::memory_order_release); return; @@ -96,16 +140,92 @@ void smp_synch_lab_set_measured(const std::optional value) noexce std::memory_order_release); } -void smp_synch_set_source_local_qualified(const bool qualified) noexcept { - g_source_local_qualified.store(qualified, std::memory_order_release); +void smp_synch_set_source_local_qualified( + const bool qualified, const SvSyncLossReason reason, + const std::uint32_t monotonic_ms) noexcept { + if (g_source_local_qualified.exchange( + qualified, std::memory_order_acq_rel) != qualified) + record_transition(qualified ? SvSyncLossReason::none : reason, + qualified, monotonic_ms); } bool smp_synch_source_local_qualified() noexcept { return g_source_local_qualified.load(std::memory_order_acquire); } -void smp_synch_set_receiver_timeline_qualified(const bool qualified) noexcept { - g_sv_timeline_phase_qualified.store(qualified, std::memory_order_release); +void smp_synch_set_receiver_timeline_qualified( + const bool qualified, const SvSyncLossReason reason, + const std::uint32_t monotonic_ms) noexcept { + if (g_sv_timeline_phase_qualified.exchange( + qualified, std::memory_order_acq_rel) != qualified) + record_transition(qualified ? SvSyncLossReason::none : reason, + qualified, monotonic_ms); +} + +void smp_synch_diag_observe( + const std::int32_t phase_us, const std::uint32_t uncertainty_us, + const std::uint32_t mac_pairs, const std::uint32_t clean_epochs, + const std::uint32_t epoch, const bool accepted, const bool tracking) noexcept { + g_diag_phase_us.store(phase_us, std::memory_order_relaxed); + g_diag_uncertainty_us.store(uncertainty_us, std::memory_order_relaxed); + g_diag_mac_pairs.store(mac_pairs, std::memory_order_relaxed); + g_diag_clean_epochs.store(clean_epochs, std::memory_order_relaxed); + g_diag_epoch.store(epoch, std::memory_order_release); + g_diag_accepted.store(accepted, std::memory_order_relaxed); + g_diag_tracking.store(tracking, std::memory_order_relaxed); +} +SvSyncFlightSnapshot smp_synch_diag_snapshot() noexcept { + SvSyncFlightSnapshot s{}; + s.events = g_event_sequence.load(std::memory_order_acquire); + s.acquisitions = g_acquisition_count.load(std::memory_order_relaxed); + s.losses = g_loss_count.load(std::memory_order_relaxed); + s.phase_error_us = g_diag_phase_us.load(std::memory_order_relaxed); + s.uncertainty_us = g_diag_uncertainty_us.load(std::memory_order_relaxed); + s.mac_pairs = g_diag_mac_pairs.load(std::memory_order_relaxed); + s.clean_epochs = g_diag_clean_epochs.load(std::memory_order_relaxed); + s.sample_epoch = g_diag_epoch.load(std::memory_order_acquire); + s.phase_accepted = g_diag_accepted.load(std::memory_order_relaxed); + s.software_tracking = g_diag_tracking.load(std::memory_order_relaxed); + for (std::size_t i = 0; i < kReasonCount; ++i) + s.cause_counts[i] = g_cause_counts[i].load(std::memory_order_relaxed); + const auto window = static_cast( + std::min(s.events, kSvSyncFlightEventCapacity)); + for (std::uint32_t offset = window; offset > 0U; --offset) { + const auto seq = s.events - offset + 1U; + 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; + const auto time = g_event_times[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 + s.recent[s.recent_count++] = SvSyncFlightEvent{ + seq, time, + static_cast((before >> 1U) & 0xFFU), + (before & 1U) != 0U + }; + } + return s; +} +const char* smp_synch_diag_reason_name(const SvSyncLossReason reason) noexcept { + switch (reason) { + case SvSyncLossReason::none: return "ACQUIRED"; + case SvSyncLossReason::missed_slot: return "MISSED_SAMPLE_SLOT"; + case SvSyncLossReason::ethernet_link: return "ETHERNET_LINK_LOSS"; + case SvSyncLossReason::observer_stale: return "PHASE_OBSERVER_STALE"; + case SvSyncLossReason::mac_egress: return "MAC_TX_TIMESTAMP_INVALID"; + case SvSyncLossReason::canonical_tx: return "CANONICAL_SV_TX_FAILURE"; + case SvSyncLossReason::ptp_lease: return "PTP_LEASE_OR_GM_CHANGE"; + case SvSyncLossReason::observer_epoch: return "OBSERVER_EPOCH_OR_LINK"; + case SvSyncLossReason::phase_or_mac: return "PHASE_OR_MAC_GATE_LOST"; + case SvSyncLossReason::phase_handoff: return "PHASE_HANDOFF_RACE"; + case SvSyncLossReason::publisher_stop: return "PUBLISHER_STOP"; + case SvSyncLossReason::ptp_stop: return "PTP_STOP"; + case SvSyncLossReason::operator_mode: return "OPERATOR_MODE_CHANGE"; + case SvSyncLossReason::other: return "UNCLASSIFIED_REVOCATION"; + case SvSyncLossReason::count: break; + } + return "UNKNOWN"; } bool smp_synch_receiver_timeline_qualified() noexcept { diff --git a/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp b/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp index 192e441b7..1a9521508 100644 --- a/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp +++ b/embedded/esp32p4_smv_injector/main/smp_synch_lab.hpp @@ -3,7 +3,9 @@ #pragma once #include "ariec61850/time_sync/smp_synch_policy.hpp" - +#include +#include +#include #include namespace ar::esp32p4::smv { @@ -34,14 +36,53 @@ void smp_synch_lab_set_measured(std::optional value) noexcept; /** SOURCE AUTO only: assert local sync after independent scheduled-phase AND * canonical MAC TX evidence have been qualified. Must revoke on STOP, source * change, missed slot, TX failure or stale phase; never claims global sync. */ -void smp_synch_set_source_local_qualified(bool qualified) noexcept; +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, + count +}; +constexpr std::size_t kSvSyncFlightEventCapacity = 16; +struct SvSyncFlightEvent final { + std::uint32_t sequence{}; + std::uint32_t monotonic_ms{}; + SvSyncLossReason reason{SvSyncLossReason::none}; + bool acquired{}; +}; +struct SvSyncFlightSnapshot final { + std::uint32_t events{}; + std::uint32_t losses{}; + std::uint32_t acquisitions{}; + std::int32_t phase_error_us{}; + std::uint32_t uncertainty_us{}; + std::uint32_t mac_pairs{}; + std::uint32_t clean_epochs{}; + std::uint32_t sample_epoch{}; + bool phase_accepted{}; + bool software_tracking{}; + std::array(SvSyncLossReason::count)> cause_counts{}; + std::array recent{}; + std::size_t recent_count{}; +}; +/** Constant-memory on-board recorder. Records transition causes without logging, + * allocation, blocking I/O, mutex, or adding work on ordinary 4kHz frames. */ +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]] const char* smp_synch_diag_reason_name(SvSyncLossReason reason) noexcept; +void smp_synch_set_source_local_qualified( + bool qualified, SvSyncLossReason reason = SvSyncLossReason::other, + std::uint32_t monotonic_ms = 0U) noexcept; [[nodiscard]] bool smp_synch_source_local_qualified() noexcept; /** RECEIVER AUTO only: independently qualified SV sample phase AND actual * canonical TX MAC descriptor continuity. PTP discipline LOCKED alone is * insufficient; optional GLOBAL still comes only from traceable GM evidence. * This is the existing receiver timeline gate, not a second sync authority. */ -void smp_synch_set_receiver_timeline_qualified(bool qualified) noexcept; +void smp_synch_set_receiver_timeline_qualified( + bool qualified, SvSyncLossReason reason = SvSyncLossReason::other, + std::uint32_t monotonic_ms = 0U) noexcept; [[nodiscard]] bool smp_synch_receiver_timeline_qualified() noexcept; } // namespace ar::esp32p4::smv diff --git a/tests/test_smp_synch_policy.cpp b/tests/test_smp_synch_policy.cpp index a2f093fc5..93987ec72 100644 --- a/tests/test_smp_synch_policy.cpp +++ b/tests/test_smp_synch_policy.cpp @@ -92,6 +92,36 @@ void test_receiver_auto_requires_fresh_ptp_and_real_timeline() { "AUTO after manual override is fail closed"); } +void test_internal_sync_recorder_captures_cause_and_bounded_history() { + using namespace ar::esp32p4::smv; + smp_synch_set_source_local_qualified(false); + const auto before = smp_synch_diag_snapshot(); + smp_synch_diag_observe(-3, 2U, 4U, 10U, 101U, true, true); + for (unsigned i = 0; i < 21U; ++i) { + smp_synch_set_source_local_qualified(true, SvSyncLossReason::none, + 1000U + 2U*i); + smp_synch_set_source_local_qualified(false, SvSyncLossReason::mac_egress, + 1001U + 2U*i); + } + const auto after = smp_synch_diag_snapshot(); + require(after.acquisitions >= before.acquisitions + 21U, + "on-board recorder missed acquired edges"); + require(after.losses >= before.losses + 21U, + "on-board recorder missed revocations"); + require(after.cause_counts[static_cast(SvSyncLossReason::mac_egress)] >= 21U, + "MAC timing reason must not be collapsed into generic phase loss"); + require(after.recent_count == kSvSyncFlightEventCapacity, + "flight recorder ring must retain exactly sixteen latest edges"); + 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.phase_error_us == -3 && after.uncertainty_us == 2U && + after.mac_pairs == 4U && after.clean_epochs == 10U && + after.sample_epoch == 101U && after.phase_accepted && + after.software_tracking, + "flight recorder snapshot must retain measured observer inputs"); +} + void test_all_lab_compatibility_modes() { const auto unsync = resolve_sv_sync_policy(SvSyncPolicyMode::honest_unsynchronized); const auto local = resolve_sv_sync_policy(SvSyncPolicyMode::local_compatibility); @@ -135,6 +165,7 @@ int main() { test_auto_is_safe_without_measured_lock(); test_auto_accepts_future_measured_state(); test_receiver_auto_requires_fresh_ptp_and_real_timeline(); + test_internal_sync_recorder_captures_cause_and_bounded_history(); test_all_lab_compatibility_modes(); test_labels_are_stable_for_ui_and_evidence(); std::cout << "smpSynch lab policy tests passed\n";