Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion docs/logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
Expand Down
14 changes: 12 additions & 2 deletions src/TxStats.h
Original file line number Diff line number Diff line change
Expand Up @@ -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;
};

Expand Down
14 changes: 14 additions & 0 deletions src/UsbTransport.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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<int>(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;
}
Expand Down
4 changes: 4 additions & 0 deletions src/jaguar1/RtlJaguarDevice.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down
23 changes: 20 additions & 3 deletions src/jaguar2/RtlJaguar2Device.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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<int>(usb_frame.size());
Comment thread
josephnef marked this conversation as resolved.
}

size_t RtlJaguar2Device::send_packets(const TxPacketView *pkts, size_t count) {
Expand Down Expand Up @@ -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<int>(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)
Comment thread
josephnef marked this conversation as resolved.
.f("ok", rc >= 0);
if (rc >= 0)
.f("ok", sent_all);
if (sent_all)
ok += plan.frames();
done += plan.frames();
}
Expand Down
23 changes: 20 additions & 3 deletions src/jaguar3/RtlJaguar3Device.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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<int>(usb_frame.size());
}

size_t RtlJaguar3Device::send_packets(const TxPacketView *pkts, size_t count) {
Expand Down Expand Up @@ -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<int>(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();
}
Expand Down
9 changes: 6 additions & 3 deletions src/rtl8733b/Rtl8733bDevice.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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<int>(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")
Expand Down
Loading