diff --git a/docs/logging.md b/docs/logging.md index 672c7406..43280eeb 100644 --- a/docs/logging.md +++ b/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 | diff --git a/examples/common/poll_skip.h b/examples/common/poll_skip.h new file mode 100644 index 00000000..d01d99a6 --- /dev/null +++ b/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 +#include + +#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 */ diff --git a/examples/rx/main.cpp b/examples/rx/main.cpp index e95de965..7847532b 100644 --- a/examples/rx/main.cpp +++ b/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(b.spoil)); + if (read_failed) + ev.f("read_failed", 1); } }); } @@ -1837,6 +1858,7 @@ 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(); @@ -1844,7 +1866,13 @@ int main(int argc, char **argv) { 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 lk(g_rxagg_mu); + g_rxagg = RxAgg{}; + } + nap(g_rx_energy_ms); + continue; + } RxAgg agg; { std::lock_guard 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) diff --git a/examples/tx/main.cpp b/examples/tx/main.cpp index 0dc36a01..2238eb11 100644 --- a/examples/tx/main.cpp +++ b/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); diff --git a/src/BusyWindow.h b/src/BusyWindow.h index 5b5bf542..1bccae2c 100644 --- a/src/BusyWindow.h +++ b/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; diff --git a/src/IRadio.h b/src/IRadio.h index 299bede7..d046dd3f 100644 --- a/src/IRadio.h +++ b/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; diff --git a/src/UsbTransport.h b/src/UsbTransport.h index c7189f66..fdea5891 100644 --- a/src/UsbTransport.h +++ b/src/UsbTransport.h @@ -295,12 +295,16 @@ template 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(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; } diff --git a/src/jaguar2/CLAUDE.md b/src/jaguar2/CLAUDE.md index cf4a0800..ded0be43 100644 --- a/src/jaguar2/CLAUDE.md +++ b/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 diff --git a/src/jaguar2/RtlJaguar2Device.cpp b/src/jaguar2/RtlJaguar2Device.cpp index a7f22654..41607115 100644 --- a/src/jaguar2/RtlJaguar2Device.cpp +++ b/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); } } }); diff --git a/tests/busy_window_selftest.cpp b/tests/busy_window_selftest.cpp index 59eb0b18..9570d8f2 100644 --- a/tests/busy_window_selftest.cpp +++ b/tests/busy_window_selftest.cpp @@ -13,6 +13,7 @@ #include #include #include +#include #include 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(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(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;