Arm/disarm retry pacing, frame-FIFO fix, and protocol doc updates

components/crow_alarm_panel/crow_alarm_panel.cpp

@@ -20,8 +20,10 @@ void CrowAlarmPanelStore::setup(InternalGPIOPin *clock_pin, InternalGPIOPin *dat
   this->clock_pin_ = clock_pin->to_isr();
   this->data_pin_ = data_pin->to_isr();
   memset(this->buffer, 0, sizeof(this->buffer));
-  memset(this->buffer2, 0, sizeof(this->buffer2));
-  this->data_length = 0;
+  memset(this->frame_queue_, 0, sizeof(this->frame_queue_));
+  memset(this->frame_queue_len_, 0, sizeof(this->frame_queue_len_));
+  this->frame_head_ = 0;
+  this->frame_tail_ = 0;
   this->num_bits_ = 0;
   this->boundary_buffer_ = 0;
   clock_pin->attach_interrupt(CrowAlarmPanelStore::interrupt, this, gpio::INTERRUPT_FALLING_EDGE);
@@ -171,9 +173,30 @@ void IRAM_ATTR HOT CrowAlarmPanelStore::interrupt(CrowAlarmPanelStore *arg) {
     arg->num_bits_++;
 
     if (arg->boundary_buffer_ == BOUNDARY) {
-      //  Save data
-      memcpy(arg->buffer2, arg->buffer, arg->num_bits_ / 8);
-      arg->data_length = arg->num_bits_ / 8;
+      const uint8_t frame_len = arg->num_bits_ / 8;
+      // ACK decision fields, captured before the buffer reset below.
+      // buffer[0]=type, buffer[1]=addr (for addressed types), buffer[frame_len-1]=0x7E.
+      const uint8_t frame_type = arg->buffer[0];
+      const uint8_t frame_addr = arg->buffer[1];
+      //  Save the frame into the queue (see the queue's ownership-protocol comment in the
+      //  header). pending is computed before the head increment, so pending > 0 means this
+      //  frame completed while an earlier one was still unconsumed (counted as backlog below).
+      //  Zero-length frames (boundary matched with < 8 bits accumulated, i.e. noise) are
+      //  skipped without queueing.
+      const uint8_t pending = (uint8_t) (arg->frame_head_ - arg->frame_tail_);
+      if (frame_len == 0) {
+        // fall through to the reset below
+      } else if (pending < FRAME_QUEUE_LENGTH) {
+        const uint8_t slot = arg->frame_head_ & (FRAME_QUEUE_LENGTH - 1);
+        memcpy(arg->frame_queue_[slot], arg->buffer, frame_len);
+        arg->frame_queue_len_[slot] = frame_len;
+        arg->frame_head_++;
+        if (pending > 0) {
+          arg->frame_backlog_events_++;
+        }
+      } else {
+        arg->frame_overflow_events_++;
+      }
       //  Reset
       memset(arg->buffer, 0, BUFFER_LENGTH);
       arg->boundary_buffer_ = 0;
@@ -182,12 +205,14 @@ void IRAM_ATTR HOT CrowAlarmPanelStore::interrupt(CrowAlarmPanelStore *arg) {
       arg->data = false;
       // Hardware ACK: drive DAT low for one clock cycle only for per-keypad frame types
       // addressed to us. Broadcast frame payload bytes must never be treated as an address.
-      // buffer2[0]=type, buffer2[1]=addr (for addressed types), buffer2[data_length-1]=0x7E.
-      if (arg->data_length >= 3) {
-        const uint8_t type = arg->buffer2[0];
-        const bool addressed_type = (type == KEYPAD_COMMAND || type == KEYPAD_STATE || type == OUTPUT_SELECT_ACK ||
-                                     type == KEYPAD_PING || type == BYPASS_STATUS);
-        if (addressed_type && arg->buffer2[1] == arg->ack_keypad_address_) {
+      // Deliberately unconditional on the queue outcome: an overflow-dropped frame is still
+      // ACKed — withholding the ACK would trigger the controller's rapid-retransmission mode
+      // instead (logs-11/36).
+      if (frame_len >= 3) {
+        const bool addressed_type = (frame_type == KEYPAD_COMMAND || frame_type == KEYPAD_STATE ||
+                                     frame_type == OUTPUT_SELECT_ACK || frame_type == KEYPAD_PING ||
+                                     frame_type == BYPASS_STATUS);
+        if (addressed_type && frame_addr == arg->ack_keypad_address_) {
           arg->data_pin_.pin_mode(gpio::FLAG_OUTPUT);
           arg->data_pin_.digital_write(0);
           arg->ack_set_time_us_ = now;
@@ -286,24 +311,35 @@ void CrowAlarmPanel::loop() {
     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);
-      InterruptLock lock;
-      memset(this->store_.buffer2, 0, BUFFER_LENGTH);
-      this->store_.data_length = 0;
+  if (this->store_.frame_head_ != this->store_.frame_tail_) {
+    // Pop one frame per loop() pass. Copy the slot out first, then release it back to the ISR
+    // with the tail increment — no lock, per the queue's ownership-protocol comment in the
+    // header (InterruptLock is core-local and never protected this cross-core handoff anyway).
+    const uint8_t slot = (uint8_t) (this->store_.frame_tail_ & (CrowAlarmPanelStore::FRAME_QUEUE_LENGTH - 1));
+    const uint8_t frame_len = this->store_.frame_queue_len_[slot];
+    uint8_t local_frame[BUFFER_LENGTH];
+    memcpy(local_frame, this->store_.frame_queue_[slot], BUFFER_LENGTH);
+    this->store_.frame_tail_++;
+
+    const uint16_t backlog = this->store_.frame_backlog_events_;
+    if (backlog != this->frame_backlog_reported_) {
+      ESP_LOGD(TAG, "Frame completed while previous still queued: %u total", backlog);
+      this->frame_backlog_reported_ = backlog;
+    }
+    const uint16_t overflow = this->store_.frame_overflow_events_;
+    if (overflow != this->frame_overflow_reported_) {
+      ESP_LOGW(TAG, "Frame queue overflow, frame(s) dropped: %u total", overflow);
+      this->frame_overflow_reported_ = overflow;
+    }
+
+    if (frame_len < 2) {
+      ESP_LOGW(TAG, "Discarding short frame (%d bytes)", frame_len);
       return;
     }
 
-    uint8_t type;
+    uint8_t type = local_frame[0];
     std::vector<uint8_t> data;
-    {
-      InterruptLock lock;
-      type = this->store_.buffer2[0];
-      data.insert(data.begin(), this->store_.buffer2 + 1, this->store_.buffer2 + this->store_.data_length - 1);
-      memset(this->store_.buffer2, 0, BUFFER_LENGTH);
-      this->store_.data_length = 0;
-    }
+    data.insert(data.begin(), local_frame + 1, local_frame + frame_len - 1);
 
     if (this->raw_frame_logging_enabled_) {
       ESP_LOGI(TAG, "Received raw frame [%02x.%s]", type, format_hex_pretty(data).c_str());

components/crow_alarm_panel/crow_alarm_panel.h

@@ -115,8 +115,22 @@ class CrowAlarmPanelStore {
   static void interrupt(CrowAlarmPanelStore *arg);
 
   uint8_t buffer[BUFFER_LENGTH];
-  uint8_t buffer2[BUFFER_LENGTH];
-  uint8_t data_length{0};
+
+  // Completed-frame queue: ISR (core 0) produces, loop() (core 1) consumes. No lock needed
+  // (InterruptLock is core-local): the ISR only writes to free slots (frame_head_ - frame_tail_ <
+  // FRAME_QUEUE_LENGTH) and publishes via frame_head_++; loop() only reads slot [frame_tail_] and
+  // releases it via frame_tail_++ after copying it out. Head/tail are free-running uint8_t
+  // counters (queue length divides 256, so wraparound is safe); slot index is
+  // counter & (FRAME_QUEUE_LENGTH - 1).
+  static const uint8_t FRAME_QUEUE_LENGTH = 4;  // must be a power of two
+  uint8_t frame_queue_[FRAME_QUEUE_LENGTH][BUFFER_LENGTH];
+  uint8_t frame_queue_len_[FRAME_QUEUE_LENGTH];
+  volatile uint8_t frame_head_{0};
+  volatile uint8_t frame_tail_{0};
+  // backlog: frame completed while the previous one was still queued. overflow: frame dropped
+  // because the queue was full (expected to stay 0 in practice).
+  volatile uint16_t frame_backlog_events_{0};
+  volatile uint16_t frame_overflow_events_{0};
 
   bool data{false};
   uint32_t last_clock_time_{0};             // Track last clock edge
@@ -310,6 +324,11 @@ class CrowAlarmPanel : public Component {
   void send_packet_blocking_(const std::vector<uint8_t> &packet);
   bool wait_for_clock_edge_(bool wait_for_state, uint32_t timeout_us);
 
+  // Last frame-queue diagnostic counter values already reported to the log, so loop() emits
+  // one line per counter change instead of spamming every pass.
+  uint16_t frame_backlog_reported_{0};
+  uint16_t frame_overflow_reported_{0};
+
   // One-shot registration announce sent after boot delay.
   bool registration_sent_{false};
   uint32_t registration_after_ms_{15000};

components/crow_alarm_panel/docs/arm_disarm_state_machine.md

@@ -254,7 +254,7 @@ Three distinct failure patterns observed when arm/disarm doesn't work:
 
 ## Digit-ack byte is keypad-address-specific, not a validity signal (2026-07-08)
 
-**Observed facts** (`esphome-aap-alarm-interface-logs-7.txt`, `esphome-aap-keypad-monitor-logs-33.txt`, captured simultaneously from the active interface and a passive monitor): across four separate code-entry attempts (2 disarm, 2 arm-away) by the ESPHome virtual keypad (address `0x05`), the controller's response to the *first* code digit was `Command [14.05.07...]` (byte[1] = `0x07`) every single time — never `0x01`. In the same window, a manual disarm entered on the physical IP keypad (address `0x07`) got byte[1] = `0x01` on every digit and completed successfully with the *same* code (`4286`, confirmed against `secrets.yaml`). The `0x07` responses occurred both while armed (`armed_state` byte = `0x01`, during disarm) and while disarmed (`armed_state` byte = `0x00`, during the subsequent arm attempts), ruling out an "alarm-pending" explanation tied to armed state.
+**Observed facts** (`esphome-aap-alarm-interface-logs-7.txt`, `esphome-aap-keypad-monitor-logs-33.txt`, captured simultaneously from the active interface and a passive monitor): across four separate code-entry attempts (2 disarm, 2 arm-away) by the ESPHome virtual keypad (address `0x05`), the controller's response to the *first* code digit was `Command [14.05.07...]` (byte[1] = `0x07`) every single time — never `0x01`. In the same window, a manual disarm entered on the physical IP keypad (address `0x07`) got byte[1] = `0x01` on every digit and completed successfully with the *same* code (confirmed identical to the entry sent by the ESPHome keypad, cross-checked against `secrets.yaml`; value redacted here). The `0x07` responses occurred both while armed (`armed_state` byte = `0x01`, during disarm) and while disarmed (`armed_state` byte = `0x00`, during the subsequent arm attempts), ruling out an "alarm-pending" explanation tied to armed state.
 
 **Inference (medium confidence — 4 consistent observations, single session):** byte[1] of `KEYPAD_COMMAND` in the digit-ack context is a per-keypad-address display code (LED/beep style), not a code-correctness signal. Different keypad types/addresses apparently use different codes for the same "digit accepted, more expected" semantic — address `0x05` uses `0x07` where the IP keypad uses `0x01`. This is consistent with `protocol_wire_format.md`'s `display_code` table describing byte[1] as display/mode instructions, not a validation result, and with the fact that the controller only appears to check code correctness at ENTER (per keypad_protocol_types.md: "Invalid code: Controller timeout ~10s, then reject" — no per-digit rejection documented for the IP keypad).
 
@@ -533,6 +533,53 @@ The previous code had the same recognition gap (unknown patterns were logged and
 this is not a regression, but a stay-mode capture confirming the actual broadcast bytes would
 settle it.
 
+## User-reported field pattern: disarm reliable right after arming, retries after hours armed (2026-08-31)
+
+**Source:** user report from real-world usage (not a scripted trace session), checked against the frigate long-term logger ([[project-crow-alarm-protocol-trace]]) for 2026-08-31 01:42–01:44 **UTC** (the logger stamps lines in UTC regardless of the host's local NZST clock — see the `protocol_investigations.md` `Unknown [91.]` entry's 2026-08-31 update for how that was confirmed).
+
+**Observed facts:** in the corroborating window, the panel had been armed away since sometime before `18:33:56` on 2026-08-30 (its last confirmed `Disarmed` broadcast before that) — armed via a physical keypad, not this integration's `arm_away()` (no `Arm away` trigger line appears anywhere earlier in the visible log). The `01:42:07` `disarm()` call against that multi-hour-armed state hit the full `CODE_ENTER_PENDING` retry sequence — 6/6 retries, ~42s to resolve, backoff 1s→13s — before a genuine `Disarmed` `ARMED_STATE` broadcast confirmed it. Two follow-up cycles run through this integration immediately after (`01:43:02` arm away → `01:43:34` disarm, 32s later; `01:43:56` arm away) both resolved on the first attempt with no retries at all.
+
+**Relation to prior findings:** this does not contradict "Gap-timing lead conclusively dead" (2026-08-05, logs-44/23) above — that investigation tested gaps of single- to double-digit *seconds* within rapid scripted arm/disarm test cycles and found no correlation at that scale. It never tested an armed period of *hours*, since every prior trace session was a short deliberate test run; a multi-hour armed duration is a distinct, untested variable.
+
+**Inference (low confidence — one paired example, plus a user-reported recurring pattern):** consistent with the existing "session-level bad state"/controller-degradation theory (2026-08-19 episode, "Retry backoff + intent-matched ARMED_STATE resolution" above) if degradation episodes become more likely the longer the controller/bus has been running in a given state — but equally consistent with something disarm-specific (e.g. the controller doing different internal bookkeeping for a disarm request after being armed a long time vs. moments after arming). This single example doesn't distinguish between the two.
+
+**Possible shared cause:** `protocol_investigations.md`'s `CURRENT_TIME` section has a 2026-08-31 update describing the panel stuck continuously broadcasting an invalid `day/month value 31/16` from `11:59:55` UTC on 2026-08-30 onward — still ongoing as of the last check, `18:33:56`'s last-disarmed timestamp and the `01:42:07` failed disarm both fall inside that window. If the panel is genuinely in an abnormal internal state for that whole span (rather than this being routine per-broadcast noise), it's a plausible shared root cause for both symptoms — see that entry for the reasoning and its own caveats. Not proven; a disarm attempted while that stuck state is still active would be the next useful data point either way.
+
+**Practical takeaway:** worth deliberately capturing next: a disarm attempt following a known multi-hour armed period, with a note of exactly how long the panel had been armed, to build more than one data point. No code change proposed — the existing retry/backoff machinery already handles this case correctly (resolved in 42s here); this is purely an open root-cause question.
+
+### Update (2026-09-03): five more days of frigate data — "armed for hours" alone doesn't predict retries; the `CURRENT_TIME`-stuck correlation holds up better
+
+**Source:** the frigate long-term logger, full range 2026-08-30 through 2026-09-03 08:32 UTC ([[project-crow-alarm-protocol-trace]]). Every `alarm_control_panel` state transition in that window was pulled and matched against the `Arm away`/`Arm stay`/`Disarm` `[I]` log lines that mark an integration-initiated (vs. physical-keypad-initiated) sequence, then cross-checked against `CURRENT_TIME` decode status at the same moment.
+
+**Observed facts — every integration-initiated disarm in the window, with armed duration and retry outcome:**
+
+| Disarm (UTC) | Armed since | Duration armed | Retries | `CURRENT_TIME` at disarm |
+| --- | --- | --- | --- | --- |
+| 08-31 01:42:07 | 08-30 18:59:14 (physical arm) | ~6h43m | **6/6, ~42s** | stuck `31/16` (confirmed) |
+| 08-31 01:43:34 | 08-31 01:43:02 (`arm_away`) | ~3s | none, instant | still stuck `31/16` (confirmed) |
+| 09-01 18:27:49 | 09-01 17:47:35 (physical arm) | ~40m | **3/6, ~11s** | unknown — debug logging was off 09-01 06:26–18:52:09, spans this event |
+| 09-01 23:20:34 | 09-01 18:52:47 (physical arm) | ~4h28m | none, instant | normal, confirmed (`Controller time update` broadcasting correctly at 23:15–23:26) |
+| 09-02 23:57:28 | 09-02 18:31:44 (physical arm) | ~5h26m | none, instant | normal, confirmed (post-fix, `7e8044f` OTA'd, raw trace running the whole time) |
+
+**Inference (medium confidence — revises the 2026-08-31 entry above):** duration-since-arming alone is not the predictor — the ~40m case retried while both multi-hour cases (4h28m, 5h26m) resolved instantly. The `CURRENT_TIME`-stuck correlation from the "Possible shared cause" note above holds up better with this larger sample: the one case with *confirmed* stuck time retried (full 6/6), and the two cases with *confirmed* normal time — including one armed for 5h26m — both resolved instantly. The 40m/retry case can't confirm or refute either theory since debug logging (which gates the `CURRENT_TIME` decode warnings) happened to be off for that entire window; it's a missing data point, not a counterexample. The 3s/instant case is a genuine wrinkle: `CURRENT_TIME` was confirmed still stuck at that moment yet the disarm resolved cleanly on the first try — so "stuck time present" isn't sufficient on its own to force a retry, only (so far) correlated with the cases that did retry. Possibly retry-triggering requires the stuck condition to coincide with the specific bus exchange the state machine is waiting on, which a 3-second-old arm sequence may not have had time to hit.
+
+**Practical takeaway:** no code change proposed. The next useful data point is a disarm attempted with `CURRENT_TIME` decode status *known* at the moment of the call (i.e., debug logging on) that either retries with time stuck, or retries with time confirmed normal — either would sharpen this considerably. Given debug + raw trace are now left on for extended stretches post-`7e8044f`, this should arrive naturally in future capture windows without a dedicated test.
+
+### Update (2026-09-05): two more disarms, both instant/no-retry with `CURRENT_TIME` confirmed normal — no new wrinkle, reinforces the 2026-09-03 correlation
+
+**Source:** the frigate long-term logger, window 2026-09-03 08:36 → 2026-09-04 23:36 UTC.
+
+**Observed facts:** two full arm/disarm cycles occurred in this window:
+
+| Disarm (UTC) | Initiator | Armed since | Duration armed | Retries | `CURRENT_TIME` at disarm |
+| --- | --- | --- | --- | --- | --- |
+| 09-03 19:50:10 | physical (`AAP Keypad`, code+ENTER) | 09-03 18:03:11 (`arm_away`) | ~1h47m | none, instant | normal (glitch recovered cleanly to the correct date/time same second) |
+| 09-04 20:49:05 | integration (`disarm()`, `ESPHome Keypad`) | 09-04 20:11:57 (physical arm) | ~37m | none, instant | normal, confirmed (`Controller time update` broadcasting correctly seconds before and after) |
+
+**Inference (medium confidence, consistent with the 2026-09-03 entry above, not new):** both cases have `CURRENT_TIME` confirmed normal and both resolved instantly with zero retries, regardless of who initiated them (physical keypad vs. integration) or how long the panel had been armed (1h47m vs. 37m) — fitting neatly into the existing "normal time → instant disarm" bucket from the table above rather than adding a new data point for the harder "stuck time" side of the correlation. No `CURRENT_TIME` `31/16`-style stuck state occurred anywhere in this ~39h window (0 occurrences), so no retry case was available to test this session.
+
+**Practical takeaway:** no code change proposed. Still waiting on a disarm that coincides with a confirmed-stuck `CURRENT_TIME` state to further test the correlation — none occurred in this window.
+
 ## Notes
 
 - ARM/STAY/DISARM sequences are simpler than OUTPUT because there's no ACK handshake