From 372de778d2fd870f5f9064e13bad29c47b8265e3 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 5 Aug 2026 21:30:10 +1200 Subject: [PATCH 1/8] docs(crow_alarm_panel): logs-28/29/30 validate time-glitch findings Confirms the doubled-bit recovery fix works on real hardware (logs-28), finds the glitch's wall-clock position isn't fixed - a registration event shifted it by 8s (logs-29) - and shows the panel's own RTC runs a stable ~4.4s fast relative to real time (logs-30). --- .../docs/protocol_investigations.md | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index 913361a..ffcb27e 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -271,6 +271,34 @@ This same log also shows a **second, more severe variant**: in two multi-minute 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. +### Update (2026-08-05): validated on real hardware; glitch phase tied to broadcast count, not wall-clock seconds + +**Source:** `traces/esphome-aap-alarm-interface-logs-28.txt` and `-29.txt`, both captured with the recovery fix flashed (compiled `2026-08-05 20:00:02`). + +**Findings (observed facts) — recovery confirmed working:** logs-28 shows the fix firing 12 times in a ~12-minute session, once per minute, every occurrence at `seconds=0x0F` (15) exactly as previously characterized, and every occurrence's recovered date (`2026-08-05`) matching real time. Verified the arithmetic on one instance (`54.04.04.B2.0F.0A.10.34`): `day_of_week=4` (Wed), `minutes=0x04B2=1202→20:02`, `seconds=0x0F=15` (clean), `day=0x0A`/`month=0x10`/`year=0x34` halve cleanly to `5`/`8`/`26`. This resolves the "not yet validated on real hardware" note above. + +**Findings (observed facts) — glitch phase shifts after an out-of-cycle broadcast, and one occurrence corrupts `seconds` in a way that isn't clean doubling:** logs-29, captured later in the same session, shows both glitch occurrences at `seconds=0x17` (23) instead of the usual 15 — e.g. `54.04.04.CF.17.0A.10.34`. Tracing the surrounding traffic: at `20:30:47.228` the AAP Keypad (address `0x00`) sends a `KEYPAD_REGISTRATION` announce, and the controller's documented post-registration re-broadcast sequence follows (`Disarmed`, `Zone state`, `Controller status`) — including an **extra, out-of-cycle `CURRENT_TIME` broadcast** at `20:30:47.612` (decoded `seconds=52`), only ~7.3s after the previous one instead of the usual ~15s. Every `CURRENT_TIME` broadcast after that point keeps dead-on 15.0s spacing (confirmed via the ESP's own receipt timestamps), just shifted 8 seconds later than before the extra broadcast — i.e. one extra broadcast got inserted mid-cycle, and every broadcast after it (including the glitchy one) shifted phase by the same amount. + +`day`/`month`/`year` in the logs-29 glitch still decode correctly via the existing recovery (`0x0A`/`0x10`/`0x34` → `5`/`8`/`26`, matching real date) — the fix is unaffected. But the observed `seconds` value itself (`0x17`=23, odd) cannot be a clean single-bit-doubling of anything, since doubling any integer is always even — this rules out the same bit-insertion mechanism that's cleanly doubling `day`/`month`/`year` in the identical frame. Whatever corrupted `seconds` here is mechanically different from (or in addition to) the established one. + +**Inference (medium confidence, one session):** the recurring glitch is very likely keyed to an internal broadcast *counter* on the panel (e.g. "corrupt every Nth `CURRENT_TIME` frame sent"), not to wall-clock `:15` directly — the extra registration-triggered broadcast inserting itself into the cycle would explain the clean 8-second phase shift in when the counter's "problem slot" next lands, while every broadcast's own 15s spacing stayed perfectly regular throughout. This also means "seconds=15" was never the real trigger condition, just what it happened to coincide with in every session observed before this one. + +**Assumption (unverified):** what specifically corrupts `seconds` to a non-doubled, odd value in this instance — a different insertion point within that byte (partial/mid-byte corruption, as opposed to the clean at-byte-boundary insertion characterizing the day/month/year doubling), two independent corruption events in the same frame, or something else — is not established from this single occurrence. Not yet worth a code change: `seconds` was already excluded from the recovery fix by design, and this doesn't affect the day/month/year recovery's correctness or safety guarantees (the weekday cross-check remains sound regardless of what happens to `seconds`). + +**Practical takeaway:** if this glitch's fixed wall-clock position (previously always `:15`) needs to be relied on again (e.g. for future correlation with other bus events), don't assume it — it moved after a single registration event in this session, and may not be fixed at all going forward. + +### Update (2026-08-05): panel's own clock runs ~4.4s fast relative to real time + +**Source:** `traces/esphome-aap-alarm-interface-logs-30.txt`. + +**Findings (observed facts):** comparing every clean (non-corrupted) `CURRENT_TIME` decode in this session against the log line's own timestamp shows a consistent offset — the panel's reported time is always **4.3–4.5 seconds ahead** of the log timestamp, holding steady across ~30 samples spanning the full ~12-minute session (e.g. `20:36:55.563` receipt → panel reports `20:37:00`, a +4.44s offset; `20:44:25.489` → `20:44:30`, +4.51s; `20:48:55.518` → `20:49:00`, +4.48s). The offset doesn't grow or shrink over the session — it's a fixed bias, not clock drift accumulating in real time. + +The device's actual production config (`aap-esl2-keypad-interface/aap_esl_keypad_interface.yaml`) has **no `time:` component** — the ESP itself has no synced clock. The bracketed log timestamp therefore isn't sourced from the device at all; it's stamped by whichever client received the API stream (`esphome logs` / Home Assistant) at the moment each line arrived, which should track real wall-clock time to well under a second on any normally NTP-synced machine. + +**Inference (medium-high confidence):** since the receiving side's timestamp should be accurate to well under a second, a stable multi-second lead is too large to be network/API transport latency, and too consistent to be jitter. This points to the **alarm panel's own onboard RTC genuinely running ~4.4 seconds fast** relative to real time — not a decoding bug, not something introduced by the recovery fix, and not something correctable from the ESP side, since we're only a passive listener reporting what the panel itself broadcasts. + +**Practical takeaway:** if any future analysis needs to correlate a `CURRENT_TIME` broadcast's reported value against real-world wall-clock time precisely (rather than just "close enough to identify which session/date"), expect the panel's own value to read ~4–5 seconds ahead. + ## `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 2cc33004bace3d10efe4dd70196bd04f1f347a68 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Mon, 10 Aug 2026 15:50:31 +1200 Subject: [PATCH 2/8] docs(crow_alarm_panel): logs-31/32 validate multi-keypad arm/disarm Analyzed two new traces with arm/disarm sequenced from the IP and Control 4 keypads directly (not just our own integration). Extends the still-open Unknown [ff.]/[fe.] corruption investigation with the first evidence it's a real bus/controller-level event (an independent keypad self-re-registers right after a burst) plus two new trigger contexts and an unlabeled 0x8A packet, adds a third occurrence of the correct-date/wrong-time-of-day CURRENT_TIME gap, and documents Control4's digit-batching timing quirk and multi-user-code support. --- .../docs/keypad_protocol_types.md | 2 ++ .../docs/protocol_investigations.md | 27 +++++++++++++++++++ 2 files changed, 29 insertions(+) diff --git a/components/crow_alarm_panel/docs/keypad_protocol_types.md b/components/crow_alarm_panel/docs/keypad_protocol_types.md index 589f7ae..2eee83c 100644 --- a/components/crow_alarm_panel/docs/keypad_protocol_types.md +++ b/components/crow_alarm_panel/docs/keypad_protocol_types.md @@ -153,6 +153,8 @@ Output-select and arm/disarm sequences are now captured (`esphome-aap-keypad-mon - During arming countdown, keypad receives `Command [14.06.AA.00.00.01.80]` before final armed-away state - Protocol appears identical to IP keypad for output-select and code-entry command gating - Address 0x06 confirmed +- **Digit batching, not per-keystroke bus timing** (`esphome-aap-alarm-interface-logs-32.txt`): during code entry, digits arrive as two near-simultaneous pairs (e.g. digits 1+2 within ~1ms of each other, then a ~150–200ms gap, then digits 3+4 within ~1ms, then another gap before ENTER) rather than the smoothly user-paced single-digit spacing IP/AAP keypads show. This is the RS232 interface's own "enter code" prompt UI batching digits behind a confirm step before relaying them to the bus — not a bus collision or double-transmit — and shouldn't be misread as a protocol anomaly if seen again. +- **Confirms multi-user-code support:** the code used by Control4 to disarm differs from the code the IP Keypad and ESPHome integration use (both redacted) — the panel accepts more than one independently-valid user code. #### ARM_AWAY + DISARM with code (from logs-25) ```text diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index ffcb27e..7a7a1a1 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -299,6 +299,16 @@ The device's actual production config (`aap-esl2-keypad-interface/aap_esl_keypad **Practical takeaway:** if any future analysis needs to correlate a `CURRENT_TIME` broadcast's reported value against real-world wall-clock time precisely (rather than just "close enough to identify which session/date"), expect the panel's own value to read ~4–5 seconds ahead. +### Update (2026-08-10): third occurrence of correct-date/wrong-time-of-day recovery; corrupted content repeats identically across broadcasts + +**Source:** `traces/esphome-aap-alarm-interface-logs-32.txt`, `15:26:55.600`–`.409`, inside the registration-storm window described in the `Unknown [ff.]`/`[fe.]` section below. + +**Findings (observed facts):** two `CURRENT_TIME` glitch recoveries fire 809ms apart, both decoding the identical raw bytes `54.02.03.1F.01.14.10.34`. The recovered date (`2026-08-10`) is correct, but the resulting `Controller time update` logs a time-of-day of `13:19:01` — real time was ~`15:26`. This is the same class of gap flagged as open (not yet fixed) in `HANDOVER_2026-08-05.md`'s `logs-30` notes: the day/month/year halving-plus-weekday-cross-check recovery only validates the date fields, and `minutes_hi`/`minutes_lo` can independently be wrong even when it succeeds. New here: both occurrences share byte-for-byte identical raw content rather than each being independently garbled — suggesting whatever corrupts this broadcast during a registration storm can be sticky/deterministic for a given trigger, not purely random per-transmission. ~15s later (`15:27:10.619`) a third `CURRENT_TIME` broadcast in the same session fails validation outright (`invalid day/month value 40/32`) and is correctly discarded — consistent with existing discard behavior, no new issue. + +**Inference (low confidence, one session):** the wrong-minutes gap from `logs-30` recurs here in a different trigger context (registration storm rather than isolated), and the identical-bytes-twice detail is new — but with only a single session showing it, whether "deterministic per storm" holds beyond this instance isn't established. + +**Practical takeaway:** the `logs-30` handover note asking whether to fix the check ordering (so day/month recovery can fire independently of the unrelated `seconds` validation) remains open and unanswered — this session doesn't change the recommendation, just adds a third data point. No code change made. + ## `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. @@ -333,3 +343,20 @@ Whether the remaining corruption is a different manifestation of the same ISR-le ### Practical takeaway This does not currently appear to cause the `CODE_ENTER_PENDING` arm/disarm failures (those show clean silence, not corruption — see `arm_disarm_state_machine.md`). It's logged here as a distinct, still-open issue so it isn't mistaken for "fixed" in future investigations. No code change is proposed until a fresh raw capture isolates the exact edge/timing condition, per the same caution the original 2026-07-12 entry applied. + +### Update (2026-08-10): independent hardware confirms this is a real bus/controller-level event, not just an ISR-side artifact; two new trigger contexts; a new unlabeled `0x8A` packet + +**Source:** `traces/esphome-aap-alarm-interface-logs-31.txt`, `-32.txt`. Both sessions have four keypads live on the bus simultaneously (`AAP`, `ESPHome`, `Control 4` — Arrowhead's own official RS232 interface, see Snippet 4/5 above — and `IP`), with several arm/disarm cycles initiated directly from the `IP Keypad` and `Control 4 Keypad` (physical/RS232 key presses) rather than through our own integration. + +**Findings (observed facts):** + +- `logs-32`, `15:26:10.818`–`.451`: a 9-frame `Unknown [ff.]` burst. Immediately after, `Control 4 Keypad`'s and `IP Keypad`'s `KEYPAD_PING` polls go missing for ~5.3s (normal poll spacing between keypads is ~80–100ms), and the moment polling resumes, **`IP Keypad` sends its own `KEYPAD_REGISTRATION` announce** (`[IP Keypad] Registration [a0.07.00]`, `15:26:16.181`) — i.e. an independent hardware device, not our own decode, lost enough polls to fall off and re-announce. +- `logs-32`, `15:26:55.771`–`56.591`: a second instance — one `Unknown [fe.]` frame followed immediately by **our own** interface firing 5x "No ping for 60s, re-sending registration announce" in under 1s, mid-flight during an active Control4-initiated arm sequence. Two `CURRENT_TIME` glitch recoveries land inside this same window with a correct date but wrong time-of-day (see `CURRENT_TIME` section above). +- `logs-31`, `15:01:56.214`–`.726`: a third 9-frame `ff.` burst, this time immediately following an arm triggered by the `IP Keypad`'s own physical key sequence (not our own TX, and not a registration event) — a new trigger context distinct from both "our own TX/ACK exchange" (original 2026-07-12 entry) and "registration storm" (this update). +- `logs-31`, `15:01:39.528`: a single `Unknown [8a.03.02.00.82.00 (5)]` frame, landing exactly in the slot where `IP Keypad`'s `KEYPAD_COMMAND` echo of an `ARMED_AWAY` confirmation would be expected (`AAP`, `ESPHome`, `Control 4` all echoed normally immediately before it; `IP`'s echo never appears in its usual form). A second, previously unremarked `0x8A` frame was found in `logs-20.txt` (`8a.82.00.00.A0.00`, `14:37:09.771`) — but that one sits right after our own terminal-key TX completes, not in a missing-4th-echo position, so the two occurrences don't share a consistent context. + +**Inference (medium confidence on the registration-storm link; low confidence on `0x8A`):** the `logs-32` `IP Keypad` self-re-registration immediately after the `ff.` burst is the first evidence that this corruption is a real bus- or controller-level event with effects other devices independently observe, rather than an artifact confined to our own ISR/decode path — strengthening (without fully confirming) the "registration storm" association raised in `arm_disarm_state_machine.md`'s logs-46/25 entry, which the later logs-47/26 session had weakened for lack of a tight correlation. `0x8A` is seen too rarely (2 occurrences, inconsistent context) to assign a meaning; flagging it here as a distinct unlabeled packet type so it isn't confused with the `ff.`/`fe.` corruption signature if seen again. + +**Assumption (unverified):** whether `0x8A` is itself a corrupted decode of something else (like `ff.`/`fe.`) or a legitimate-but-rare packet type is not established. Whether the corruption mechanism is the same across all three trigger contexts now observed (our own TX, registration storms, another keypad's physical arm) or several distinct mechanisms sharing a symptom is likewise still open. + +**Practical takeaway:** no code change proposed. The registration-storm correlation is now real evidence rather than speculation, but still not proven causal (which direction, if either, is cause vs. effect isn't established) — worth deliberately targeting in a future capture (e.g. watching for `ff.`/`fe.` bursts specifically around forced re-registrations). `0x8A` should be logged if seen again but not acted on. From 3f2f8ef04bf4e6f4b573b1986d050d9d28e9040d Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Mon, 10 Aug 2026 16:10:32 +1200 Subject: [PATCH 3/8] fix(crow_alarm_panel): recover CURRENT_TIME date despite bad seconds Checking the seconds field before attempting day/month/year recovery meant a frame with a corrupted seconds byte skipped recovery entirely, even when day/month/year would have recovered cleanly on their own. Move the seconds check after the recovery attempt; the final time update log is still gated on seconds being valid, so no untrusted data gets logged, but the recovery path itself now fires as designed. --- components/crow_alarm_panel/crow_alarm_panel.cpp | 14 +++++++++----- .../docs/protocol_investigations.md | 2 ++ 2 files changed, 11 insertions(+), 5 deletions(-) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index 7ad5a8f..9248091 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -523,11 +523,6 @@ void CrowAlarmPanel::loop() { format_hex_pretty(data).c_str()); break; } - if (data[3] >= 60) { - ESP_LOGW(TAG, "[%-*s] Current time has invalid seconds value %u [%02x.%s]", this->keypad_label_width_, - CONTROLLER_LABEL, data[3], type, format_hex_pretty(data).c_str()); - break; - } uint8_t day = data[4]; uint8_t month = data[5]; uint8_t year = data[6]; @@ -564,6 +559,15 @@ void CrowAlarmPanel::loop() { break; } } + // Checked after the day/month recovery attempt above (not before) so a bad seconds value + // doesn't discard an otherwise-recoverable day/month/year — see protocol_investigations.md, + // the 2026-08-10 CURRENT_TIME update, for two sessions where this order previously discarded + // cleanly-recoverable date data alongside an unrelated bad seconds byte. + if (data[3] >= 60) { + ESP_LOGW(TAG, "[%-*s] Current time has invalid seconds value %u [%02x.%s]", this->keypad_label_width_, + CONTROLLER_LABEL, data[3], 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, year, month, day, hour, minute, data[3]); break; diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index 7a7a1a1..a6bb55d 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -309,6 +309,8 @@ The device's actual production config (`aap-esl2-keypad-interface/aap_esl_keypad **Practical takeaway:** the `logs-30` handover note asking whether to fix the check ordering (so day/month recovery can fire independently of the unrelated `seconds` validation) remains open and unanswered — this session doesn't change the recommendation, just adds a third data point. No code change made. +**Fix applied (2026-08-10):** `CURRENT_TIME` handling (`crow_alarm_panel.cpp`) now checks `seconds` *after* attempting the day/month/year recovery rather than before, so a frame with a corrupted `seconds` byte alongside a cleanly-recoverable `day`/`month`/`year` still fires the `ESP_LOGI` recovery path instead of being discarded before recovery is even attempted. The final `Controller time update` log line is still gated on `seconds` being valid (0–59) — this only fixes the completeness gap in *attempting* recovery, it does not start trusting an invalid `seconds` value. Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. Not yet validated on real hardware against a fresh case matching the `logs-30`/`logs-32` shape (bad `seconds`, recoverable date). + ## `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 6f2cc2f1a8461e13e03a494846bee011980ce83d Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 19 Aug 2026 09:05:05 +1200 Subject: [PATCH 4/8] docs(crow_alarm_panel): CURRENT_TIME glitch phase-locks to wall clock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 62h HA log: the mild variant fires overwhelmingly at seconds=0x0F, and glitch bursts recur within ~1s of the same wall-clock time 24h apart — consistent with a phase trigger anchored to the panel's own (stable, barely-offset) clock rather than random bus contention. --- .../docs/protocol_investigations.md | 40 +++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index a6bb55d..9bc744e 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -311,6 +311,46 @@ The device's actual production config (`aap-esl2-keypad-interface/aap_esl_keypad **Fix applied (2026-08-10):** `CURRENT_TIME` handling (`crow_alarm_panel.cpp`) now checks `seconds` *after* attempting the day/month/year recovery rather than before, so a frame with a corrupted `seconds` byte alongside a cleanly-recoverable `day`/`month`/`year` still fires the `ESP_LOGI` recovery path instead of being discarded before recovery is even attempted. The final `Controller time update` log line is still gated on `seconds` being valid (0–59) — this only fixes the completeness gap in *attempting* recovery, it does not start trusting an invalid `seconds` value. Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. Not yet validated on real hardware against a fresh case matching the `logs-30`/`logs-32` shape (bad `seconds`, recoverable date). +### Update (2026-08-19): 62-hour log shows glitch bursts recurring at the same wall-clock time on consecutive days — strengthens the "internal counter/schedule, not bus noise" hypothesis + +**Source:** `traces/home-assistant_2026-08-18T20-27-05.080Z.log`, a Home Assistant log spanning `2026-08-17 04:11:25` to `2026-08-19 08:26:55` (~62 hours) captured post-2026-08-10-fix, at HA's default log level (only `ESP_LOGI`/`ESP_LOGW` `CURRENT_TIME` lines are visible — no `ESP_LOGD` clean-decode lines to compute a glitch ratio against). + +**Findings (observed facts):** + +- Across the full log, `CURRENT_TIME` glitch-related lines total 2279 `recovered doubled-bit glitch` (day/month/year), 559 `invalid seconds value`, and 90 `invalid day/month value` (unrecoverable). The recoverable/unrecoverable split is consistent with prior sessions; nothing new there. +- The corrupted values are drawn from a small fixed set, not spread across the byte range: `invalid seconds value` is one of `{60, 61, 89, 90, 91}` in 557 of 559 occurrences (2 outliers: one `73`, one `100`). `invalid day/month value` is one of `{68/32, 72/32, 76/32}` in all 90 occurrences — `month` is *always* exactly `32`. +- Bucketing all glitch-line timestamps by hour-of-day shows near-identical counts 24 hours apart across the two full days in the log, e.g.: `05:00`→18/18, `08:00`→88/88, `09:00`→18/18, `12:00`→111/114, `13:00`→18/18, `16:00`→102/102, `21:00`→82/82, `22:00`→18/18, `23:00`→49/49 (Aug 17 vs Aug 18 respectively; full table not reproduced here). +- Individual glitch *bursts* line up to within ~1 second, 24 hours apart. E.g. the `05:xx` burst on both days: Aug 17 — `05:17:55`, `05:18:10`, `05:18:25`, `05:18:40`, `05:18:55`, `05:19:10`, `05:19:25`, `05:19:40`; Aug 18 — `05:17:54`, `05:18:09`, `05:18:25`, `05:18:39`, `05:18:55`, `05:19:10`, `05:19:25`, `05:19:40`. Same shape recurs at `05:50:54`–`05:51:39` both days too. + +**Inference (medium-high confidence):** random bus contention or EMI would not be expected to phase-lock a burst's onset to within ~1 second of real wall-clock time across a 24-hour gap, nor reproduce near-identical per-hour glitch counts two days running. This is a much stronger data point for the "internal broadcast counter" hypothesis raised in the 2026-08-05 update above (`glitch phase tied to broadcast count, not wall-clock seconds`) than the single-session evidence that hypothesis was originally based on — and points toward the glitch being tied to something that itself runs on a roughly-24h schedule (a periodic counter whose cycle length divides evenly enough into ~86400s to phase-lock, or a daily reset/rollover event on the panel), rather than to transient wiring/contention noise. Whether the trigger is purely internal to the panel (e.g. a scheduled self-test or status-report cycle) or an external environmental correlate (e.g. another device on the same daily schedule perturbing the bus) is not distinguishable from this log alone. + +**Assumption (unverified):** the exact mechanism tying the glitch to time-of-day — panel-internal schedule vs. external daily-cycling interference source — is not established. Confirming either would need either panel documentation/firmware insight (not available) or correlating burst onsets against other known daily-scheduled activity in the installation (HVAC, irrigation, etc.), which hasn't been attempted. + +**Practical takeaway:** no code change proposed — the existing day/month/year recovery already handles the recoverable case regardless of *why* it recurs, and `seconds` is still correctly discarded when invalid. This is logged here because it directly answers the open question from the 2026-08-05 update about whether the "severe" (near-every-broadcast) glitch variant is triggered/contention-driven or schedule-driven: the day-over-day phase-lock evidence here favors schedule/counter-driven ("by design", in the sense of being a deterministic property of the panel's own broadcast logic) over bus contention. + +### Update (2026-08-19, cont.): dominant trigger is still `seconds = 0x0F` (15) — the day-over-day match is better explained by that per-minute phase plus a stable clock offset than by a literal daily schedule + +**Findings (observed facts):** decoding `data[3]` (the `seconds` byte) for every `recovered doubled-bit glitch` line in the same log whose `seconds` value itself was *not* also corrupted (1721 of the 2279 recovered events; the other 558 pair with an `invalid seconds value` line off the same frame, per the previous entry) gives this distribution: + +| `seconds` byte | Count | Share | +| --- | --- | --- | +| `0x0F` (15) | 736 | 43% | +| `0x17` (23) | 341 | 20% | +| `0x1B` (27) | 176 | 10% | +| `0x1E` (30) | 143 | 8% | +| `0x00` (0) | 144 | 8% | +| `0x01` (1) | 90 | 5% | +| `0x1D` (29) | 88 | 5% | +| `0x0E` (14) / `0x2F` (47) | 1 / 2 | <1% | + +`0x0F` (15) is the single largest bucket by a wide margin — nearly 2.2x the next most common value — matching (not superseding) the original `protocol_trace_2026-04-12_time_setting.md`/2026-08-05 characterization of the mild variant firing "always at the `seconds = 0x0F` (15s) broadcast." The other values above are not random scatter either: `arm_disarm_state_machine.md`-style phase shifts (documented in the 2026-08-05 "glitch phase tied to broadcast count" update, where a registration event shifted the glitch's `seconds` phase from 15 to 23 for the rest of that session) plausibly account for the `23`/`27`/`30` clusters as the same per-cycle trigger recurring at a shifted phase after similar mid-session events, though this hasn't been individually traced per burst here. + +**Inference (revises the previous entry's framing):** this changes what the day-over-day burst-timing match most likely indicates. The trigger is best described as tied to the panel's own broadcast-cycle *phase* (predominantly, but not exclusively, "the broadcast where its internal clock reads `:15` seconds"), not to wall-clock time directly. Combined with the already-documented, stable ~4.4s-fast panel clock offset (2026-08-05 update — a fixed bias, not accumulating drift), a phase trigger recurring every cycle would land at very nearly the same real-world clock time from one day to the next *on its own*, with no need to additionally posit a literal calendar/24h-scheduled event on the panel. In other words: the previous entry's "roughly-24h schedule" framing was more speculative than necessary — a per-minute (or per-broadcast-count) phase trigger plus a non-drifting clock is sufficient to produce the observed ~1-second day-over-day alignment. + +This does *not* explain why the "severe" behavior (multiple corrupted broadcasts clustering into a several-minute burst, rather than the mild variant's steady one-per-minute) itself only occurs in specific windows through the day rather than continuously — that part of the original question is still open and isn't addressed by the `seconds` phase data alone. + +**Practical takeaway:** narrows, rather than replaces, the previous entry's conclusion — still "by design" in the sense of being deterministic and tied to the panel's own clock/broadcast logic rather than random bus noise, but the day-over-day recurrence specifically is adequately explained by (per-cycle phase trigger) + (stable clock offset), so it shouldn't be read as independent evidence of a separate daily-scheduled trigger condition. No code change proposed. + ## `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 fae38e7db47cc5d5b69c66d2d127e605ee65fe79 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 19 Aug 2026 09:05:38 +1200 Subject: [PATCH 5/8] fix(crow_alarm_panel): quiet frequent, benign CURRENT_TIME glitch logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The doubled-bit glitch (day/month/year, seconds) fires up to hundreds of times/hour and is a known, expected panel behavior, not a bus fault — CURRENT_TIME also isn't published to any entity. Drop the recovered/ invalid-seconds/invalid-day-month lines from INFO/WARN to DEBUG so they stop cluttering HA's log while staying available for protocol work. --- components/crow_alarm_panel/crow_alarm_panel.cpp | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index 9248091..8cf2f4c 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -535,6 +535,12 @@ void CrowAlarmPanel::loop() { // 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. + // + // This glitch is frequent (up to hundreds of occurrences/hour — see the 2026-08-19 + // protocol_investigations.md update) and, per that update, an expected/benign property of + // the panel's own broadcast logic rather than a bus fault — and CURRENT_TIME isn't published + // to any entity, so none of this is user-actionable. Logged at DEBUG, same level as the + // successful decode below, to avoid spamming WARN/INFO on every occurrence. bool recovered = false; if ((data[4] % 2) == 0 && (data[5] % 2) == 0 && (data[6] % 2) == 0) { uint8_t rec_day = data[4] / 2; @@ -542,7 +548,7 @@ void CrowAlarmPanel::loop() { 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, + ESP_LOGD(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()); @@ -553,7 +559,7 @@ void CrowAlarmPanel::loop() { } } if (!recovered) { - ESP_LOGW(TAG, "[%-*s] Current time has invalid day/month value %u/%u [%02x.%s]", + ESP_LOGD(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; @@ -564,7 +570,8 @@ void CrowAlarmPanel::loop() { // the 2026-08-10 CURRENT_TIME update, for two sessions where this order previously discarded // cleanly-recoverable date data alongside an unrelated bad seconds byte. if (data[3] >= 60) { - ESP_LOGW(TAG, "[%-*s] Current time has invalid seconds value %u [%02x.%s]", this->keypad_label_width_, + // Same known glitch family as above (frequent, benign, unpublished) — DEBUG, not WARN. + ESP_LOGD(TAG, "[%-*s] Current time has invalid seconds value %u [%02x.%s]", this->keypad_label_width_, CONTROLLER_LABEL, data[3], type, format_hex_pretty(data).c_str()); break; } From e14a21594df7acd04d145d94eaa7c5209caa5a85 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 19 Aug 2026 14:27:17 +1200 Subject: [PATCH 6/8] docs(crow_alarm_panel): logs-33 confirms auto-retry, no new failure mode Two disarms hit the known CODE_ENTER_PENDING silence signature and recovered on the first automatic retry, same shape as logs-27. --- components/crow_alarm_panel/docs/arm_disarm_state_machine.md | 2 ++ 1 file changed, 2 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 930e722..8668310 100644 --- a/components/crow_alarm_panel/docs/arm_disarm_state_machine.md +++ b/components/crow_alarm_panel/docs/arm_disarm_state_machine.md @@ -436,6 +436,8 @@ Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. **No 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. +**Further confirmed (2026-08-19, logs-33):** `esphome-aap-alarm-interface-logs-33.txt`, four arm/disarm cycles in a ~14-minute session (`14:06`–`14:20`). All four arms completed cleanly on the first attempt. Two of the four disarms (`14:08:36.196`, `14:20:00.756`) hit the ordinary `CODE_ENTER_PENDING` silence signature — terminal key acked (`CMD 0x07`), then genuine bus silence, 1s watchdog fires `Arm/disarm: timeout in state 4, retrying (1/5)`, full code+terminal sequence resent, succeeds immediately on the retry with no user action. Same shape as the logs-27 validation above, one retry each instead of two, still 100% eventual success. No new failure mechanism, no code change proposed. + ## Notes - ARM/STAY/DISARM sequences are simpler than OUTPUT because there's no ACK handshake From a3343eaa210867cbc33583e78f25293acde316e6 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 19 Aug 2026 19:48:43 +1200 Subject: [PATCH 7/8] docs(crow_alarm_panel): fix stale review-flagged claims Reconciles protocol_investigations.md with the actual state of the code on this branch: the check-ordering fix was already applied (not still open), and the recovery/invalid-seconds/invalid-day-month CURRENT_TIME logs moved from ESP_LOGI to ESP_LOGD in a later commit, so the HA-default-log-level capture notes needed a caveat for future readers trying to reproduce them. Co-Authored-By: Claude Sonnet 5 --- components/crow_alarm_panel/docs/protocol_investigations.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/components/crow_alarm_panel/docs/protocol_investigations.md b/components/crow_alarm_panel/docs/protocol_investigations.md index 9bc744e..39fc98e 100644 --- a/components/crow_alarm_panel/docs/protocol_investigations.md +++ b/components/crow_alarm_panel/docs/protocol_investigations.md @@ -307,13 +307,13 @@ The device's actual production config (`aap-esl2-keypad-interface/aap_esl_keypad **Inference (low confidence, one session):** the wrong-minutes gap from `logs-30` recurs here in a different trigger context (registration storm rather than isolated), and the identical-bytes-twice detail is new — but with only a single session showing it, whether "deterministic per storm" holds beyond this instance isn't established. -**Practical takeaway:** the `logs-30` handover note asking whether to fix the check ordering (so day/month recovery can fire independently of the unrelated `seconds` validation) remains open and unanswered — this session doesn't change the recommendation, just adds a third data point. No code change made. +**Practical takeaway:** this session adds a third data point supporting the `logs-30` handover note's suggestion to fix the check ordering (so day/month recovery can fire independently of the unrelated `seconds` validation). See "Fix applied" below — the check-ordering change was made as part of this update. -**Fix applied (2026-08-10):** `CURRENT_TIME` handling (`crow_alarm_panel.cpp`) now checks `seconds` *after* attempting the day/month/year recovery rather than before, so a frame with a corrupted `seconds` byte alongside a cleanly-recoverable `day`/`month`/`year` still fires the `ESP_LOGI` recovery path instead of being discarded before recovery is even attempted. The final `Controller time update` log line is still gated on `seconds` being valid (0–59) — this only fixes the completeness gap in *attempting* recovery, it does not start trusting an invalid `seconds` value. Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. Not yet validated on real hardware against a fresh case matching the `logs-30`/`logs-32` shape (bad `seconds`, recoverable date). +**Fix applied (2026-08-10):** `CURRENT_TIME` handling (`crow_alarm_panel.cpp`) now checks `seconds` *after* attempting the day/month/year recovery rather than before, so a frame with a corrupted `seconds` byte alongside a cleanly-recoverable `day`/`month`/`year` still fires the recovery path (logged at `ESP_LOGD`, quieted from `ESP_LOGI` in a later commit on this branch — see the 2026-08-19 update below) instead of being discarded before recovery is even attempted. The final `Controller time update` log line is still gated on `seconds` being valid (0–59) — this only fixes the completeness gap in *attempting* recovery, it does not start trusting an invalid `seconds` value. Compiles and passes `esphome compile` against `crow_alarm_panel_test.yaml`. Not yet validated on real hardware against a fresh case matching the `logs-30`/`logs-32` shape (bad `seconds`, recoverable date). ### Update (2026-08-19): 62-hour log shows glitch bursts recurring at the same wall-clock time on consecutive days — strengthens the "internal counter/schedule, not bus noise" hypothesis -**Source:** `traces/home-assistant_2026-08-18T20-27-05.080Z.log`, a Home Assistant log spanning `2026-08-17 04:11:25` to `2026-08-19 08:26:55` (~62 hours) captured post-2026-08-10-fix, at HA's default log level (only `ESP_LOGI`/`ESP_LOGW` `CURRENT_TIME` lines are visible — no `ESP_LOGD` clean-decode lines to compute a glitch ratio against). +**Source:** `traces/home-assistant_2026-08-18T20-27-05.080Z.log`, a Home Assistant log spanning `2026-08-17 04:11:25` to `2026-08-19 08:26:55` (~62 hours) captured post-2026-08-10-fix but pre-2026-08-19-log-level-change, at HA's default log level (only `ESP_LOGI`/`ESP_LOGW` `CURRENT_TIME` lines are visible — no `ESP_LOGD` clean-decode lines to compute a glitch ratio against). As of the log-level change documented below, the recovery/invalid-seconds/invalid-day-month lines analyzed here are now `ESP_LOGD` and won't appear at HA's default log level in future captures — reproducing this analysis requires raising the log level. **Findings (observed facts):** From be55d9a954a39cfd95fa84169b5a8c3133ad35d8 Mon Sep 17 00:00:00 2001 From: dan-s-github Date: Wed, 19 Aug 2026 21:02:24 +1200 Subject: [PATCH 8/8] fix(crow_alarm_panel): rate-limit registration-announce resends No-ping watchdog could flip registration_sent_ false->true every loop() iteration while last_ping_ms_ stayed stale, re-sending the registration announce on every pass instead of backing off (a real capture on 2026-08-19 showed 6 resends within ~1s). Guard resends with a minimum interval, matching the MIN_TX_INTERVAL_MS pattern used elsewhere in this file. Compiles and passes esphome compile against crow_alarm_panel_test.yaml. Not yet validated on real hardware. Co-Authored-By: Claude Sonnet 5 --- components/crow_alarm_panel/crow_alarm_panel.cpp | 4 +++- components/crow_alarm_panel/crow_alarm_panel.h | 6 ++++++ 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/components/crow_alarm_panel/crow_alarm_panel.cpp b/components/crow_alarm_panel/crow_alarm_panel.cpp index 8cf2f4c..e059ee6 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.cpp +++ b/components/crow_alarm_panel/crow_alarm_panel.cpp @@ -969,12 +969,14 @@ void CrowAlarmPanel::loop() { ESP_LOGW(TAG, "No ping for 60 s, re-sending registration announce"); this->registration_sent_ = false; } - if (!this->registration_sent_ && now_ms >= this->registration_after_ms_ && this->is_bus_idle_()) { + if (!this->registration_sent_ && now_ms >= this->registration_after_ms_ && this->is_bus_idle_() && + (now_ms - this->last_registration_announce_ms_) >= REGISTRATION_ANNOUNCE_MIN_INTERVAL_MS) { CrowAlarmPanelKeypad keypad = this->find_keypad_(this->keypad_address_); ESP_LOGW(TAG, "[%-*s] Sending registration announce", this->keypad_label_width_, keypad_label(keypad, this->keypad_address_).c_str()); this->send_packet(KEYPAD_REGISTRATION, {0x00}); this->registration_sent_ = true; + this->last_registration_announce_ms_ = now_ms; } } } diff --git a/components/crow_alarm_panel/crow_alarm_panel.h b/components/crow_alarm_panel/crow_alarm_panel.h index 0768c9d..1617a9d 100644 --- a/components/crow_alarm_panel/crow_alarm_panel.h +++ b/components/crow_alarm_panel/crow_alarm_panel.h @@ -294,6 +294,12 @@ class CrowAlarmPanel : public Component { // Watchdog: track last time the controller polled us; re-register if silent for 60 s. uint32_t last_ping_ms_{0}; + // Minimum spacing between registration-announce resends triggered by the no-ping watchdog + // above. Without this, registration_sent_ flips false->true every loop() iteration while + // last_ping_ms_ stays stale (no KEYPAD_PING arriving to advance it), re-sending on every pass + // instead of backing off — observed firing 6x within ~1s in a real capture (2026-08-19). + static const uint32_t REGISTRATION_ANNOUNCE_MIN_INTERVAL_MS = 1000; + uint32_t last_registration_announce_ms_{0}; // Output-select state machine. OutputSelectState output_select_state_{OutputSelectState::IDLE};