diff --git a/docs/logging.md b/docs/logging.md index 1335714..26517d5 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -109,7 +109,7 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; |---|---|---| | `tx.frame` | TX | n, rc — precoder demo variant: n, ok | | `tx.stats` | TX | submitted, failed, was_timeout, last_rc | -| `tx.agg` | L (`DEVOURER_TX_USB_AGG`, send_packets) | frames, bytes, shim, ok — one per multi-frame bulk-OUT URB. RTL8733B also emits `sent` (bytes actually transferred) and sets `ok` only on a FULL write, so `ok=false` with `0 <= sent < bytes` is a short write, not a transport error | +| `tx.agg` | L (`DEVOURER_TX_USB_AGG`, send_packets) | frames, bytes, shim, ok — one per multi-frame bulk-OUT URB. The sync-TX generations (Jaguar2/Jaguar3/RTL8733B) also emit `sent` — bytes actually transferred, OR the negative libusb rc on a transport error (deliberately raw: this event is the only machine-readable carrier of the aggregated-path error code) — and set `ok` only on a FULL write, so `ok=false` splits as `sent < 0` transport error vs `0 <= sent < bytes` short write. Jaguar1 TX is async: its `ok` means URB accepted by the transport and there is no `sent` field (bytes resolve at completion reaping) | | `tx.report` | L (`DEVOURER_TX_REPORT`, CCX decode) | t, state (0=delivered, 1=retry-drop), ok, retries, final_rate, queue_time_raw, bmc, macid, fmt ("8812"\|"halmac"); halmac adds tag (SW_DEFINE echo), rts_retries, missed (fw-stuffed constant on Jaguar3 — tag gaps are the drop signal; `tests/txrpt_coverage_attrib.py`) — t is the achieved-report-rate timebase (the CCX emission ceiling is reports/s) | | `tx.status` | RX, duplex (C2H TX_RPT decode) | hoff, queue, retry, airtime_us, rate | | `tx.receipt` | TX (its RX thread, `DEVOURER_TX_RECEIPTS`) | t, fresh, total, covered, receipts, tlv hex — one event per absorbed windowed RX receipt (src/cell/RxReceipt.h), WITH the raw TLV so `tests/receipt_verify.py` can replay the merge and compare frame-exactly against the receiver's rx.seq ledger; decimating would break that comparison | diff --git a/src/TxStats.h b/src/TxStats.h index 8613f98..9a09b91 100644 --- a/src/TxStats.h +++ b/src/TxStats.h @@ -17,11 +17,21 @@ namespace devourer { * (LIBUSB_ERROR_TIMEOUT / LIBUSB_TRANSFER_TIMED_OUT) is the chip NAKing because * its TX FIFO is full — recoverable back-pressure, the xtx case — whereas a * hard error (NO_DEVICE, pipe stall, ...) is a broken link. `last_error_rc` is - * the raw libusb code of the most recent failure (0 = none yet). */ + * the raw libusb code of the most recent failure (0 = none yet), or + * kTxShortWriteRc for a transfer libusb reported OK but short — the + * full-write contract counts that as a failure, and libusb has no code for + * it. */ + +/* Sentinel for a short bulk write (libusb success, fewer bytes than asked). + * Chosen outside every libusb error code (-1..-99) and negated-transfer-status + * value so it can never be mistaken for one. */ +constexpr int kTxShortWriteRc = -1000; + struct TxStats { uint64_t submitted = 0; uint64_t failed = 0; - int last_error_rc = 0; /* raw libusb rc / negated transfer status */ + int last_error_rc = 0; /* raw libusb rc / negated transfer status / + * kTxShortWriteRc */ bool last_was_timeout = false; }; diff --git a/src/UsbTransport.cpp b/src/UsbTransport.cpp index f9bc6ca..a357d1e 100644 --- a/src/UsbTransport.cpp +++ b/src/UsbTransport.cpp @@ -1018,6 +1018,20 @@ int UsbTransport::tx_sync(uint8_t ep, uint8_t *packet, size_t length, (int)length); return rc; } + if (actual != static_cast(length)) { + /* libusb reported success but moved fewer bytes than asked. Under the + * full-write contract the device layers enforce (a frame the chip got + * only a prefix of is not sent), this is a failure and must count as one + * here too — TxStats.failed is "did not complete OK", and a consumer + * comparing it against tx.frame/tx.agg outcomes must see the same + * verdict. No libusb code exists for the case, hence the sentinel. */ + _tx_failed.fetch_add(1, std::memory_order_relaxed); + _tx_last_rc.store(devourer::kTxShortWriteRc, std::memory_order_relaxed); + _tx_last_timeout.store(false, std::memory_order_relaxed); + _logger->error("bulk_send EP {} SHORT {}/{} bytes", (int)ep, actual, + (int)length); + return actual; + } _logger->info("bulk_send EP {} OK {} bytes", (int)ep, actual); return actual; } diff --git a/src/jaguar1/RtlJaguarDevice.cpp b/src/jaguar1/RtlJaguarDevice.cpp index e82cf3b..7494b3e 100644 --- a/src/jaguar1/RtlJaguarDevice.cpp +++ b/src/jaguar1/RtlJaguarDevice.cpp @@ -942,6 +942,10 @@ size_t RtlJaguarDevice::send_packets(const TxPacketView *pkts, size_t count) { rtl8812a_cal_txdesc_chksum(first); const bool sent = _device.send_packet(urb.data(), urb.size()); + /* Async TX (this generation's deliberate transfer mode): `ok` means the + * URB was ACCEPTED by the transport — bytes-on-wire resolve later at + * completion reaping, so there is no `sent` byte count to emit here and + * the sync generations' full-write accounting cannot apply. */ devourer::Ev(_logger->events(), "tx.agg") .f("frames", (unsigned long long)plan.frames()) .f("bytes", (unsigned long long)urb.size()) diff --git a/src/jaguar2/RtlJaguar2Device.cpp b/src/jaguar2/RtlJaguar2Device.cpp index 87f8951..b7251ae 100644 --- a/src/jaguar2/RtlJaguar2Device.cpp +++ b/src/jaguar2/RtlJaguar2Device.cpp @@ -1253,7 +1253,12 @@ bool RtlJaguar2Device::send_packet(const uint8_t *packet, size_t length) { int rc = _device.bulk_send_sync_ep(_device.first_bulk_out_ep(), usb_frame.data(), usb_frame.size(), /*timeout_ms=*/20); - return rc >= 0; + /* bulk_send_sync_ep returns BYTES SUBMITTED, so `rc >= 0` would also cover + * a short write — a frame the chip got only a prefix of must not be + * reported as sent. No error log on the failure path: until the TX-enable + * registers are programmed the chip NAKs every frame and the caller backs + * off, so logging here would flood exactly then. */ + return rc == static_cast(usb_frame.size()); } size_t RtlJaguar2Device::send_packets(const TxPacketView *pkts, size_t count) { @@ -1344,12 +1349,24 @@ size_t RtlJaguar2Device::send_packets(const TxPacketView *pkts, size_t count) { const int rc = _device.bulk_send_sync_ep(_device.first_bulk_out_ep(), urb.data(), urb.size(), /*timeout_ms=*/50); + /* Full write or nothing submitted: a truncated URB means the chip got a + * prefix — some trailing block partial or absent — and there is no way to + * say which frames aired, so none may be counted. A genuine short write + * (rc >= 0) is rare and actionable, so it is logged; rc < 0 stays quiet + * like the single-frame path (NAK-backoff flood). */ + const bool sent_all = rc == static_cast(urb.size()); + if (rc >= 0 && !sent_all) + _logger->error("8822B aggregated TX short on EP 0x{:02x}: {}/{} " + "({} frames dropped)", + _device.first_bulk_out_ep(), rc, urb.size(), + plan.frames()); devourer::Ev(_logger->events(), "tx.agg") .f("frames", (unsigned long long)plan.frames()) .f("bytes", (unsigned long long)urb.size()) + .f("sent", (long long)rc) .f("shim", plan.shim) - .f("ok", rc >= 0); - if (rc >= 0) + .f("ok", sent_all); + if (sent_all) ok += plan.frames(); done += plan.frames(); } diff --git a/src/jaguar3/RtlJaguar3Device.cpp b/src/jaguar3/RtlJaguar3Device.cpp index 628f4bc..e9c92eb 100644 --- a/src/jaguar3/RtlJaguar3Device.cpp +++ b/src/jaguar3/RtlJaguar3Device.cpp @@ -1725,7 +1725,12 @@ bool RtlJaguar3Device::send_packet(const uint8_t *packet, size_t length) { int rc = _device.bulk_send_sync_ep(_device.first_bulk_out_ep(), usb_frame.data(), usb_frame.size(), /*timeout_ms=*/20); - return rc >= 0; + /* bulk_send_sync_ep returns BYTES SUBMITTED, so `rc >= 0` would also cover + * a short write — a frame the chip got only a prefix of must not be + * reported as sent. No error log on the failure path: the NAK-backoff + * contract above means logging here would flood exactly when the caller is + * already backing off. */ + return rc == static_cast(usb_frame.size()); } size_t RtlJaguar3Device::send_packets(const TxPacketView *pkts, size_t count) { @@ -1826,12 +1831,24 @@ size_t RtlJaguar3Device::send_packets(const TxPacketView *pkts, size_t count) { const int rc = _device.bulk_send_sync_ep(_device.first_bulk_out_ep(), urb.data(), urb.size(), /*timeout_ms=*/50); + /* Full write or nothing submitted: a truncated URB means the chip got a + * prefix — some trailing block partial or absent — and there is no way to + * say which frames aired, so none may be counted. A genuine short write + * (rc >= 0) is rare and actionable, so it is logged; rc < 0 stays quiet + * like the single-frame path (NAK-backoff flood). */ + const bool sent_all = rc == static_cast(urb.size()); + if (rc >= 0 && !sent_all) + _logger->error("8822C aggregated TX short on EP 0x{:02x}: {}/{} " + "({} frames dropped)", + _device.first_bulk_out_ep(), rc, urb.size(), + plan.frames()); devourer::Ev(_logger->events(), "tx.agg") .f("frames", (unsigned long long)plan.frames()) .f("bytes", (unsigned long long)urb.size()) + .f("sent", (long long)rc) .f("shim", plan.shim) - .f("ok", rc >= 0); - if (rc >= 0) + .f("ok", sent_all); + if (sent_all) ok += plan.frames(); done += plan.frames(); } diff --git a/src/rtl8733b/Rtl8733bDevice.cpp b/src/rtl8733b/Rtl8733bDevice.cpp index 569e117..e1f1985 100644 --- a/src/rtl8733b/Rtl8733bDevice.cpp +++ b/src/rtl8733b/Rtl8733bDevice.cpp @@ -593,9 +593,12 @@ size_t Rtl8733bDevice::send_packets(const TxPacketView *pkts, size_t count) { * single-frame path already refuses a short write; the aggregated one * must not be the looser of the two in the same backend. */ const bool sent_all = rc == static_cast(urb.size()); - if (rc >= 0 && !sent_all) - _logger->error("RTL8733B aggregated TX short on EP 0x{:02x}: {}/{} " - "({} frames dropped)", + if (!sent_all) + /* Both failure shapes reach stderr — rc < 0 (transport error) and a + * short write — because the single-frame path logs both and this + * backend has no NAK-backoff flood concern excusing silence. */ + _logger->error("RTL8733B aggregated TX failed/short on EP 0x{:02x}: " + "{}/{} ({} frames dropped)", _device.first_bulk_out_ep(), rc, urb.size(), plan.frames()); devourer::Ev(_logger->events(), "tx.agg")