From 9d38418817d1894b31c93ece0113e503d82167cd Mon Sep 17 00:00:00 2001 From: Christophe Besson Date: Sun, 11 Oct 2026 15:42:52 +0200 Subject: feat(node): log what a transfer moved when it ends One INFO line per lease: bytes, duration, rate, and the SCTP association's window, round trip, losses and T3 expirations. Co-Authored-By: Claude Opus 5.5 --- .../src/meshbay_node/transport/webrtc/core.py | 5 ++- .../src/meshbay_node/transport/webrtc/files.py | 2 + .../meshbay_node/transport/webrtc/sctp_stats.py | 43 ++++++++++++++++++++++ .../transport/webrtc/transfer_handlers.py | 32 ++++++++++++++++ .../transport/webrtc/upload_handlers.py | 4 +- 5 files changed, 84 insertions(+), 2 deletions(-) create mode 100644 packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py (limited to 'packages/meshbay-node/src/meshbay_node/transport') diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py index a44f097..c48e9ca 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py @@ -14,7 +14,10 @@ from meshbay_common.protocol import MNP from meshbay_node import ops from meshbay_node import transfers as transfers_mod -from meshbay_node.transport.webrtc import sctp_fix # noqa: F401 (patches aiortc on import) +from meshbay_node.transport.webrtc import ( + sctp_fix, # noqa: F401 (patches aiortc on import) + sctp_stats, # noqa: F401 (patches aiortc on import) +) from meshbay_node.transport.webrtc.channel import ( _REPLY_TO, _DataChannelBuffer, diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py index 0434554..eafdaed 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py @@ -319,6 +319,8 @@ class FilesMixin: if self._channel is None or self._channel.readyState != "open": return self._send(chunk_data) + if leased: + self._account(tr, len(chunk_data.get("ct") or b"")) log.debug("dl: sent file=%s chunk=%s bytes=%s buffered=%s", file_id[:12], chunk_index, len(chunk_data.get("ct") or b""), getattr(self._channel, "bufferedAmount", "?")) diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py new file mode 100644 index 0000000..338ded9 --- /dev/null +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py @@ -0,0 +1,43 @@ +"""Counts what aiortc's SCTP sender does not, applied on import (aiortc 1.15). + +aiortc halves its congestion window on every loss and drops it to one packet +when the T3 timer expires, and keeps no record of either. Those two counts are +what say whether a slow transfer was held back by the path: a window that never +grows past a few hundred KB is losses, and the node could not tell. + +A loss is counted when the sender enters fast recovery, so a burst of packets +dropped together is one loss, which is also one halving of the window. +""" + +from aiortc.rtcsctptransport import RTCSctpTransport + +_receive_sack_chunk = RTCSctpTransport._receive_sack_chunk +_t3_expired = RTCSctpTransport._t3_expired + + +async def _counting_receive_sack_chunk(self, chunk) -> None: + recovering = self._fast_recovery_exit is not None + await _receive_sack_chunk(self, chunk) + if not recovering and self._fast_recovery_exit is not None: + self._mb_losses = getattr(self, "_mb_losses", 0) + 1 + + +def _counting_t3_expired(self) -> None: + self._mb_t3 = getattr(self, "_mb_t3", 0) + 1 + _t3_expired(self) + + +RTCSctpTransport._receive_sack_chunk = _counting_receive_sack_chunk +RTCSctpTransport._t3_expired = _counting_t3_expired + + +def describe(pc) -> str: + """The association of `pc` as a log suffix, or nothing when it has none.""" + sctp = getattr(pc, "sctp", None) + if sctp is None: + return "" + srtt = getattr(sctp, "_srtt", None) + rtt = f"{srtt * 1000:.0f} ms" if srtt else "?" + return (f" sctp cwnd={sctp._cwnd // 1024} KB rtt={rtt}" + f" loss={getattr(sctp, '_mb_losses', 0)}" + f" t3={getattr(sctp, '_mb_t3', 0)}") diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py index 729c0a0..78c74d6 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py @@ -11,6 +11,7 @@ from meshbay_common.protocol import MNP from meshbay_node import transfers as transfers_mod from meshbay_node.transfers import TransferSlots +from meshbay_node.transport.webrtc import sctp_stats from meshbay_node.transport.webrtc.limits import LEASE_GRANTED, LEASE_NONE, LEASE_QUEUED log = logging.getLogger("meshbay_node.transport.webrtc_server") @@ -25,6 +26,8 @@ if TYPE_CHECKING: # annotations only: the facade imports this module # noticing, so it trades latency for a timer that hardly ever runs. TRANSFER_SWEEP_SECS = 15 +MIB = 1024 * 1024 + class TransferMixin: def _slots(self) -> "TransferSlots": @@ -109,6 +112,29 @@ class TransferMixin: (self._user_id or "?")[:8], str(tr)[:8]) self._audit("transfer_unleased", str(tr)[:16]) + def _account(self, tr: str, nbytes: int) -> None: + slots = self._ctx.get("_transfer_slots") + if slots is not None: + slots.account(tr, nbytes) + + def _transfer_end_line(self, lease, reason: str) -> str: + """What a transfer moved, how fast, and what its association looked like. + + The node wrote nothing about throughput, so a slow download left no + trace in the journal and took a test bench to explain. The SCTP figures + are the association's totals since it opened, not this transfer's + share: a connection carries several transfers and they share one + window. + """ + line = (f"transfer: end {lease.kind} {lease.tr[:8]} {reason} " + f"{lease.moved / MIB:.1f} MB") + if lease.moved and lease.elapsed > 0: + line += (f" in {lease.elapsed:.1f} s " + f"({lease.moved / MIB / lease.elapsed:.2f} MB/s)") + owner = (self if lease.session_key == self._registry_key else + next(iter(self._sessions_everywhere(lease.session_key)), None)) + return line + sctp_stats.describe(getattr(owner, "_pc", None)) + def _transfer_state_msg(self, lease, state: str, reason: str = "") -> dict: slots = self._slots() out = { @@ -215,6 +241,7 @@ class TransferMixin: lease, granted = slots.close(tr, reason) if lease is not None: self._send(self._transfer_state_msg(lease, "closed", reason)) + log.info("%s", self._transfer_end_line(lease, reason)) self._announce(granted) def _release_transfers(self) -> None: @@ -223,6 +250,9 @@ class TransferMixin: if slots is None: return gone, granted = slots.release_session(self._registry_key) + for lease in gone: + log.info("%s", self._transfer_end_line( + lease, transfers_mod.REASON_SESSION_GONE)) if gone: log.info("transfer: session gone, released %d (%s)", len(gone), slots.summary()) @@ -251,6 +281,8 @@ class TransferMixin: ended, granted = slots.sweep() for lease, reason in ended: log.info("transfer: reclaimed %s (%s)", lease.tr[:8], reason) + if lease.state != "queued": + log.info("%s", self._transfer_end_line(lease, reason)) self._announce(granted, ended) log.debug("transfer: %s", slots.summary()) diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py index b19846c..c052703 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py @@ -18,7 +18,7 @@ from meshbay_node.roots import ( shell_active, ) from meshbay_node.transport.webrtc.disk import _append_chunk, _free_bytes -from meshbay_node.transport.webrtc.limits import LEASE_NONE, LEASE_QUEUED +from meshbay_node.transport.webrtc.limits import LEASE_GRANTED, LEASE_NONE, LEASE_QUEUED log = logging.getLogger("meshbay_node.transport.webrtc_server") @@ -227,6 +227,8 @@ class UploadMixin: _refuse("Invalid chunk encoding", "bad_chunk_encoding") return chunk_bytes = bytes(data) + if tr and state == LEASE_GRANTED: + self._account(tr, len(chunk_bytes)) if not SAFE_UPLOAD_NAME.match(filename): _refuse("Invalid filename", "invalid_filename") -- cgit v1.2.3