diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index b501e5e..7ad5a8f 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"; @@ -140,6 +150,21 @@ void IRAM_ATTR HOT CrowAlarmPanelStore::interrupt(CrowAlarmPanelStore *arg) { // Check for boundary arg->boundary_buffer_ = (uint8_t) ((arg->boundary_buffer_ << 1) | data_bit); + // 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); + 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 +276,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); @@ -493,19 +528,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: @@ -832,23 +892,57 @@ 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); + // 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); + 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; + } + } 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_); + } } } } @@ -892,6 +986,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]); } @@ -912,6 +1007,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); } } @@ -932,6 +1028,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 ea417f4..0768c9d 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.h +++ b/components/crow_alarm_panel/crow_alarm_panel.h @@ -165,6 +165,20 @@ 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; + // 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}; + volatile bool bit_trace_ready_{false}; }; struct CrowAlarmPanelZone { @@ -252,6 +266,20 @@ 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_). 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); bool is_bus_idle_(); @@ -290,6 +318,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..930e722 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,83 @@ 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`). + +**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 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. 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. 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"