From 1996a1c82798ee6ac9b50cf1b9fcd1a44451080d Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Thu, 30 Jul 2026 21:14:39 +1200 Subject: [PATCH 1/5] feat(crow_alarm_panel): add raw bit-trace logging toggle switch Captures every clock-sampled DAT bit (post glitch-filter, same bits the frame parser feeds into boundary_buffer_) into a batched 128-bit string, independent of frame decoding, so mis-alignment/framing issues can be diagnosed by hand from the literal bitstream. Co-Authored-By: Claude Sonnet 5 --- .../crow_alarm_panel/crow_alarm_panel.cpp | 20 +++++++++++++++++++ .../crow_alarm_panel/crow_alarm_panel.h | 15 ++++++++++++++ .../crow_alarm_panel/switch/__init__.py | 12 +++++++++++ .../switch/crow_alarm_panel_switch.cpp | 13 ++++++++++++ .../switch/crow_alarm_panel_switch.h | 10 ++++++++++ crow_alarm_panel_test.yaml | 5 +++++ 6 files changed, 75 insertions(+) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index b501e5e..cab78ab 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -140,6 +140,16 @@ void IRAM_ATTR HOT CrowAlarmPanelStore::interrupt(CrowAlarmPanelStore *arg) { // Check for boundary arg->boundary_buffer_ = (uint8_t) ((arg->boundary_buffer_ << 1) | data_bit); + if (arg->bit_trace_enabled_) { + arg->bit_trace_buffer_[arg->bit_trace_len_++] = data_bit ? '1' : '0'; + if (arg->bit_trace_len_ >= BIT_TRACE_BUFFER_BITS) { + memcpy(arg->bit_trace_buffer2_, arg->bit_trace_buffer_, BIT_TRACE_BUFFER_BITS); + arg->bit_trace_buffer2_[BIT_TRACE_BUFFER_BITS] = '\0'; + arg->bit_trace_len_ = 0; + arg->bit_trace_ready_ = true; + } + } + if (arg->inside_) { uint8_t idx = arg->num_bits_ / 8; arg->buffer[idx] = (arg->buffer[idx] >> 1) | ((data_bit ? 1 : 0) << 7); @@ -251,6 +261,16 @@ void CrowAlarmPanel::loop() { this->store_.ack_pending_ = false; } + if (this->store_.bit_trace_ready_) { + char local_bits[CrowAlarmPanelStore::BIT_TRACE_BUFFER_BITS + 1]; + { + InterruptLock lock; + memcpy(local_bits, this->store_.bit_trace_buffer2_, sizeof(local_bits)); + this->store_.bit_trace_ready_ = false; + } + ESP_LOGI(TAG, "Raw bit trace: %s", local_bits); + } + if (this->store_.data_length) { if (this->store_.data_length < 2) { ESP_LOGW(TAG, "Discarding short frame (%d bytes)", this->store_.data_length); diff --git a/components/crow_alarm_panel/crow_alarm_panel.h b/components/crow_alarm_panel/crow_alarm_panel.h index ea417f4..a6e1a4d 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.h +++ b/components/crow_alarm_panel/crow_alarm_panel.h @@ -165,6 +165,18 @@ class CrowAlarmPanelStore { // The controller then keeps the keypad stuck in "output-select mode", rejecting all // subsequent KEY_OUTPUT attempts with KEYPAD_COMMAND [07]. static const uint32_t OUTPUT_SELECT_ENTER_DELAY_MS = 60; + + // Raw bit trace (diagnostic): batches every clock-sampled DAT bit that reaches the + // frame boundary-search logic (i.e. after glitch filtering, same bits that feed + // boundary_buffer_) into a fixed-size string and hands it to loop() once full. + // Independent of frame decoding, so mis-alignment/framing issues can be diagnosed + // by hand from the literal bitstream instead of the already-decoded bytes. + static const uint16_t BIT_TRACE_BUFFER_BITS = 128; + bool bit_trace_enabled_{false}; + char bit_trace_buffer_[BIT_TRACE_BUFFER_BITS + 1]{}; + char bit_trace_buffer2_[BIT_TRACE_BUFFER_BITS + 1]{}; + uint16_t bit_trace_len_{0}; + volatile bool bit_trace_ready_{false}; }; struct CrowAlarmPanelZone { @@ -252,6 +264,9 @@ class CrowAlarmPanel : public Component { // be toggled at runtime without recompiling with a higher logger level. void set_raw_frame_logging_enabled(bool enabled) { this->raw_frame_logging_enabled_ = enabled; } + // Enables the ISR-side raw bit trace (see CrowAlarmPanelStore::bit_trace_enabled_). + void set_raw_bit_trace_enabled(bool enabled) { this->store_.bit_trace_enabled_ = enabled; } + protected: CrowAlarmPanelKeypad find_keypad_(uint8_t address); bool is_bus_idle_(); diff --git a/components/crow_alarm_panel/switch/__init__.py b/components/crow_alarm_panel/switch/__init__.py index dc11c4f..3de461a 100644 --- a/components/crow_alarm_panel/switch/__init__.py +++ b/components/crow_alarm_panel/switch/__init__.py @@ -14,6 +14,7 @@ CONF_BYPASS = "bypass" CONF_LOG_RAW_FRAMES = "log_raw_frames" +CONF_LOG_RAW_BITS = "log_raw_bits" CrowAlarmPanelSwitch = crow_alarm_panel_ns.class_( "CrowAlarmPanelSwitch", switch.Switch, cg.Component @@ -24,6 +25,9 @@ CrowAlarmPanelRawLogSwitch = crow_alarm_panel_ns.class_( "CrowAlarmPanelRawLogSwitch", CrowAlarmPanelSwitch ) +CrowAlarmPanelRawBitTraceSwitch = crow_alarm_panel_ns.class_( + "CrowAlarmPanelRawBitTraceSwitch", CrowAlarmPanelSwitch +) CROW_SWITCH_SCHEMA = switch.switch_schema(CrowAlarmPanelSwitch).extend( @@ -53,6 +57,12 @@ cv.Optional(CONF_ICON, default="mdi:text-box-search-outline"): cv.icon, } ), + CONF_LOG_RAW_BITS: CROW_SWITCH_SCHEMA.extend( + { + cv.GenerateID(): cv.declare_id(CrowAlarmPanelRawBitTraceSwitch), + cv.Optional(CONF_ICON, default="mdi:pulse"): cv.icon, + } + ), } ) @@ -71,6 +81,8 @@ async def to_code(config): cg.add(paren.register_zone_bypass_switch(var, config[CONF_ZONE])) elif type == CONF_LOG_RAW_FRAMES: cg.add(var.set_crow_alarm_panel_parent(paren)) + elif type == CONF_LOG_RAW_BITS: + cg.add(var.set_crow_alarm_panel_parent(paren)) await switch.register_switch(var, config) await cg.register_component(var, config) diff --git a/components/crow_alarm_panel/switch/crow_alarm_panel_switch.cpp b/components/crow_alarm_panel/switch/crow_alarm_panel_switch.cpp index 21c9440..66192de 100644 --- a/components/crow_alarm_panel/switch/crow_alarm_panel_switch.cpp +++ b/components/crow_alarm_panel/switch/crow_alarm_panel_switch.cpp @@ -37,5 +37,18 @@ void CrowAlarmPanelRawLogSwitch::dump_config() { LOG_SWITCH("", "Crow Alarm Panel Raw Log Switch", this); } +void CrowAlarmPanelRawBitTraceSwitch::write_state(bool state) { + if (this->parent_ == nullptr) { + ESP_LOGE(TAG, "Parent not set, ignoring raw bit trace switch command"); + return; + } + this->parent_->set_raw_bit_trace_enabled(state); + this->publish_state(state); +} + +void CrowAlarmPanelRawBitTraceSwitch::dump_config() { + LOG_SWITCH("", "Crow Alarm Panel Raw Bit Trace Switch", this); +} + } // namespace crow_alarm_panel } // namespace esphome diff --git a/components/crow_alarm_panel/switch/crow_alarm_panel_switch.h b/components/crow_alarm_panel/switch/crow_alarm_panel_switch.h index 810a2ff..b766969 100644 --- a/components/crow_alarm_panel/switch/crow_alarm_panel_switch.h +++ b/components/crow_alarm_panel/switch/crow_alarm_panel_switch.h @@ -39,5 +39,15 @@ class CrowAlarmPanelRawLogSwitch : public CrowAlarmPanelSwitch { void write_state(bool state) override; }; +// Pure software toggle: no bus traffic, enables the parent's ISR-side raw bit trace +// (batched DAT bitstream sampled on each accepted clock edge). State isn't restored on +// boot since it's a debug aid, not panel state. +class CrowAlarmPanelRawBitTraceSwitch : public CrowAlarmPanelSwitch { + public: + void dump_config() override; + protected: + void write_state(bool state) override; +}; + } // namespace crow_alarm_panel } // namespace esphome diff --git a/crow_alarm_panel_test.yaml b/crow_alarm_panel_test.yaml index 0cb79b7..a46a06b 100644 --- a/crow_alarm_panel_test.yaml +++ b/crow_alarm_panel_test.yaml @@ -116,3 +116,8 @@ switch: - platform: crow_alarm_panel type: log_raw_frames name: "Raw Frame Logging" + # Toggles ISR-side raw bit trace: batched DAT bitstream (post glitch-filter), logged + # at INFO once a 128-bit buffer fills. Diagnostic aid for framing/glitch issues. + - platform: crow_alarm_panel + type: log_raw_bits + name: "Raw Bit Trace" From 18129d864ca25280103a143ba334e1cd2a37ca41 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 5 Aug 2026 14:45:04 +1200 Subject: [PATCH 2/5] fix(crow_alarm_panel): retry arm/disarm sequence on watchdog timeout Six independent traced sessions (logs-10/35, logs-12/37, logs-42, logs-24/25/26) show a watchdog timeout in CODE_DIGIT_PENDING/ CODE_ENTER_PENDING reliably means the panel's state never changed, with monitor cross-checks confirming no ARMED_STATE broadcast was ever missed. Unlike output-select/zone-bypass, a blind retry here can't undo a change that already landed, so the watchdog now retries the whole sequence (up to ARM_DISARM_MAX_RETRIES=5, covering the worst observed streak) before falling back to the existing abort/restore behavior. Full trace analysis in docs/protocol_trace_2026-08-05_disarm_after_arm.md. --- .../crow_alarm_panel/crow_alarm_panel.cpp | 61 ++- .../crow_alarm_panel/crow_alarm_panel.h | 7 + .../docs/arm_disarm_state_machine.md | 62 +++ ...tocol_trace_2026-08-05_disarm_after_arm.md | 471 ++++++++++++++++++ 4 files changed, 587 insertions(+), 14 deletions(-) create mode 100644 components/crow_alarm_panel/docs/protocol_trace_2026-08-05_disarm_after_arm.md diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index cab78ab..e678c75 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -852,23 +852,53 @@ void CrowAlarmPanel::loop() { } } - // Arm/disarm watchdog: abort if any non-IDLE state exceeds 1s without progress. + // Arm/disarm watchdog: abort if any non-IDLE state exceeds 1s without progress. See + // ARM_DISARM_MAX_RETRIES in crow_alarm_panel.h for why retrying here (unlike output-select/ + // zone-bypass above) is safe: a timeout reliably means the panel's state did not change. if (this->arm_disarm_state_ != ArmDisarmState::IDLE) { const uint32_t now_ms = millis(); if (now_ms - this->arm_disarm_state_enter_ms_ > 1000) { - ESP_LOGW(TAG, "Arm/disarm: timeout in state %u, aborting", - static_cast(this->arm_disarm_state_)); - this->arm_disarm_state_ = ArmDisarmState::IDLE; - this->arm_disarm_code_digits_.clear(); - this->arm_disarm_code_idx_ = 0; - // CrowAlarmControlPanel::control() optimistically publishes ACP_STATE_ARMING/DISARMING - // before this sequence resolves. On abort no ARMED_STATE broadcast is coming to correct - // that, so without this the entity would be stuck in the transitional state forever, - // rejecting both future arm and disarm calls (ESPHome's alarm_control_panel validate_() - // requires DISARMED to arm and an armed/pending state to disarm). Restore it to the last - // state the controller itself actually confirmed. - if (this->alarm_control_panel_ != nullptr) { - this->alarm_control_panel_->publish_state(this->last_confirmed_acp_state_); + if (this->arm_disarm_retry_count_ < ARM_DISARM_MAX_RETRIES) { + this->arm_disarm_retry_count_++; + ESP_LOGW(TAG, "Arm/disarm: timeout in state %u, retrying (%u/%u)", + static_cast(this->arm_disarm_state_), this->arm_disarm_retry_count_, + ARM_DISARM_MAX_RETRIES); + switch (this->arm_disarm_state_) { + case ArmDisarmState::ARM_AWAY_PENDING: + this->keypress(KEY_ARM); + break; + case ArmDisarmState::ARM_STAY_PENDING: + this->keypress(KEY_STAY); + break; + case ArmDisarmState::CODE_DIGIT_PENDING: + case ArmDisarmState::CODE_ENTER_PENDING: + // Restart the whole code+terminal-key sequence from scratch, exactly like a fresh + // manual retry (proven reliable across every session in arm_disarm_state_machine.md). + this->arm_disarm_code_idx_ = 1; + this->arm_disarm_state_ = ArmDisarmState::CODE_DIGIT_PENDING; + this->arm_disarm_digit_ack_byte_set_ = false; + this->keypress(this->arm_disarm_code_digits_[0]); + break; + default: + break; + } + this->arm_disarm_state_enter_ms_ = millis(); + } else { + ESP_LOGW(TAG, "Arm/disarm: timeout in state %u, aborting after %u retries", + static_cast(this->arm_disarm_state_), this->arm_disarm_retry_count_); + this->arm_disarm_state_ = ArmDisarmState::IDLE; + this->arm_disarm_code_digits_.clear(); + this->arm_disarm_code_idx_ = 0; + this->arm_disarm_retry_count_ = 0; + // CrowAlarmControlPanel::control() optimistically publishes ACP_STATE_ARMING/DISARMING + // before this sequence resolves. On abort no ARMED_STATE broadcast is coming to correct + // that, so without this the entity would be stuck in the transitional state forever, + // rejecting both future arm and disarm calls (ESPHome's alarm_control_panel validate_() + // requires DISARMED to arm and an armed/pending state to disarm). Restore it to the last + // state the controller itself actually confirmed. + if (this->alarm_control_panel_ != nullptr) { + this->alarm_control_panel_->publish_state(this->last_confirmed_acp_state_); + } } } } @@ -912,6 +942,7 @@ void CrowAlarmPanel::start_code_sequence_(const std::string &code, uint8_t termi this->arm_disarm_code_idx_ = 1; this->arm_disarm_state_ = ArmDisarmState::CODE_DIGIT_PENDING; this->arm_disarm_state_enter_ms_ = millis(); + this->arm_disarm_retry_count_ = 0; this->arm_disarm_digit_ack_byte_set_ = false; this->keypress(this->arm_disarm_code_digits_[0]); } @@ -932,6 +963,7 @@ void CrowAlarmPanel::arm_away(const std::string &code) { ESP_LOGI(TAG, "Arm away"); this->arm_disarm_state_ = ArmDisarmState::ARM_AWAY_PENDING; this->arm_disarm_state_enter_ms_ = millis(); + this->arm_disarm_retry_count_ = 0; this->keypress(KEY_ARM); } } @@ -952,6 +984,7 @@ void CrowAlarmPanel::arm_stay(const std::string &code) { ESP_LOGI(TAG, "Arm stay"); this->arm_disarm_state_ = ArmDisarmState::ARM_STAY_PENDING; this->arm_disarm_state_enter_ms_ = millis(); + this->arm_disarm_retry_count_ = 0; this->keypress(KEY_STAY); } } diff --git a/components/crow_alarm_panel/crow_alarm_panel.h b/components/crow_alarm_panel/crow_alarm_panel.h index a6e1a4d..342c583 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.h +++ b/components/crow_alarm_panel/crow_alarm_panel.h @@ -305,6 +305,13 @@ class CrowAlarmPanel : public Component { std::vector arm_disarm_code_digits_; // code digits consumed one per KEYPAD_COMMAND uint8_t arm_disarm_code_idx_{0}; uint8_t arm_disarm_terminal_key_{KEY_ENTER}; // KEY_ENTER (disarm), KEY_ARM or KEY_STAY (arm-with-code) + // A watchdog timeout here reliably means the panel's state did not change (see + // docs/arm_disarm_state_machine.md — multiple sessions with an independent monitor capture + // confirm no ARMED_STATE broadcast occurred around the timeout), so unlike output-select/ + // zone-bypass a blind retry can't undo a change that already landed. 5 covers the worst + // consecutive-failure streak observed so far (logs-24, logs-42: 5 failures before success). + static const uint8_t ARM_DISARM_MAX_RETRIES = 5; + uint8_t arm_disarm_retry_count_{0}; // "Digit accepted" display_code (KEYPAD_COMMAND byte[1]) learned from the first digit's // response each sequence. Physical keypad types disagree on this value (0x01 is common, // but address 0x05 has been observed sending 0x07 for the same "more digits expected" diff --git a/components/crow_alarm_panel/docs/arm_disarm_state_machine.md b/components/crow_alarm_panel/docs/arm_disarm_state_machine.md index 8ad6d8f..8fe8bd8 100644 --- a/components/crow_alarm_panel/docs/arm_disarm_state_machine.md +++ b/components/crow_alarm_panel/docs/arm_disarm_state_machine.md @@ -359,6 +359,68 @@ Compiles and passes `esphome config`/`esphome compile` against `crow_alarm_panel **Not yet established:** why the controller sometimes fails to act on a correctly-received ENTER. No raw CLK/DAT bit capture or controller-side diagnostic exists to distinguish an internal controller timing/busy condition from something else. Needs further investigation if this failure rate proves disruptive in practice; no code change is proposed here since `CODE_ENTER_PENDING` already handles this correctly (resolves via `ARMED_STATE`/watchdog, no byte[1] trust) — this entry is about confirming *why* it fails, not changing *how* it's handled. +## Two more corroborating sessions, gap-timing candidate raised then undermined (2026-08-05) + +**Source:** `protocol_trace_2026-08-05_disarm_after_arm.md` (full detail) — `esphome-aap-keypad-monitor-logs-41/42/43.txt`, `esphome-aap-alarm-interface-logs-22.txt`. + +Two more sessions show the identical `CODE_ENTER_PENDING` silence signature from the 2026-07-25 entry above (clean terminal-key ack, then genuine bus silence until the 1s watchdog aborts), bringing the running total to at least 7 independent sessions. One session (paired monitor+interface capture, logs-43/22) raised a candidate explanation — the single failure out of 8 cycles had the shortest armed→disarm gap (7.4s) of the session, while all 7 successes had gaps ≥9.6s — but a second session (logs-42, monitor-only) contradicts it: 5 of 6 failures there occurred at gaps of 21–44s, far longer than the 7.4s failure elsewhere. Net conclusion: gap length alone doesn't explain the failure rate; something session-level (overall bus conditions, an unidentified controller state) more likely dominates. Still not established. No code change proposed. + +## Gap-timing lead conclusively dead; monitor-side RX corruption complicates the 2026-07-12 ACK theory (2026-08-05, logs-44/23) + +**Source:** `protocol_trace_2026-08-05_disarm_after_arm.md` (full detail) — `esphome-aap-keypad-monitor-logs-44.txt`, `esphome-aap-alarm-interface-logs-23.txt`. + +A third session in the same investigation kills the gap-timing lead outright: cycle 3's disarm failed twice (`CODE_ENTER_PENDING` silence, same signature as always) at 6.4s and 9.5s armed→disarm gaps, then succeeded on a third attempt at 13.8s — but cycle 5 in the *same session* succeeded with a 5.5s gap, shorter than either of cycle 3's failures. Gap length is not the mechanism, in either direction. + +Separately, cross-checking cycle 3's second failed attempt against the passive monitor's independently bit-decoded traffic (the monitor still has no working DEBUG output — see the stale-firmware note above, still true as of this session) turned up a burst of `Unknown 0xFF`/`0xFE` RX-corruption frames on the **monitor** at `11:23:47.330–47.741`, in a window the interface decoded with zero corruption. This is the reverse pairing from the 2026-07-12 entry above (there, the ACK-driving interface saw the garbage and the passive monitor was clean) — and since the monitor never drives the hardware ACK, this instance can't be explained by that entry's "our own ACK-release desyncs our own RX" mechanism. Whether this is the same underlying phenomenon or a distinct one producing the same garbled byte values is open; needs `ESP_LOGV` on both devices simultaneously to compare at the raw-frame level. Not yet established. No code change proposed. + +## Five consecutive disarm failures; failure mode 3 (bus collision) independently reproduced, and a new variant found (2026-08-05, logs-45/24) + +**Source:** `protocol_trace_2026-08-05_disarm_after_arm.md` (full detail) — `esphome-aap-keypad-monitor-logs-45.txt`, `esphome-aap-alarm-interface-logs-24.txt`. + +A fourth session in the same investigation, and the worst failure streak seen yet: 5 of 6 disarm attempts fail in a row before the 6th succeeds. This session also kills the "armed via a physical keypad" lead from the entry above — this failure cycle was armed via the ESPHome interface's own ARM key, not a physical keypad, contradicting the pattern every prior failure shared. + +Cross-checking each failed attempt against the passive monitor's independent bit-decode (again no working DEBUG output there) turns up a mix of causes rather than one repeated mechanism: + +- **Attempt 1** independently reproduces this document's "Terminal key lost in bus collision" failure mode (mode 3, above) almost exactly — the monitor decodes a garbled `[14.a1.05.11]` frame at the terminal-key send, byte-for-byte the same pattern originally described from the interface's own logs alone. This is the first time it's been confirmed via a passive monitor's raw bits in a fresh session. +- **Attempt 4** shows a new variant of the same collision class landing on a mid-sequence digit instead of ENTER: the monitor decodes an abnormally long, malformed `OUTPUT_STATE`-typed frame (`data=000406`) spanning several seconds right where digit "6"'s `KEYPRESS` should have been, with `04`/`06` fragments consistent with two keypresses merging. So this collision mechanism isn't ENTER-specific. +- **Attempts 2 and 5** are the ordinary `CODE_ENTER_PENDING` silence signature from the 2026-07-25 entry (clean `0x07` ack, then genuine silence). +- **Attempt 3** is the ordinary "timeout in digit state" failure mode (mode 1, above) — no ack at all for the first digit. + +**Inference (low confidence, one session):** a "bad" session appears to raise the odds of several already-catalogued failure mechanisms together (two collisions, two silences, one digit-timeout, all in the same ~30s span) rather than introducing one new mechanism. Combined with logs-42 (5/6 failed) and the mostly-clean logs-22/23 (1/8, 2/6 failed), sessions seem to vary between "good" and "bad" for reasons still not isolated. Not yet established. No code change proposed. + +## Bus-collision mode reproduced a third time (now on the first digit); corruption pairing flips back (2026-08-05, logs-46/25) + +**Source:** `protocol_trace_2026-08-05_disarm_after_arm.md` (full detail) — `esphome-aap-keypad-monitor-logs-46.txt`, `esphome-aap-alarm-interface-logs-25.txt`. + +A fifth session, "medium" severity (3 of 9 disarm attempts failed). One failure reproduces failure mode 3 (bus collision) again, this time on the very first digit of the sequence — the monitor's independent decode shows a bare `Unknown 0xFF` frame in place of the first `KEYPRESS`, rather than a clean ack ever arriving. Combined with the previous session's ENTER and mid-digit collisions, this mechanism now appears able to hit any outgoing keypress in a sequence, not a specific one. The other two failures in this session match already-established signatures (digit-silence, then terminal-key `0x07` silence) with no new mechanism, following (but likely not caused by, since polling had been stable for 4m45s beforehand) a "no ping for 60s" registration-storm. + +Separately, this session also produced a malformed 7-byte `ARMED_STATE` (`[11.83.01.46.81.00.80.11]`) decoded by the **interface**, with the monitor's simultaneous independent decode showing nothing of the sort — clean ordinary traffic. This is the *original* 2026-07-12 pairing (ACK-driving interface corrupted, passive monitor clean), the reverse of last session's logs-44/23 pairing (monitor corrupted, interface clean). Both directions have now been observed, in different sessions — at least consistent with general bus noise affecting whichever receiver happens to be unlucky, rather than a mechanism deterministically tied to whichever device drives the hardware ACK, though not conclusive either way. + +Failure rate across sessions so far (1/8, 2/6, 3/9, 5/6, 5/6) looks more like a continuum than a "good session"/"bad session" binary — argues for something with continuously-varying severity (e.g. general bus contention level) rather than a single on/off trigger. Not yet established. No code change proposed. + +## High failure rate with zero collisions; long-gap cycles reproduce the same two-failures-then-success shape twice (2026-08-05, logs-47/26) + +**Source:** `protocol_trace_2026-08-05_disarm_after_arm.md` (full detail) — `esphome-aap-keypad-monitor-logs-47.txt`, `esphome-aap-alarm-interface-logs-26.txt`. + +A sixth session, 5 of 9 disarm attempts failed (~56%) — extending the failure-rate continuum (now 1/8, 2/6, 3/9, 5/9, 5/6, 5/6) with no two sessions landing at the same rate. Unlike the previous session, cross-checking every "no ack" failure against the monitor here shows **zero** collision artifacts — every failure is genuine bus silence, meaning a high failure rate doesn't require the collision mechanism to be active. One failure's ack arrived but took 825ms (vs. the usual ~100–200ms) before the watchdog still ran out — the first time a slow-but-present ack has been noted rather than one that's prompt or entirely absent. + +This session's ~5-minute-gap cycle reproduces logs-46/25's exact "digit-silence fail, terminal-key-silence fail, success" shape a second time — but with completely healthy `KEYPAD_PING` polling throughout the gap, no registration/ping-loss event at all. This weakens the tentative "registration storm precedes failure" link raised last session, while making the "two failures then success on a long-gap cycle" shape itself a small but now-twice-reproduced pattern worth targeting deliberately in a future capture. + +Not yet established. No code change proposed. + +## Automatic retry added for CODE_DIGIT_PENDING/CODE_ENTER_PENDING and ARM_AWAY_PENDING/ARM_STAY_PENDING (2026-08-05) + +**Rationale:** six independent sessions (logs-10/35, logs-12/37, logs-42, logs-24/25/26) now show, with monitor cross-checks in several of them, that a watchdog timeout in these states reliably means the panel's state did not change — no `ARMED_STATE` broadcast is ever missed by the passive monitor either. That's a materially different situation from the output-select and zone-bypass watchdogs above, where a retry could double-fire an output or undo a bypass toggle that actually landed. Here a blind retry can't undo something that already happened, because nothing did. The worst observed streak needing manual retries before success was 5 consecutive failures (logs-24, logs-42). + +**Fix applied:** the arm/disarm watchdog (`crow_alarm_panel.cpp`, "Arm/disarm watchdog") now retries up to `ARM_DISARM_MAX_RETRIES` (5, `crow_alarm_panel.h`) times before falling back to the existing abort behavior (clear state, restore `last_confirmed_acp_state_`). A new `arm_disarm_retry_count_` counter, reset to 0 at the start of every fresh `arm_away()`/`arm_stay()`/`disarm()` call (via `start_code_sequence_()` and the no-code branches), tracks this. On retry: + +- `ARM_AWAY_PENDING`/`ARM_STAY_PENDING` just resend `KEY_ARM`/`KEY_STAY`. +- `CODE_DIGIT_PENDING`/`CODE_ENTER_PENDING` restart the whole code+terminal-key sequence from the first digit (`arm_disarm_code_idx_ = 1`, state back to `CODE_DIGIT_PENDING`, digit-ack baseline re-learned) — exactly what every manual retry across every session in this document already did, and which has a 100% eventual success rate in the traces gathered so far. + +Because `arm_away()`/`arm_stay()`/`disarm()` all reject a new call while `arm_disarm_state_ != IDLE`, a user's own repeated manual retries (as seen throughout this document) now become no-ops while an automatic retry is already in flight — the entity resolves on its own instead of needing the user to notice the failure and try again by hand. + +Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. **Not yet validated on real hardware** — needs a fresh capture (ideally reproducing a multi-failure streak like logs-24/42) to confirm the automatic retries actually land and that no new interaction appears between rapid consecutive retries and the controller (e.g. the same kind of ACK-timing sensitivity documented for output-select's `OUTPUT_SELECT_ENTER_DELAY_MS`). + ## Notes - ARM/STAY/DISARM sequences are simpler than OUTPUT because there's no ACK handshake diff --git a/components/crow_alarm_panel/docs/protocol_trace_2026-08-05_disarm_after_arm.md b/components/crow_alarm_panel/docs/protocol_trace_2026-08-05_disarm_after_arm.md new file mode 100644 index 0000000..d23ad7c --- /dev/null +++ b/components/crow_alarm_panel/docs/protocol_trace_2026-08-05_disarm_after_arm.md @@ -0,0 +1,471 @@ +# AAP protocol findings from the 2026-08-05 disarm-after-arm traces + +Source traces: + +- `../../../traces/esphome-aap-keypad-monitor-logs-41.txt` (passive monitor) +- `../../../traces/esphome-aap-keypad-monitor-logs-42.txt` (passive monitor) +- `../../../traces/esphome-aap-keypad-monitor-logs-43.txt` (passive monitor) +- `../../../traces/esphome-aap-alarm-interface-logs-22.txt` (active interface, paired with logs-43) +- `../../../traces/esphome-aap-keypad-monitor-logs-44.txt` (passive monitor, paired with logs-23) +- `../../../traces/esphome-aap-alarm-interface-logs-23.txt` (active interface, paired with logs-44) +- `../../../traces/esphome-aap-keypad-monitor-logs-45.txt` (passive monitor, paired with logs-24) +- `../../../traces/esphome-aap-alarm-interface-logs-24.txt` (active interface, paired with logs-45) +- `../../../traces/esphome-aap-keypad-monitor-logs-46.txt` (passive monitor, paired with logs-25) +- `../../../traces/esphome-aap-alarm-interface-logs-25.txt` (active interface, paired with logs-46) +- `../../../traces/esphome-aap-keypad-monitor-logs-47.txt` (passive monitor, paired with logs-26) +- `../../../traces/esphome-aap-alarm-interface-logs-26.txt` (active interface, paired with logs-47) + +Related: `arm_disarm_state_machine.md` — this note adds two more corroborating sessions to +that document's "`CODE_ENTER_PENDING` silence confirmed genuine" investigation (2026-07-25) +and introduces a candidate (but not confirmed) timing variable. + +## Decode method + +`esphome-aap-keypad-monitor.yaml` sets `logs: crow_alarm_panel: DEBUG`, but logs-41, -42, and +-43 (all captured from the passive monitor device) contain **zero** `[D]`/`[W]` lines — only +the `[I]` boot banner and `ESP_LOGI`-level `Raw bit trace` lines. The monitor binary in these +sessions was compiled 2026-08-02, three days before the interface binary (2026-08-05) used for +logs-22; the per-tag DEBUG override apparently isn't reaching the monitor's compiled/running +log level. This means logs-41/42/43 had to be decoded independently of the device's own +frame parser. + +Frames were recovered by simulating `CrowAlarmPanelStore::interrupt()`'s boundary-detection +state machine (`boundary_buffer_`/`inside_`/`num_bits_`, `crow_alarm_panel.cpp`) directly +against the concatenated `Raw bit trace` bit strings — an 8-bit sliding window compared to +`0x7E` marks frame start/end, exactly as the ISR does. Because the bit-trace capture and the +real frame decoder are gated by the same `is_transmitting_`/glitch-filter logic in the ISR, the +recorded bit stream is bit-for-bit what the onboard parser would have seen, including the +device's own outgoing keypresses. The reconstructed frames matched `protocol_wire_format.md` +cleanly across ~140+ frames per file with no ambiguous decodes. + +logs-43 (monitor) and logs-22 (interface) were captured concurrently from the same bus and are +cross-referenced below; logs-22 has full `[D]`/`[W]` output, so no manual bit decoding was +needed for that half. Same story for logs-44/logs-23 (still 2026-08-02-compiled monitor +firmware, still no per-tag DEBUG output there): logs-44 was decoded with the same bit-level +simulator where needed to cross-check specific windows against logs-23. + +## Session: logs-41 (clean baseline) + +One arm/disarm cycle via the ESPHome virtual keypad (`0x05`), no anomalies: + +``` +09:30:29.172 [ESPHome Keypad] Key ARM pressed +09:30:29.289 ARMED_STATE: Arming +09:30:57.729 ARMED_STATE: Armed Away +09:31:08.405–08.810 [ESPHome Keypad] digits 4-2-8-6, ENTER (disarm code) +09:31:08.925 ARMED_STATE: Disarmed +09:31:09.024 [ESPHome Keypad] Command display=0x15 ("return to normal") +``` + +Single attempt, no retries — this is the reference shape a clean cycle should have. + +## Session: logs-42 (armed via IP Keypad, 5 of 6 disarms fail) + +Armed at `09:31:35.147` via the **IP Keypad (`0x07`)** entering code `4-2-8-6` + ENTER directly +(no ARM key) — the same "arm with code" pattern the physical keypads use, not the ESPHome +interface's own `ARM_AWAY_PENDING` path. `ARMED_STATE: Armed Away` confirmed at `09:32:03.712`. + +Six subsequent disarm attempts from the ESPHome keypad (`0x05`), only the last succeeds: + +| # | Start (gap after Armed Away) | Outcome | +|---|---|---| +| 1 | 09:32:25.013 (+21.3s) | Only 3 of 4 digits sent (4-2-8), then goes silent — no ENTER, no error | +| 2 | 09:32:31.221 (+27.5s) | Digit "4" sent+acked, then a corrupted/garbage frame (<2 bytes) appears — aborts | +| 3 | 09:32:34.498 (+30.8s) | Full 4-2-8-6-ENTER sent; controller replies `display=0x07` twice, no `ARMED_STATE` at all | +| 4 | 09:32:39.516 (+35.8s) | Digit "4" sent+acked, then another corrupted/garbage frame — aborts | +| 5 | 09:32:43.611 (+39.9s) | Full sequence again; `display=0x07` twice, still no `ARMED_STATE` | +| 6 | 09:32:47.810 (+44.1s) | Full sequence; `ARMED_STATE: Disarmed` at 09:32:48.425 — **success** | + +Decoded directly from raw bits (representative frame from attempt 3): + +``` +14.05.07.00.40.01.80 [ESPHome Keypad] Command, display=0x07, armed=1 +``` + +## Session: logs-43 (monitor) / logs-22 (interface) — 1 of 8 disarms fails + +Full session with proper `[D]`/`[W]` logging (from logs-22). Eight arm/disarm cycles; every +arm alternates between the ESPHome interface's own `ARM_AWAY_PENDING` path ("Arm away" / +"Arm/stay: CMD received, sequence complete") and the IP Keypad entering code+ENTER directly. +Only cycle 5's disarm fails: + +``` +10:21:15.216 [IP Keypad] Key ENTER pressed (arm-with-code 4-2-8-6) +10:21:43.544 [Controller] Armed Away +10:21:50.829 Disarm (HA-triggered) +10:21:50.913–51.334 Code sequence: digits 4-2-8-6 sent, all acked display=0x01 (normal) +10:21:51.334 Code sequence: sending terminal key 0x11 (ENTER) +10:21:51.538 [ESPHome Keypad] Command display=0x07 ("code accepted, alarm-pending") + Code sequence: CMD 0x07 after terminal key, awaiting ARMED_STATE confirmation +10:21:52.357 Arm/disarm: timeout in state 4, aborting <- no ARMED_STATE ever arrived +10:21:52.468 alarm_control_panel restored to ARMED_AWAY (last-confirmed-state fix, 2026-07-22) +10:21:56.156 Disarm retried +10:21:56.654 Code sequence: sending terminal key 0x11 +10:21:56.776 [Controller] Disarmed — success, ~120ms turnaround +``` + +Armed→disarm-attempt gap for all 8 cycles in this session: + +| Cycle | Preceding arm method | Gap | Outcome | +|---|---|---|---| +| 1 | ESPHome ARM key | 9.6s | success | +| 2 | IP Keypad code+ENTER | 11.1s | success | +| 3 | ESPHome ARM key | 10.2s | success | +| 4 | ESPHome ARM key | 10.0s | success | +| **5** | **IP Keypad code+ENTER** | **7.4s** | **fail** | +| 6 | ESPHome ARM key | 10.4s | success | +| 7 | ESPHome ARM key | 37.8s | success | + +## Session: logs-44 (monitor) / logs-23 (interface) — cycle 3 fails twice, then succeeds + +Five arm/disarm cycles, arming alternating between the ESPHome interface's own ARM key and the +IP Keypad's direct code+ENTER, same as the previous session. Cycle 3's disarm fails twice in a +row before a third attempt succeeds: + +``` +11:23:37.412 [Controller] Armed Away (armed via IP Keypad code+ENTER) +11:23:43.786 Disarm (attempt 1) +11:23:44.491 Code sequence: CMD 0x07 after terminal key, awaiting ARMED_STATE confirmation +11:23:45.314 Arm/disarm: timeout in state 4, aborting +11:23:46.947 Disarm (attempt 2) +11:23:47.669 Code sequence: CMD 0x07 after terminal key, awaiting ARMED_STATE confirmation +11:23:48.490 Arm/disarm: timeout in state 4, aborting +11:23:51.166 Disarm (attempt 3) +11:23:51.851 [Controller] Disarmed — success +``` + +Armed→disarm-attempt gap for all cycles in this session: + +| Cycle | Armed via | Gap | Outcome | +|---|---|---|---| +| 1 | IP Keypad code+ENTER | 6.8s | success | +| 2 | ESPHome ARM key | 16.5s | success | +| 3, attempt 1 | IP Keypad code+ENTER | 6.4s | fail | +| 3, attempt 2 | same | 9.5s | fail | +| 3, attempt 3 | same | 13.8s | success | +| 4 | ESPHome ARM key | 18.9s | success | +| 5 | IP Keypad code+ENTER | **5.5s** | success | + +Cycle 5's 5.5s gap — shorter than either of cycle 3's failing attempts — disarmed cleanly. This +directly contradicts the gap-timing lead raised from the previous session (see Findings below). + +**Independent monitor decode of cycle 3, attempt 2:** logs-23 (interface) decodes this window +completely cleanly — normal `14.05.01...` digit acks, `14.05.07` after ENTER, then +`[ESPHome Keypad] In normal state`, no corruption. But logs-44 (monitor), decoded independently +via the same bit-level simulator, shows a burst of `Unknown 0xFF`/`0xFE` garbage frames at +`11:23:47.330–47.741` — right after the digit-8 ack, in the same window the interface decoded +perfectly. This is the **opposite** of `arm_disarm_state_machine.md`'s 2026-07-12 finding, where +the ACK-driving interface saw the garbage and the passive monitor (which never drives the +hardware ACK) decoded clean. Here the passive monitor is the one garbling while the ACK-driving +interface is clean — this specific instance can't be explained by "our own ACK-release desyncs +our own RX," since the monitor never drives that ACK at all. + +## Session: logs-45 (monitor) / logs-24 (interface) — five consecutive disarm failures + +Armed at `12:53:58.226` via the ESPHome interface's own ARM key. Six subsequent disarm +attempts, only the sixth succeeds: + +| # | Gap from arm | Outcome | Mechanism (per interface `[D]` log, cross-checked against logs-45) | +| --- | --- | --- | --- | +| 1 | 44.5s | fail | Bus collision — see below | +| 2 | 51.3s | fail | Clean `0x07`-after-terminal-key silence (established signature) | +| 3 | 57.3s | fail | No digit ack at all — failure mode 1 ("timeout in digit state") | +| 4 | 60.3s | fail | Bus collision, new variant — see below | +| 5 | 64.7s | fail | Clean `0x07`-after-terminal-key silence (established signature) | +| 6 | 70.9s | success | Clean throughout | + +Two further cycles later in the same session (9.6s and 10.8s gaps) both succeed cleanly — +consistent with the gap-timing lead already being dead (see Findings below). + +**Attempt 1 — reproduces the documented `[14.A1.05.11]` collision:** the interface logs +`Code sequence: CMD 0x01 after terminal key, awaiting ARMED_STATE confirmation` (an ordinary- +looking `0x01`, not the usual `0x07`). Independently decoding logs-45's raw bits for this exact +window turns up: + +```text +[12:54:43.328] type=0x14 KEYPAD_COMMAND data=a10511 +``` + +This is a byte-for-byte match for the `[14.A1.05.11]` garbled frame already documented in +`arm_disarm_state_machine.md`'s "Terminal key lost in bus collision" failure mode: the +controller's own `0x14` type byte wins bus arbitration over ESPHome's simultaneous +`A1.05.11` (KEYPRESS ENTER) transmission, so the real ENTER never reaches the controller. This +is the first time this exact collision signature has been independently reproduced and +confirmed via a passive monitor's raw bits in a fresh session — previously it was inferred from +the interface's own logs alone. + +**Attempt 4 — a new collision variant, hitting a digit instead of the terminal key:** the +interface logs digits 4/2/8 acked normally, then digit "6" sent with no further ack before the +1s digit-state timeout. logs-45's independent decode shows why: instead of a clean +`KEYPRESS [a1.05.06]`, the bus produces an abnormally long, malformed frame: + +```text +[12:54:58.995-12:55:03.009] type=0x50 OUTPUT_STATE data=000406 +``` + +(`OUTPUT_STATE` is normally 1 payload byte; this one runs ~4 seconds and contains `04`/`06` +fragments consistent with the digit-4 and digit-6 keypresses being merged/garbled together). +Same collision class as attempt 1, but landing on a mid-sequence digit rather than the terminal +key — the first evidence that this collision mechanism isn't specific to ENTER. + +## Session: logs-46 (monitor) / logs-25 (interface) — longer session, 3 of 9 disarms fail + +Six arm/disarm cycles, 9 total disarm attempts, 3 failures — a "medium" session between the +extremes of logs-22 (1/8) and logs-24 (5/6). Two failures reproduce already-established +signatures; the third extends the bus-collision finding from the previous session. + +| Cycle/attempt | Gap from arm | Outcome | Mechanism | +| --- | --- | --- | --- | +| 1 | 26.1s | success | clean | +| 2 | 26.1s | success | clean | +| 3 | 82.8s | success | clean | +| 4 | 66.7s | success | clean | +| 5, attempt 1 | 30.6s | fail | bus collision on the *first* digit — see below | +| 5, attempt 2 | 34.4s | success | clean | +| 6, attempt 1 | 285.8s | fail | genuine digit-ack silence (mode 1) | +| 6, attempt 2 | 288.7s | fail | genuine `0x07`-after-terminal-key silence (established) | +| 6, attempt 3 | 292.0s | success | clean | + +**Cycle 5, attempt 1 — collision hits the first digit:** the interface logs `Code sequence: 4 +digits, terminal key 0x11` then times out in `CODE_DIGIT_PENDING` with no ack ever logged for +the first digit. logs-46's independent decode shows why: right at that moment the bus produces +a bare `Unknown 0xFF` garbage frame instead of a clean `KEYPRESS [a1.05.04]`. This is the same +collision class documented in `arm_disarm_state_machine.md` (failure mode 3) and reproduced last +session on ENTER and a mid-sequence digit — now confirmed hitting the very first digit too. Any +keypress in the sequence appears equally vulnerable. + +**Cycle 6's two failures follow an unusually long idle-armed period.** Between cycle 6 arming +(`13:40:19.202`) and the first disarm attempt (`13:46:12.485`) there's a ~5m50s gap. During it, +the interface loses ping contact with the controller and re-registers repeatedly +(`13:41:25.876`–`13:41:27.209`, "No ping for 60 s, re-sending registration announce" ×9) — each +re-registration triggers a fresh `ARMED_STATE` re-broadcast per the documented registration +handshake, explaining a run of repeated `Armed Away` lines in that window. However, `KEYPAD_PING` +resumes a normal, steady 15s cadence immediately after (confirmed in the log from `13:41:27` +through `13:46:10`) — polling had been stable for 4m45s before the actual failures, so the +registration storm is at most a weak/coincidental precursor, not clearly causal. Both failures +match already-established signatures (mode 1 digit-silence, then the standard `0x07`-after- +terminal-key silence) — no new mechanism. The 285–292s gaps are also, by a wide margin, the +longest in this investigation to still show failures, reinforcing that gap length isn't +predictive at any point on the scale from 5.5s to nearly 5 minutes. + +**A malformed `ARMED_STATE` on the interface, invisible to the monitor:** right after cycle 1's +clean disarm, the interface logs `Armed state unknown [11.83.01.46.81.00.80.11 (7)]` — a 7-byte +payload where `ARMED_STATE` is normally 4. logs-46's simultaneous independent decode shows +nothing of the sort at that timestamp — just ordinary `KEYPAD_PING`/`CURRENT_TIME` traffic, no +`ARMED_STATE` at all. This is the interface's own receiver diverging from ground truth while the +monitor stays clean — the **original** 2026-07-12 pairing from `arm_disarm_state_machine.md` +(ACK-driving interface corrupted, passive monitor clean), the reverse of what last session's +logs-44/23 showed. Both pairings have now been observed across different sessions. + +## Session: logs-47 (monitor) / logs-26 (interface) — 5 of 9 disarms fail, no new collisions + +Four arm/disarm cycles, 9 total disarm attempts, 5 failures (~56%) — the highest rate seen +outside the two 5/6 sessions, but this time cross-checking against the monitor turns up no +collision artifacts at all; every failure is genuine bus silence. + +| Cycle/attempt | Gap from arm | Outcome | +| --- | --- | --- | +| 1, attempt 1 | 17.6s | fail — genuine digit-ack silence | +| 1, attempt 2 | 23.2s | fail — genuine `0x07`-after-terminal-key silence | +| 1, attempt 3 | 30.0s | success | +| 2 | 8.5s | success | +| 3, attempt 1 | 13.2s | fail — `0x07`-after-terminal-key silence, ack itself took 825ms to arrive | +| 3, attempt 2 | 17.1s | success | +| 4, attempt 1 | 299.2s | fail — genuine digit-ack silence | +| 4, attempt 2 | 305.1s | fail — genuine `0x07`-after-terminal-key silence | +| 4, attempt 3 | 311.5s | success | + +**The two digit-ack-silence failures (cycle 1/1, cycle 4/1) show no hidden collision this +time.** Cross-checking both against logs-47's independent decode: the keypress goes out +cleanly, gets acked, and then the *next* digit's keypress goes out cleanly too — but its ack +simply never arrives, with no garbled/`Unknown` frame anywhere nearby. Unlike logs-46/25's +first-digit failure (a bare `Unknown 0xFF` in place of the keypress itself), these are genuinely +silent at the ack stage, not TX collisions. The interface's own log can't distinguish the two +cases — cross-checking the monitor is the only way to tell which failure a given "no ack" +timeout actually is. + +**Cycle 3, attempt 1 — an unusually slow (not missing) ack:** the terminal key was sent at +`13:32.844`; the `display=0x07` ack didn't arrive until `13:33.669` — an 825ms turnaround, +several times slower than the typical ~100–200ms seen everywhere else in this investigation — +and the watchdog still ran out shortly after with no `ARMED_STATE` ever following. Not a new +failure signature, but the slow ack itself is a data point that hasn't been called out before. + +**Cycle 4's ~5-minute gap repeats last session's exact shape, without the registration +storm.** Like logs-46/25's cycle 6, this cycle sits armed for a long stretch (299–311s) before +disarming, and fails twice (digit-silence, then terminal-key silence) before succeeding on the +third attempt — but this time `KEYPAD_PING` polling stayed perfectly healthy the whole time, with +no "no ping for 60s" event anywhere in the gap. This weakens the already-tentative link between +the registration storm and failure from last session, but the "two failures, then success, on a +long-gap cycle" shape has now repeated identically twice. + +**The apparent "mystery" extra `Disarmed` broadcast (`14:12:45.044`, no local disarm attempt +nearby) turns out to be nothing new:** it's the documented post-`KEYPAD_REGISTRATION` +re-announce (the IP Keypad re-registers at `14:12:45.027` immediately before it), preceded by a +~500ms burst of `Unknown [ff.]` corruption on the interface right after the prior successful +disarm (`14:12:39.396`–`39.902`) — the same interface-side corruption signature from the +2026-07-12 entry in `arm_disarm_state_machine.md`, not a new mechanism. + +## Findings (observed facts) + +1. In every failure across both sessions, the code digits and terminal key were sent and acked + completely normally (`display=0x01` per digit, matching successful cycles bit-for-bit) — the + failure is not in ESPHome's own TX. +2. The proximate signature is identical to `arm_disarm_state_machine.md`'s 2026-07-25 + "`CODE_ENTER_PENDING` silence confirmed genuine" entry: a clean terminal-key ack + (`display=0x07` in logs-42/logs-22; no adjacent corruption) followed by genuine bus silence — + no `ARMED_STATE`, no garbled retry — until the shared 1s watchdog aborts. This is now + corroborated across two more independent sessions. +3. In logs-43/22, the one failure had the shortest armed→disarm gap (7.4s) of all 8 cycles; + every other gap (9.6–37.8s) succeeded. +4. In logs-42, this pattern does **not** hold: 5 of 6 failures occurred at gaps of 21–40s, far + longer than the 7.4s failure in logs-43/22, and only the 6th attempt (44.1s gap) succeeded. +5. logs-44/23 falsifies the gap-timing lead outright: cycle 5's 5.5s gap (the shortest in that + session) succeeded cleanly, while cycle 3's two failing attempts had longer gaps (6.4s, 9.5s) + than that success. Gap length is not a usable predictor of failure in any direction. +6. logs-44/23's cycle 3 is also the first session where the *passive monitor* (not the + ACK-driving interface) shows the `Unknown 0xFF`/`0xFE` RX-corruption signature, in a window + the interface decoded perfectly — the reverse of the 2026-07-12 pairing in + `arm_disarm_state_machine.md`, and not explainable by that entry's "our own ACK-release + desyncs our own RX" mechanism, since the monitor never drives the hardware ACK. +7. In all three sessions, the arm event immediately preceding a failing disarm cycle was + performed via the physical IP Keypad's direct code+ENTER, not the ESPHome interface's own ARM + key. But this alone isn't sufficient either — logs-43/22 cycle 2 and logs-44/23 cycles 1 and 5 + were armed the same way and succeeded cleanly. logs-45/24's five-failure cycle breaks this + pattern entirely: it was armed via the ESPHome interface's own ARM key, not a physical keypad. +8. logs-41/42/43/44 (monitor) show no `[D]`/`[W]` output at all despite `logs: crow_alarm_panel: + DEBUG` in the yaml, while logs-22/23 (interface, rebuilt 2026-08-05) log normally — consistent + with the monitor running a stale firmware build (still compiled 2026-08-02 in logs-44/45). +9. logs-45/24 independently reproduces `arm_disarm_state_machine.md`'s documented + `[14.A1.05.11]` bus-collision failure mode (failure mode 3) via a passive monitor's raw-bit + decode, and shows a new variant of the same collision class landing on a mid-sequence digit + keypress instead of the terminal key. +10. logs-45/24's five-failure streak mixes three distinct, previously-catalogued failure + mechanisms back to back (two bus collisions, two genuine `CODE_ENTER_PENDING` silences, one + genuine digit-state silence) rather than repeating a single mechanism — consistent with a + "bad session" raising the odds of every known failure mode together, rather than one new + mechanism being responsible. +11. logs-46/25 confirms the bus-collision failure mode can hit the *first* digit of a code + sequence too (a bare `Unknown 0xFF` frame in place of the first `KEYPRESS`), not just ENTER + or a mid-sequence digit — this mechanism appears equally able to hit any outgoing keypress. +12. logs-46/25's two long-gap (285–292s) failures both match already-established signatures + (mode 1 digit-silence, then `0x07`-after-terminal-key silence) with no new mechanism, and + follow — but likely don't causally depend on — a "no ping for 60s" registration-storm that had + already resolved 4m45s before the failures. +13. logs-46/25 also shows the *original* 2026-07-12 corruption pairing (interface's own decode + corrupted — a malformed 7-byte `ARMED_STATE` — while the monitor's simultaneous decode is + clean), the reverse of logs-44/23's pairing. Both directions have now been observed across + different sessions. +14. logs-47/26's two "no digit ack" failures show no collision artifact at all when + cross-checked against the monitor — genuinely silent, unlike logs-46/25's first-digit + failure. The interface's own log cannot distinguish a genuine silence from a hidden + collision; only a monitor cross-check can. +15. logs-47/26's cycle 3 failure shows an ack that arrived (825ms after the terminal key) but + much slower than the typical ~100–200ms turnaround seen everywhere else, and the watchdog + still ran out shortly after — the first time a slow-but-present ack has been noted rather + than an ack that's either prompt or entirely absent. +16. logs-47/26's ~5-minute-gap cycle repeats the exact "two failures (digit-silence, then + terminal-key silence), then success" shape from logs-46/25's ~5-minute-gap cycle — but this + time with zero registration/ping-loss activity in the gap, weakening the tentative link + between the registration storm and failure raised last session while strengthening the + "two failures then success" shape itself as a (still small-sample) recurring pattern on + long-gap cycles specifically. +17. logs-47/26's overall failure rate (5/9, ~56%) extends the failure-rate continuum further: + 1/8, 2/6, 3/9, 5/9, 5/6, 5/6 across sessions so far, with no two sessions landing at exactly + the same rate. + +## Inference (low confidence — six sessions, gap-timing and arming-method leads now both dead) + +A short gap between `ARMED_STATE: Armed Away` and the next disarm attempt looked associated with +failure in the logs-43/22 session, but logs-42 and logs-44/23 both kill that lead: logs-42 failed +repeatedly across a much wider range of gaps (21–44s) and only succeeded on the 6th try, and +logs-44/23's shortest gap of the whole session (5.5s, cycle 5) succeeded while two *longer* gaps +in the same session (6.4s, 9.5s, cycle 3) failed. logs-45/24 adds nothing for gap length either +way (all its failures sit at 44–65s, its lone earlier successes at 9.6–10.8s) but does kill the +arming-method lead: its five-failure cycle was armed via the ESPHome interface's own ARM key, not +a physical keypad, breaking the "preceded by IP Keypad code+ENTER" pattern every prior failure +shared. What's left is that **overall session/bus conditions** (contention, an unidentified +controller-side state, or something upstream of any single per-attempt variable) dominate the +failure rate — sessions vary continuously from "good" (1/8 failed, logs-22) through "medium" +(3/9 failed, logs-25; 5/9 failed, logs-26) to "bad" (5/6 failed, twice: logs-42 and logs-24) for +reasons not yet isolated, and a bad-to-medium session appears to raise the odds of multiple +distinct known failure mechanisms simultaneously (collision and silence alike) rather than +swapping in one new mechanism. The bus-collision mechanism itself is now well established (3 +independent reproductions across logs-24/25, hitting the terminal key, a mid-sequence digit, and +the first digit) — what's still missing is what makes a session more or less prone to it, and +logs-26 shows collisions aren't a prerequisite for a high failure rate: its 5/9 session had zero +collision artifacts, all genuine silence. Two long-gap (~5 minute) cycles now (logs-25, logs-26) +have independently produced the identical "digit-silence fail, terminal-key-silence fail, +success" shape — still only 2 data points, but a pattern worth watching for. + +## Assumption (unverified) + +Whether arming via a physical keypad's direct code+ENTER (vs. the ESPHome interface's own ARM +key) makes the controller more likely to respond to a subsequent disarm with `display=0x07` +silence is no longer a live hypothesis — logs-45/24's failure cycle was armed via the ESPHome +interface's own ARM key, contradicting it directly. Also unverified: whether the logs-44/23 +monitor-side `0xFF`/`0xFE` corruption, the logs-45/24 `[14.A1.05.11]`-class collisions, and +logs-46/25's interface-side malformed `ARMED_STATE` share a root cause with the interface-side +corruption from the 2026-07-12 entry in `arm_disarm_state_machine.md`, or are distinct phenomena +that happen to produce similar garbled bytes — both the "interface corrupted, monitor clean" +and "monitor corrupted, interface clean" pairings have now been seen, in different sessions, +which is at least consistent with general bus noise hitting either receiver rather than a +mechanism deterministically tied to whichever device drives the hardware ACK, but not +conclusive. Whether "bad sessions" have a detectable common cause (vs. being independently +unlucky) is also unverified — the failure rate across sessions so far (1/8, 2/6, 3/9, 5/9, 5/6, +5/6) looks more like a continuum than two discrete "good"/"bad" buckets, which argues against a +single binary trigger and toward something with a continuous severity (e.g. general bus +contention level). Whether the "registration storm precedes a long-gap failure pair" link from +logs-46/25 is real is now doubtful — logs-47/26's equivalent long-gap cycle showed the identical +failure shape with a completely healthy ping/registration history throughout. A larger sample, +ideally with `ESP_LOGV` raw-frame logging enabled on the interface and the monitor's DEBUG output +actually working, is needed before any of this is treated as more than confounded noise. + +## Practical takeaway + +- This doesn't change the recommended handling in `CODE_ENTER_PENDING` or `CODE_DIGIT_PENDING` — + both already resolve correctly via `ARMED_STATE`/watchdog per the 2026-07-12/07-25 redesigns, + and the 2026-07-22 last-confirmed-state fix means a failed attempt here is cheaply recoverable + (confirmed again in logs-22 through logs-26: every retry after an abort re-armed the entity + correctly and the next attempt succeeded, even after five consecutive failures). +- Before spending more effort chasing a root cause, get the monitor device onto current firmware + so `logs: crow_alarm_panel: DEBUG` actually produces output there — right now half of every + paired capture (the passive witness) is bit-trace-only, which cost significant manual decode + effort for logs-41 through logs-47 that the interface's own logging already provides for free. +- The gap-timing and arming-method leads are both spent; the next productive step is probably + correlating failures against bus-health signals already tracked elsewhere (RX corruption + bursts, `CURRENT_TIME` glitch timing) or against a session-level "how busy/contended was the + bus overall" signal, rather than inventing more per-attempt variables. Given logs-26 shows a + high failure rate with zero collisions, "bus contention" and "collision frequency" may need to + be tracked as separate signals rather than one combined "bus health" score. + +## Open questions + +1. Why does the controller sometimes ack a correctly-received ENTER (`display=0x07` or + otherwise) but never broadcast `ARMED_STATE`? (Carried over, unresolved, from + `arm_disarm_state_machine.md`'s 2026-07-25 entry — still not established by this data either.) +2. Does the overall per-session failure rate (1/8, 2/6, 3/9, 5/9, 5/6, 5/6 across + logs-22/23/25/26/42/24) correlate with any bus-health signal visible elsewhere in the same + captures (e.g. the RX decode corruption documented in `protocol_investigations.md`), or is it + independent? Worth checking whether the two 5/6 sessions (logs-42, logs-24) share anything + else (time of day, session duration, zone activity) that logs-26's 5/9 session doesn't. +3. Is the monitor's missing DEBUG/WARN output a stale-firmware artifact, or does the per-tag + `logs:` override genuinely not take effect for that device? Worth a quick confirmation next + time both devices are reflashed together. +4. The bus-collision mechanism (failure mode 3 and its variants) is now confirmed able to hit + any outgoing keypress — terminal key (logs-24), a mid-sequence digit (logs-24), and the first + digit (logs-25). Is it purely a function of unlucky timing against the controller's own + periodic broadcasts, or does something about bus timing (e.g. proximity to a periodic + `KEYPAD_COMMAND`/`KEYPAD_PING` broadcast) predict which specific keypress in a sequence gets + hit, and does session-level bus contention make it more likely overall in some sessions + (logs-24, logs-25) than others (logs-22, logs-23, logs-26)? logs-26 shows collisions aren't + required for a high failure rate, so this may be an independent axis from whatever drives the + overall rate. +5. Is the "two failures (digit-silence, then terminal-key silence), then success" shape on + long-gap (~5 minute) cycles — now seen identically in both logs-25 and logs-26 — a real + pattern specific to long idle periods, or coincidence from a 2-sample base rate? Worth + specifically targeting a few more long-gap disarms to check. +6. Is the `0xFF`/`0xFE`/malformed-frame corruption seen on the monitor (logs-44) and on the + interface (logs-46, this session's malformed `ARMED_STATE`) the same underlying mechanism as + the 2026-07-12 entry in `arm_disarm_state_machine.md`, given it's now been seen hitting + whichever device *doesn't* drive the hardware ACK as well as the one that does? Needs a + session with `ESP_LOGV` on both devices simultaneously to compare raw frame-level detail. From ab2d6ba2e0d43986adc91d9d8da9e0e69b99a4a9 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 5 Aug 2026 15:05:32 +1200 Subject: [PATCH 3/5] docs(crow_alarm_panel): logs-27 validates arm/disarm retry fix MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A disarm hit the familiar two-failure-then-success shape, but this time the watchdog's automatic retry resolved it in 3.8s with a single user call and no manual intervention — confirms the fix works in practice. --- .../docs/arm_disarm_state_machine.md | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/components/crow_alarm_panel/docs/arm_disarm_state_machine.md b/components/crow_alarm_panel/docs/arm_disarm_state_machine.md index 8fe8bd8..930e722 100644 --- a/components/crow_alarm_panel/docs/arm_disarm_state_machine.md +++ b/components/crow_alarm_panel/docs/arm_disarm_state_machine.md @@ -421,6 +421,21 @@ Because `arm_away()`/`arm_stay()`/`disarm()` all reject a new call while `arm_di Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. **Not yet validated on real hardware** — needs a fresh capture (ideally reproducing a multi-failure streak like logs-24/42) to confirm the automatic retries actually land and that no new interaction appears between rapid consecutive retries and the controller (e.g. the same kind of ACK-timing sensitivity documented for output-select's `OUTPUT_SELECT_ENTER_DELAY_MS`). +**Validated on real hardware (2026-08-05, logs-27):** `esphome-aap-alarm-interface-logs-27.txt`, captured with the fix flashed (compiled `14:47:22`). Two disarm cycles: the first succeeds on the first attempt (no retry needed), the second reproduces the familiar "digit-silence/terminal-key-silence, then success" shape already seen manually in logs-44/23, logs-46/25, and logs-47/26 — but fully automatically this time: + +``` +14:51:46.740 Disarm (single user-initiated call) +14:51:47.349 CMD 0x01 after terminal key, awaiting ARMED_STATE confirmation +14:51:48.288 Arm/disarm: timeout in state 4, retrying (1/5) +14:51:48.669 Arm/disarm: CMD byte changed from 0x01 to 0x07 in CODE_DIGIT_PENDING, continuing +14:51:48.999 CMD 0x07 after terminal key, awaiting ARMED_STATE confirmation +14:51:49.820 Arm/disarm: timeout in state 4, retrying (2/5) +14:51:50.513 [Controller] Disarmed +14:51:50.529 Code sequence: complete (confirmed via ARMED_STATE broadcast) +``` + +A single `disarm()` call resolved in 3.8s total across two automatic retries, with no user action in between — the retries land cleanly, the CMD-byte-change tolerance from the 2026-07-25 fix keeps working unmodified mid-retry, and there's no sign of any new interaction between the rapid consecutive retries and the controller. Confirms the fix works in practice, not just in code review. + ## Notes - ARM/STAY/DISARM sequences are simpler than OUTPUT because there's no ACK handshake From 3879100416324fcca60d046cf11101b02f40e16b Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 5 Aug 2026 16:15:44 +1200 Subject: [PATCH 4/5] fix(crow_alarm_panel): recover doubled-bit CURRENT_TIME glitch safely Comparing corrupted frames against Home Assistant's own log timestamps confirmed day/month/year are exactly doubled by a single inserted bit, and that it originates on the panel's transmit side (minutes_hi/lo, sent before the insertion point, always match real time exactly). Halving now recovers the frame instead of discarding it, but only when the recovered date's weekday also matches the frame's own untouched day_of_week field, avoiding the coincidental-valid-value risk already noted in protocol_investigations.md. --- .../crow_alarm_panel/crow_alarm_panel.cpp | 57 +++++++++++++++---- .../docs/protocol_investigations.md | 16 +++++- 2 files changed, 61 insertions(+), 12 deletions(-) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index e678c75..60b6cec 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -47,6 +47,16 @@ std::string keypad_label(const CrowAlarmPanelKeypad &keypad, uint8_t address) { return str_sprintf("Keypad 0x%02X", address); } +// Sakamoto's algorithm. Returns the protocol's day_of_week encoding directly (1=Sunday..7=Saturday, +// matching DAYS[] and CURRENT_TIME's data[0]) rather than the usual 0=Sunday. +uint8_t day_of_week_from_date(uint16_t year, uint8_t month, uint8_t day) { + static const uint8_t OFFSETS[] = {0, 3, 2, 5, 0, 3, 5, 1, 4, 6, 2, 4}; + if (month < 3) { + year--; + } + return static_cast((year + year / 4 - year / 100 + year / 400 + OFFSETS[month - 1] + day) % 7) + 1; +} + const char *controller_status_profile(uint8_t flags) { if (flags == 0x80) { return "zone_activity"; @@ -513,19 +523,44 @@ void CrowAlarmPanel::loop() { CONTROLLER_LABEL, data[3], type, format_hex_pretty(data).c_str()); break; } - if (data[4] == 0 || data[4] > 31) { - ESP_LOGW(TAG, "[%-*s] Current time has invalid day-of-month value %u [%02x.%s]", this->keypad_label_width_, - CONTROLLER_LABEL, data[4], type, format_hex_pretty(data).c_str()); - break; - } - if (data[5] == 0 || data[5] > 12) { - ESP_LOGW(TAG, "[%-*s] Current time has invalid month value %u [%02x.%s]", this->keypad_label_width_, - CONTROLLER_LABEL, data[5], type, format_hex_pretty(data).c_str()); - break; + uint8_t day = data[4]; + uint8_t month = data[5]; + uint8_t year = data[6]; + if (day == 0 || day > 31 || month == 0 || month > 12) { + // The documented CURRENT_TIME bit-corruption glitch (protocol_investigations.md) shifts + // day/month/year one bit left together (a single spurious 0 bit inserted right after the + // seconds byte) — i.e. each is exactly double its true value. Halving all three and + // cross-checking the recovered date's weekday against the untouched day_of_week field + // (data[0], from earlier in the frame, before the glitch's insertion point) makes a false + // recovery astronomically unlikely, addressing the coincidental-valid-range risk noted in + // that doc. Validated against real HA log timestamps in the 2026-08-05 traces: the + // recovered date matched the true date/time exactly in every sample checked. + bool recovered = false; + if ((data[4] % 2) == 0 && (data[5] % 2) == 0 && (data[6] % 2) == 0) { + uint8_t rec_day = data[4] / 2; + uint8_t rec_month = data[5] / 2; + uint8_t rec_year = data[6] / 2; + if (rec_day >= 1 && rec_day <= 31 && rec_month >= 1 && rec_month <= 12 && + day_of_week_from_date(2000 + rec_year, rec_month, rec_day) == data[0]) { + ESP_LOGI(TAG, + "[%-*s] Current time: recovered doubled-bit glitch, using 20%02u-%02u-%02u [%02x.%s]", + this->keypad_label_width_, CONTROLLER_LABEL, rec_year, rec_month, rec_day, type, + format_hex_pretty(data).c_str()); + day = rec_day; + month = rec_month; + year = rec_year; + recovered = true; + } + } + if (!recovered) { + ESP_LOGW(TAG, "[%-*s] Current time has invalid day/month value %u/%u [%02x.%s]", + this->keypad_label_width_, CONTROLLER_LABEL, data[4], data[5], type, + format_hex_pretty(data).c_str()); + break; + } } ESP_LOGD(TAG, "[%-*s] Controller time update: %s 20%02d-%02d-%02d %02d:%02d:%02d", - this->keypad_label_width_, CONTROLLER_LABEL, day_of_week, data[6], data[5], data[4], hour, minute, - data[3]); + this->keypad_label_width_, CONTROLLER_LABEL, day_of_week, year, month, day, hour, minute, data[3]); break; } case RESPONSE_TIME: diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index bb3f0c4..913361a 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -249,7 +249,7 @@ Doubling a byte whose true value never sets bit 7 (true for `day` 1–31, `month The closing `0x7E` boundary is still found at the expected byte count (`(7)` in both good and bad frames), which is consistent with the framer's boundary detector because it uses a raw sliding-bit window rather than byte-aligned matching (see `protocol_wire_format.md`). -### Assumption (unverified) +### Assumption (unverified) — superseded, see 2026-08-05 update below Whether the extra bit originates from the panel's own bus driver (e.g. a hiccup while it composes/shifts out this specific broadcast) or from our own ISR sampling (e.g. something else briefly delaying bit capture at a consistent point in the cycle) is not established. The fact that it recurs at the exact same *relative* position every session, across different panel installs and different ESP32 units, favors a controller-side cause, but this is not confirmed. @@ -257,6 +257,20 @@ Whether the extra bit originates from the panel's own bus driver (e.g. a hiccup Do not attempt to auto-correct by halving the bytes: a doubled value can coincidentally land in a valid range (e.g. true `month=6` → corrupted `12`), which would silently publish a wrong-but-plausible date. Discarding the frame with a warning (current behavior) is the safer choice. The `ESP_LOGW` branches in `CURRENT_TIME` handling now include the raw frame hex so future captures don't require `ESP_LOGV` to diagnose this. +### Update (2026-08-05): panel-side origin confirmed; safe recovery implemented + +**Source:** `traces/home-assistant_2026-08-05T03-50-34.425Z.log` (Home Assistant's own log, which timestamps every ESPHome device log line with HA's real wall-clock time — a ground truth independent of the panel's own RTC). + +**Findings (observed facts):** cross-checking the recovered date (halving `day`/`month`/`year`) against HA's own log timestamp for multiple `Current time has invalid month value 16` warnings shows an exact match, to the minute, every time — e.g. `14:56:10.594` decodes (after halving) to `2026-08-05 14:56`, matching HA's own timestamp precisely; same for `15:00:10.507` → `15:00` and `15:26:10.153` → `15:26`. `minutes_hi`/`minutes_lo` (offsets 1–2, transmitted *before* the glitch's insertion point at the seconds/day boundary) also matched real wall-clock time exactly in every sample, incrementing by exactly one minute between consecutive corrupted broadcasts. + +This same log also shows a **second, more severe variant**: in two multi-minute bursts (`14:22:55`–`14:23:40` and `14:51:55`–`14:55:40`), *every* `CURRENT_TIME` broadcast in the window is corrupted (not just one per minute), and `seconds` is doubled too, not just `day`/`month`/`year` — confirmed by tracking four consecutive 15s-spaced broadcasts whose observed `seconds` bytes (`0x00, 0x1E, 0x3C, 0x5A` = 0, 30, 60, 90) are each exactly double the true progression (0, 15, 30, 45). This suggests the insertion point sometimes shifts one byte earlier (into the `seconds` byte itself), and that the "severe" variant clusters in bursts rather than being spread evenly — more consistent with a triggered condition (e.g. bus contention, matching the "session badness" continuum from `arm_disarm_state_machine.md`) than constant background noise. + +**Inference (high confidence):** since `minutes_hi`/`minutes_lo` — transmitted *before* the corruption's insertion point in the same frame — always match real time exactly while `day`/`month`/`year` after it don't, this is very unlikely to be an ISR/receiver-side sampling artifact (which would be expected to occasionally perturb earlier bytes too, or differ between independent receivers). This resolves the assumption above: **the glitch originates on the panel's own transmit side**, not our sampling. + +**Fix applied:** `CrowAlarmPanel::` `CURRENT_TIME` handling (`crow_alarm_panel.cpp`) now attempts recovery instead of only discarding, addressing the "coincidental valid range" risk the original practical takeaway (above) correctly flagged: when `day`/`month` fail their range check, it halves `day`/`month`/`year` together (only if all three are even — a true single-bit doubling can't produce an odd result) and independently cross-checks the recovered date's day-of-week (via a new `day_of_week_from_date()` Sakamoto's-algorithm helper) against the frame's own untouched `day_of_week` field. A coincidental match on both the halved ranges *and* the weekday is astronomically unlikely, so this is treated as a confident recovery (logged at `ESP_LOGI`) rather than a guess. The "severe" seconds-doubling variant is not addressed — `seconds` isn't critical enough to warrant the same treatment, and the existing per-field range check still discards those frames when `seconds` lands out of range. + +Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. **Not yet validated on real hardware** — needs a fresh capture showing the `ESP_LOGI` recovery line fire against a real corrupted frame. + ## `Unknown [ff.]`/`[fe.]` RX decode corruption still recurring after the 2026-07-12 ISR fix `arm_disarm_state_machine.md`'s "Root-cause candidate: hardware-ACK release corrupts our own RX decode under rapid retransmission (2026-07-12)" entry identified this signature (a burst of `Unknown [ff.]`/`[fe.]` frames, decoded correctly by a passive monitor at the same moment but garbled on the active interface) and applied a fix to `CrowAlarmPanelStore::interrupt()`, validated against `logs-12/37` as showing zero occurrences in that one session. From 112d5e4b4a5b1be1f212f0c032f6eb44728da9f0 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 5 Aug 2026 19:47:55 +1200 Subject: [PATCH 5/5] fix(crow_alarm_panel): address Copilot review comments on PR #10 - Refresh arm_disarm_state_enter_ms_ before keypress() in the retry block, not after: keypress()->send_packet() can yield and re-enter loop(), so the watchdog could otherwise fire again on the stale timestamp and send extra keypresses (same fix already applied to the output-select retry). - Gate the ISR's bit-trace buffer swap on !bit_trace_ready_ so it can't overwrite bit_trace_buffer2_ while loop() (other core) is still copying it out. - Mark bit_trace_enabled_ volatile, matching ack_pending_/ is_transmitting_. - Reset bit_trace_len_/bit_trace_ready_ on every toggle so disabling mid-buffer and re-enabling can't mix stale bits into a trace chunk. --- .../crow_alarm_panel/crow_alarm_panel.cpp | 13 +++++++++++-- .../crow_alarm_panel/crow_alarm_panel.h | 19 ++++++++++++++++--- 2 files changed, 27 insertions(+), 5 deletions(-) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index 60b6cec..7ad5a8f 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -150,7 +150,12 @@ void IRAM_ATTR HOT CrowAlarmPanelStore::interrupt(CrowAlarmPanelStore *arg) { // Check for boundary arg->boundary_buffer_ = (uint8_t) ((arg->boundary_buffer_ << 1) | data_bit); - if (arg->bit_trace_enabled_) { + // Gated on !bit_trace_ready_ so bit_trace_buffer2_ stays untouched while loop() (running on + // the other core) is still copying it out — loop()'s InterruptLock only protects against + // same-core reentrancy, not this ISR on the other core, so the flag itself is what prevents + // the overwrite. Bits are simply dropped while the consumer is behind; accumulation resumes + // as soon as it clears the flag (normally sub-millisecond later). + if (arg->bit_trace_enabled_ && !arg->bit_trace_ready_) { arg->bit_trace_buffer_[arg->bit_trace_len_++] = data_bit ? '1' : '0'; if (arg->bit_trace_len_ >= BIT_TRACE_BUFFER_BITS) { memcpy(arg->bit_trace_buffer2_, arg->bit_trace_buffer_, BIT_TRACE_BUFFER_BITS); @@ -898,6 +903,11 @@ void CrowAlarmPanel::loop() { ESP_LOGW(TAG, "Arm/disarm: timeout in state %u, retrying (%u/%u)", static_cast(this->arm_disarm_state_), this->arm_disarm_retry_count_, ARM_DISARM_MAX_RETRIES); + // Refresh the watchdog timer BEFORE any keypress() below — keypress()->send_packet() + // can delay()/yield() and re-enter this loop(), and with the old timestamp still in + // place the watchdog would see itself as still timed out, firing again and sending an + // extra keypress (same race the output-select retry above avoids the same way). + this->arm_disarm_state_enter_ms_ = millis(); switch (this->arm_disarm_state_) { case ArmDisarmState::ARM_AWAY_PENDING: this->keypress(KEY_ARM); @@ -917,7 +927,6 @@ void CrowAlarmPanel::loop() { default: break; } - this->arm_disarm_state_enter_ms_ = millis(); } else { ESP_LOGW(TAG, "Arm/disarm: timeout in state %u, aborting after %u retries", static_cast(this->arm_disarm_state_), this->arm_disarm_retry_count_); diff --git a/components/crow_alarm_panel/crow_alarm_panel.h b/components/crow_alarm_panel/crow_alarm_panel.h index 342c583..0768c9d 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.h +++ b/components/crow_alarm_panel/crow_alarm_panel.h @@ -172,7 +172,9 @@ class CrowAlarmPanelStore { // Independent of frame decoding, so mis-alignment/framing issues can be diagnosed // by hand from the literal bitstream instead of the already-decoded bytes. static const uint16_t BIT_TRACE_BUFFER_BITS = 128; - bool bit_trace_enabled_{false}; + // Read in the ISR, written from the main loop via set_raw_bit_trace_enabled() — volatile like + // ack_pending_/is_transmitting_ above, for the same cross-core visibility reason. + volatile bool bit_trace_enabled_{false}; char bit_trace_buffer_[BIT_TRACE_BUFFER_BITS + 1]{}; char bit_trace_buffer2_[BIT_TRACE_BUFFER_BITS + 1]{}; uint16_t bit_trace_len_{0}; @@ -264,8 +266,19 @@ class CrowAlarmPanel : public Component { // be toggled at runtime without recompiling with a higher logger level. void set_raw_frame_logging_enabled(bool enabled) { this->raw_frame_logging_enabled_ = enabled; } - // Enables the ISR-side raw bit trace (see CrowAlarmPanelStore::bit_trace_enabled_). - void set_raw_bit_trace_enabled(bool enabled) { this->store_.bit_trace_enabled_ = enabled; } + // Enables the ISR-side raw bit trace (see CrowAlarmPanelStore::bit_trace_enabled_). Disables + // first, then resets the in-progress buffer position and any pending-but-unconsumed batch + // before (re-)enabling, so a toggle never mixes bits captured before/after it into one trace + // chunk, and never emits a stale ready buffer left over from before the toggle. + void set_raw_bit_trace_enabled(bool enabled) { + this->store_.bit_trace_enabled_ = false; + { + InterruptLock lock; + this->store_.bit_trace_len_ = 0; + this->store_.bit_trace_ready_ = false; + } + this->store_.bit_trace_enabled_ = enabled; + } protected: CrowAlarmPanelKeypad find_keypad_(uint8_t address);