jaguar2/examples: survive a failed register read under co-channel load

docs/logging.md

@@ -101,8 +101,9 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets];
 | `rx.path` | RX (`DEVOURER_RX_ALLPATHS`) | seq, rssi[4], snr[4], evm[4] |
 | `rx.path_mask` | L (toggle spec) | t, mask "0xNN" |
 | `rx.scrambler` | RX (`DEVOURER_DUMP_SCRAMBLER`) | seed "0xNN", rate, hits, len |
-| `rx.energy` | RX (`DEVOURER_RX_ENERGY_MS` / sweep) | t, [ch], cca_ofdm\|null, cca_cck\|null, fa_ofdm\|null, fa_cck\|null, igi\|null, abs_noise_floor_dbm\|null, clm\|null (CCX busy airtime %), nhm_env\|null (NHM mass above the receiver's own floor, %), [retune_us], frames, frames_ldpc, frames_stbc, crc_err, icv_err, rssi_mean, rssi_max, snr_mean, snr_min, evm_mean — crc/icv nonzero only under `DEVOURER_RX_KEEP_CORRUPTED` (the parser drops failed frames otherwise) |
+| `rx.energy` | RX (`DEVOURER_RX_ENERGY_MS` / sweep) | t, [ch], cca_ofdm\|null, cca_cck\|null, fa_ofdm\|null, fa_cck\|null, igi\|null, abs_noise_floor_dbm\|null, clm\|null (CCX busy airtime %), nhm_env\|null (NHM mass above the receiver's own floor, %), [retune_us], frames, frames_ldpc, frames_stbc, crc_err, icv_err, rssi_mean, rssi_max, snr_mean, snr_min, evm_mean — crc/icv nonzero only under `DEVOURER_RX_KEEP_CORRUPTED` (the parser drops failed frames otherwise). An interval whose energy read threw emits no event, and its frame counts are dropped with it |
 | `rx.nhm` | RX | [ch], peak, busy (naive mass above bucket 0 — rails ~100 on a quiet channel), ratio, env (same mass with the IC's own noise-floor cluster removed — the comparable one), dur, hist[12] |
+| `rx.busy` | RX (`DEVOURER_RX_BUSY_MS`) | t, armed_us (the window actually armed — the hardware clamps the request), valid, busy_pct\|null, energy_pct\|null, window_us, own_tx, spoil (`BusySpoil`); `read_failed:1` when that window's read threw (a failed control transfer — the other fields then hold their defaults, `valid` false, `window_us` 0, `spoil` 0, so `read_failed` is what tells it from an unarmed window; a failed arm is retried and emits nothing) |
 | `rx.quality` | RX (`DEVOURER_RXQUALITY`) | verdict, frames, rssi_mean_dbm, rssi_max_dbm, snr_mean_db\|null, snr_min_db\|null, evm_db\|null, noise_floor_dbm\|null, abs_noise_floor_dbm\|null, igi |
 | `adapter.rxpaths` | RX (`DEVOURER_RXQUALITY`) | active_mask "0xNN", n_active, n_chains, frames, rssi_dbm[], snr_db[], evm_db[] — GetActiveRxPaths live per-chain activity (the caps rx_chains companion); snr_db/evm_db only when a chain carried the metric this window (EVM -128 no-stream rail excluded) |
 | `link.health` | RX (`DEVOURER_LINKHEALTH`) | verdict, rssi_dbm, snr_db, evm_db\|null, frames, fa_ofdm\|null, igi\|null, [igi_floor], [igi_ceil], cause, fix |

examples/common/poll_skip.h

@@ -0,0 +1,39 @@
+/* A demo telemetry thread's answer to a failed register read.
+ *
+ * A register read throws on a failed control transfer, and the pollers
+ * that call the device on their own cadence (busy window, thermal meter, RX
+ * energy) run on threads of their own or inside a demo's main loop, where an
+ * uncaught throw is std::terminate. Under co-channel load these reads do fail while the chip
+ * works on (src/jaguar2/CLAUDE.md has the measured rate), so a poller catches,
+ * counts and skips the sample - the same shape as the library's DIG loop -
+ * and the next tick reads afresh. The warning is rate-limited (failures 1,
+ * 101, 201, ...) and always carries the running count, so a
+ * long session neither floods stderr nor hides how often it happened. */
+#ifndef DEVOURER_POLL_SKIP_H
+#define DEVOURER_POLL_SKIP_H
+
+#include <cstdint>
+#include <exception>
+
+#include "logger.h"
+
+namespace devourer {
+
+class PollSkips {
+public:
+  explicit PollSkips(const char *what) : _what(what) {}
+
+  void note(Logger &log, const std::exception &e) {
+    if (_n++ % 100 == 0)
+      log.warn("{}: sample skipped after a failed register access ({}), {} so "
+               "far", _what, e.what(), _n);
+  }
+
+private:
+  const char *_what;
+  uint64_t _n = 0;
+};
+
+} // namespace devourer
+
+#endif /* DEVOURER_POLL_SKIP_H */

examples/rx/main.cpp

@@ -33,6 +33,7 @@
 #include "tsf_linfit.h"
 #include "TriggerParse.h"
 #include "caps_event.h"
+#include "poll_skip.h"
 #include "station_arm_env.h"
 #if defined(DEVOURER_HAVE_JAGUAR1)
 #include "jaguar1/RtlJaguarDevice.h"
@@ -1784,8 +1785,19 @@ int main(int argc, char **argv) {
            s += 50)
         std::this_thread::sleep_for(std::chrono::milliseconds(50));
       bool waited_on_gate = false;
+      devourer::PollSkips skips("DEVOURER_RX_BUSY_MS");
       while (!busy_emitter_stop.load()) {
-        const uint32_t armed = dev->ArmChannelBusy(g_rx_busy_ms * 1000u);
+        /* A failed arm is retried after a short nap and emits nothing (no
+         * window existed); a failed read is one window with no reading. */
+        uint32_t armed = 0;
+        try {
+          armed = dev->ArmChannelBusy(g_rx_busy_ms * 1000u);
+        } catch (const std::exception &e) {
+          skips.note(*logger, e);
+          for (uint32_t s = 0; s < 200 && !busy_emitter_stop.load(); s += 50)
+            std::this_thread::sleep_for(std::chrono::milliseconds(50));
+          continue;
+        }
         if (armed == 0) {
           if (!waited_on_gate)
             logger->info("DEVOURER_RX_BUSY_MS: arm refused (not brought up "
@@ -1806,7 +1818,14 @@ int main(int argc, char **argv) {
         }
         if (busy_emitter_stop.load())
           break;
-        const devourer::ChannelBusy b = dev->GetChannelBusy();
+        devourer::ChannelBusy b;
+        bool read_failed = false;
+        try {
+          b = dev->GetChannelBusy();
+        } catch (const std::exception &e) {
+          skips.note(*logger, e);
+          read_failed = true;
+        }
         devourer::Ev ev(*g_ev, "rx.busy");
         ev.t().f("armed_us", armed).f("valid", b.valid);
         if (b.valid_busy)
@@ -1820,6 +1839,8 @@ int main(int argc, char **argv) {
         ev.f("window_us", b.window_us)
             .f("own_tx", b.own_tx_in_window)
             .f("spoil", static_cast<int>(b.spoil));
+        if (read_failed)
+          ev.f("read_failed", 1);
       }
     });
   }
@@ -1837,14 +1858,21 @@ int main(int argc, char **argv) {
     IRadio *dev = rtlDevice;
     therm_emitter = std::thread([&therm_emitter_stop, dev, logger]() {
       bool warned = false;
+      devourer::PollSkips skips("DEVOURER_THERMAL_POLL_MS");
       while (!therm_emitter_stop.load()) {
         for (uint32_t slept = 0;
              slept < g_thermal_poll_ms && !therm_emitter_stop.load();
              slept += 50)
           std::this_thread::sleep_for(std::chrono::milliseconds(50));
         if (therm_emitter_stop.load())
           break;
-        const auto t = dev->GetThermalStatus();
+        devourer::ThermalStatus t;
+        try {
+          t = dev->GetThermalStatus();
+        } catch (const std::exception &e) {
+          skips.note(*logger, e);
+          continue;
+        }
         if (t.raw == 0 && !t.valid)
           continue; // backend not initialized yet, or no live meter
         devourer::Ev ev(*g_ev, "thermal");
@@ -1883,14 +1911,28 @@ int main(int argc, char **argv) {
     logger->info("DEVOURER_RX_ENERGY_MS={} — starting RX energy telemetry",
                  g_rx_energy_ms);
     IRtlRadio *dev = energy_dev;
-    energy_emitter = std::thread([&energy_emitter_stop, dev]() {
+    energy_emitter = std::thread([&energy_emitter_stop, dev, logger]() {
       auto nap = [&](uint32_t ms) {
         for (uint32_t s = 0; s < ms && !energy_emitter_stop.load(); s += 50)
           std::this_thread::sleep_for(std::chrono::milliseconds(50));
       };
+      devourer::PollSkips skips("DEVOURER_RX_ENERGY_MS");
       nap(g_rx_energy_ms); /* let bring-up finish before the first read */
       while (!energy_emitter_stop.load()) {
-        RxEnergy e = dev->GetRxEnergy(true);
+        /* A failed read skips this interval's event; its frame aggregate is
+         * dropped with it, so the next event still covers one interval. */
+        RxEnergy e;
+        try {
+          e = dev->GetRxEnergy(true);
+        } catch (const std::exception &ex) {
+          skips.note(*logger, ex);
+          {
+            std::lock_guard<std::mutex> lk(g_rxagg_mu);
+            g_rxagg = RxAgg{};
+          }
+          nap(g_rx_energy_ms);
+          continue;
+        }
         RxAgg agg;
         {
           std::lock_guard<std::mutex> lk(g_rxagg_mu);
@@ -1990,7 +2032,14 @@ int main(int argc, char **argv) {
          * rx.energy/link.health events above (which use the
          * demo's own g_rxagg). */
         if (g_rxquality) {
-          devourer::RxQuality q = dev->GetRxQuality();
+          devourer::RxQuality q;
+          try {
+            q = dev->GetRxQuality();
+          } catch (const std::exception &ex) {
+            skips.note(*logger, ex);
+            nap(g_rx_energy_ms);
+            continue;
+          }
           devourer::Ev ev(*g_ev, "rx.quality");
           ev.f("verdict", q.label)
               .f("frames", q.frames)

examples/tx/main.cpp

@@ -49,6 +49,7 @@
 #include "SweepSpec.h"
 #include "TxPower.h" /* txpkt_pwr_db_for_step — DEVOURER_TX_PKT_OFSET fan-out */
 #include "caps_event.h"
+#include "poll_skip.h"
 #include "station_arm_env.h"
 #if defined(DEVOURER_HAVE_JAGUAR1)
 #include "jaguar1/RtlJaguarDevice.h"
@@ -1442,6 +1443,7 @@ int main(int argc, char **argv) {
                  "warn_delta={}", thermal_poll_ms, thermal_warn_delta);
   }
   bool thermal_warned = false;
+  devourer::PollSkips thermal_skips("DEVOURER_THERMAL_POLL_MS");
   auto thermal_next_poll = std::chrono::steady_clock::now() +
       std::chrono::milliseconds(thermal_poll_ms);
 
@@ -2601,7 +2603,12 @@ int main(int argc, char **argv) {
         std::chrono::steady_clock::now() >= thermal_next_poll) {
       thermal_next_poll = std::chrono::steady_clock::now() +
           std::chrono::milliseconds(thermal_poll_ms);
-      auto t = rtlDevice->GetThermalStatus();
+      devourer::ThermalStatus t;
+      try {
+        t = rtlDevice->GetThermalStatus();
+      } catch (const std::exception &e) {
+        thermal_skips.note(*logger, e);
+      }
       if (t.valid || t.raw != 0) {
         devourer::Ev ev(*g_ev, "thermal");
         ev.t().f("raw", t.raw);

src/BusyWindow.h

@@ -90,6 +90,11 @@ class ClmWindow {
      * a period they never chose. Nothing is armed and nothing is disturbed. */
     if (window_us == 0)
       return 0;
+    /* Disarmed BEFORE the writes: each is a read-modify-write, and a read
+     * that throws part-way leaves the engine half-programmed. A window armed
+     * earlier must not survive that with this call's period: read() then
+     * returns no reading. */
+    armed_ = false;
     period_ = clm_period_for_us(window_us);
     arm_clm_only(regs, period_, set_bb);
     armed_ = true;

src/IRadio.h

@@ -772,7 +772,17 @@ class IRadio {
    * A spoiled or completed window is consumed by
    * the read; a not-yet-elapsed one stays armed, so the caller reads again
    * at the end of its dwell instead of re-arming. Single control thread, like
-   * every other control-plane entry point. */
+   * every other control-plane entry point.
+   *
+   * On the Realtek USB backends a failed register read throws
+   * std::ios_base::failure out of either call. A read that fails inside the
+   * arm leaves nothing armed, so the caller re-arms rather than reads: with
+   * nothing armed, GetChannelBusy falls back to its sampled path (a ~2 ms
+   * reading, or none where that path is not ported). A
+   * failed read of the window leaves it as it was. A failed write is not
+   * reported at all, so an arm can succeed over an engine it did not fully
+   * program. A poller catches, skips that window and carries on - rxdemo's
+   * DEVOURER_RX_BUSY_MS thread is the reference (examples/common/poll_skip.h). */
   virtual uint32_t ArmChannelBusy(uint32_t window_us) {
     (void)window_us;
     return 0;

src/UsbTransport.h

@@ -295,12 +295,16 @@ template <typename T> T UsbTransport::ctrl_read(uint16_t reg_num) {
                    reg_num);
   }
   _ctrl_xfers.fetch_add(1, std::memory_order_relaxed);
-  if (libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_READ, 5, reg_num,
-                              0, (uint8_t *)&data, sizeof(T),
-                              USB_TIMEOUT) == sizeof(T)) {
+  const int rc = libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_READ,
+                                         5, reg_num, 0, (uint8_t *)&data,
+                                         sizeof(T), USB_TIMEOUT);
+  if (rc == static_cast<int>(sizeof(T)))
     return data;
-  }
-  _logger->error("rtw_read({:04x}), sizeof(T) = {}", reg_num, sizeof(T));
+  /* The rc is the diagnosis: LIBUSB_ERROR_PIPE is the device stalling the
+   * request (it answers at once), LIBUSB_ERROR_TIMEOUT a request it never
+   * answered, a non-negative rc a short read. */
+  _logger->error("rtw_read({:04x}), sizeof(T) = {}, rc = {} ({})", reg_num,
+                 sizeof(T), rc, rc < 0 ? libusb_error_name(rc) : "short read");
   throw std::ios_base::failure("rtw_read");
   return 0;
 }

src/jaguar2/CLAUDE.md

@@ -94,6 +94,24 @@ Jaguar1 (shared `PhyTableLoader`).
   one control read a minute failed while the chip worked on, and an unguarded
   `GetTxDmaStatus` poll killed that AP at minute 9. The poller contract is at
   `IRtlRadio::GetTxDmaStatus`.
+- **Under co-channel saturation, a failed 8812BU register read is the device
+  stalling the request.** One 8812BU at USB 3, ch 149 HT40+, an 8812EU 50 cm
+  away injecting MCS1/40 at saturation (-10 dB offset, ~1.8k frames/s, CLM
+  busy ~83%): every failure is `LIBUSB_ERROR_PIPE` in ~100 µs - no
+  timeouts, no reads slower than 5 ms - on every address sampled (MAC
+  0x0100, BB config 0x9a4/0xa2c/0xb58/0xc50, BB report 0xf08/0xf48, the RF
+  window 0x2908). With DIG plus a 1 s busy window and thermal poll that is
+  1-6 failures per 90 s run; adding a 5 ms busy window and 50 ms thermal
+  poll, 23-26 per 60 s. An immediate re-read, from a throwaway probe patch that is
+  not in the tree, succeeded 6/6 in one 90 s run. Nothing retries: neither
+  `UsbTransport::ctrl_read` nor, by default, the vendor driver
+  (`MAX_USBCTRL_VENDORREQ_TIMES` is 1 without `CONFIG_VENDOR_REQ_RETRY`).
+  Counterparts: zero failures in 45 s with the injector off (ambient, busy
+  ~2%); one in 60 s at MCS5/40 (busy ~68%); zero in 60 s each at MCS1/20
+  and 6M/20 - but the 40 MHz witness's CLM read those at only 6% / 29% busy,
+  so 20 vs 40 MHz and airtime are not separated. The vendor's 0x4E0 write
+  after an always-on-section access (`usbctrl_vendorreq`, rtw88
+  `rtw_usb_reg_sec`) is not ported and was not tested as a cause.
 
 ## TX power
 

src/jaguar2/RtlJaguar2Device.cpp

@@ -295,6 +295,7 @@ void RtlJaguar2Device::start_pwrtrack() {
     /* ~2 s cadence via steady_clock, polled in short slices so the dtor join
      * returns promptly on shutdown. */
     auto next = std::chrono::steady_clock::now();
+    uint64_t skipped = 0;
     while (!_pwrtrack_stop && !g_devourer_should_stop) {
       std::this_thread::sleep_for(std::chrono::milliseconds(200));
       if (std::chrono::steady_clock::now() < next)
@@ -308,11 +309,14 @@ void RtlJaguar2Device::start_pwrtrack() {
       int cck = -1, ofdm = -1, mcs7 = -1;
       _hal.txagc_shadow(cck, ofdm, mcs7);
       /* Same hazard as the DIG thread: a register read that throws under RX
-       * load must skip this tick, not terminate the process. */
+       * load must skip this tick, not terminate the process. Counted and
+       * rate-limited the same way. */
       try {
         _cal->pwr_track(ofdm);
       } catch (const std::exception &e) {
-        _logger->warn("Jaguar2 thermal track: tick skipped ({})", e.what());
+        if (skipped++ % 100 == 0)
+          _logger->warn("Jaguar2 thermal track: tick skipped after a failed "
+                        "register access ({}), {} so far", e.what(), skipped);
       }
     }
   });

tests/busy_window_selftest.cpp

@@ -13,6 +13,7 @@
 #include <cstdint>
 #include <cstdio>
 #include <map>
+#include <stdexcept>
 #include <vector>
 
 using devourer::BusySource;
@@ -53,13 +54,24 @@ struct MockBb {
   bool clm_ready = true;
   /* The register map under test, so the JGR3 addresses can be exercised too. */
   NhmRegs map = nhm_regs_11ac();
+  /* A failed control transfer, the way the transport reports one: a read
+   * throws. `fail_set_bb_at` is the index of the set_bb call whose
+   * read-modify-write throws on its read (-1 = none); `fail_reads` makes
+   * every report read throw. */
+  long fail_set_bb_at = -1;
+  bool fail_reads = false;
 
   uint32_t read32(uint16_t addr) {
+    if (fail_reads)
+      throw std::runtime_error("read failed");
     if (addr == map.clm)
       return (clm_ready ? (1u << 16) : 0u) | clm_ticks;
     return regs[addr];
   }
   void set_bb(uint16_t addr, uint32_t mask, uint32_t value) {
+    if (fail_set_bb_at >= 0 &&
+        static_cast<long>(writes.size()) == fail_set_bb_at)
+      throw std::runtime_error("set_bb read failed");
     int shift = 0;
     while (shift < 32 && !((mask >> shift) & 1u))
       shift++;
@@ -450,6 +462,52 @@ int main() {
     check("jgr3: reading", b.busy_pct, 25);
   }
 
+  /* --- a failed register access: the caller catches and polls on, so the
+   * window it leaves behind must still answer honestly. --- */
+  {
+    /* A re-arm that throws part-way over a still-running window leaves
+     * NOTHING armed: the engine is half-programmed, and the earlier window
+     * must not survive with this call's period. */
+    MockBb bb;
+    ClmWindow w;
+    w.arm(regs, 240000, 0, bb.wr());
+    bb.fail_set_bb_at = static_cast<long>(bb.writes.size()) + 2;
+    bool threw = false;
+    try {
+      w.arm(regs, 1000, 0, bb.wr());
+    } catch (const std::exception &) {
+      threw = true;
+    }
+    check("failed arm: the throw reaches the caller", threw, 1);
+    check("failed arm: nothing left armed", w.armed(), 0);
+    bb.fail_set_bb_at = -1;
+    bb.clm_ticks = 30000;
+    bb.clm_ready = true;
+    const ChannelBusy b = w.read(regs, 0, bb.rd());
+    check("failed arm: no reading", b.valid, 0);
+  }
+  {
+    /* A read that throws changes nothing: the window is still armed, and
+     * the next read gets it. */
+    MockBb bb;
+    ClmWindow w;
+    w.arm(regs, 240000, 0, bb.wr());
+    bb.clm_ticks = 30000;
+    bb.clm_ready = true;
+    bb.fail_reads = true;
+    bool threw = false;
+    try {
+      (void)w.read(regs, 0, bb.rd());
+    } catch (const std::exception &) {
+      threw = true;
+    }
+    check("failed read: the throw reaches the caller", threw, 1);
+    check("failed read: still armed", w.armed(), 1);
+    bb.fail_reads = false;
+    const ChannelBusy b = w.read(regs, 0, bb.rd());
+    check("failed read: the retry reads the window", b.busy_pct, 50);
+  }
+
   if (g_fail == 0)
     std::printf("busy_window_selftest: all checks passed\n");
   return g_fail ? 1 : 0;