Log the channel-scan deferral, and fix the window-transition counts

Carrier sense has two gates and only one of them was observable. busyRx in
canSendImmediately() is a latched PREAMBLE_DETECTED/HEADER_VALID IRQ and logs
every deferral; isChannelActive() is a 2-symbol CAD and logged nothing at all,
so how often it catches an inbound packet - and by implication how often it
misses one - has never been measurable. It is also the gate that matters for
the question, because the strong check is already clear by the time the scan
runs: every deferral it reports is a packet the strong check missed. Log it at
the one RadioLib call site, and at the SimRadio one with the same wording so a
sim run and a hardware run can be counted the same way.

Separately, the client's input-window transition logging was misleading. Both
lines lived inside the flush loop, which only runs while typed bytes are
queued, so a window that reopened with an empty queue logged nothing and a run
ended up with a close that had no matching reopen. That reads as a latch and is
not one. The transitions are now recorded on every service tick, so the counts
describe the window rather than the typing. The retransmit line also carries
the attempt number and the current interval, which is what separates a link
recovering slowly from one not recovering at all.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

bin/dmshell_client.py

@@ -877,6 +877,27 @@ def replay_frames_from(transport, state: SessionState, start_seq: int) -> None:
     )
 
 
+def log_input_window_transition(state: SessionState) -> None:
+    """Record the window opening and closing, independently of whether input is waiting.
+
+    This used to live inside the flush loop, which only runs while bytes are queued - so a window
+    that reopened with an empty queue logged nothing, and the run showed a closed with no matching
+    reopen. That reads as a latch and is not one. Called on every service tick instead, so the
+    closed/reopened counts describe the window rather than the typing.
+    """
+    if state.input_window_frames == 0:
+        return
+    closed = not state.input_window_open()
+    if closed == state.input_window_blocked:
+        return
+    state.input_window_blocked = closed
+    if closed:
+        state.log_replay_event("input_window_closed", state.peer_acked_tx_seq,
+                               f"outstanding={state.outstanding_input()}")
+    else:
+        state.log_replay_event("input_window_reopened", state.peer_acked_tx_seq)
+
+
 def flush_pending_input(transport, state: SessionState) -> None:
     """Send as much held input as the window allows, oldest bytes first."""
     with state.input_lock:
@@ -885,15 +906,9 @@ def flush_pending_input(transport, state: SessionState) -> None:
 
 def _flush_pending_input_locked(transport, state: SessionState) -> None:
     while state.active and not state.closed_event.is_set() and state.has_queued_input():
+        log_input_window_transition(state)
         if not state.input_window_open():
-            if not state.input_window_blocked:
-                state.input_window_blocked = True
-                state.log_replay_event("input_window_closed", state.peer_acked_tx_seq,
-                                       f"outstanding={state.outstanding_input()}")
             return
-        if state.input_window_blocked:
-            state.input_window_blocked = False
-            state.log_replay_event("input_window_reopened", state.peer_acked_tx_seq)
         chunk = state.take_queued_input(INPUT_BATCH_MAX_BYTES)
         if not chunk:
             return
@@ -917,6 +932,7 @@ def service_input_window(transport, state: SessionState) -> None:
     flush_pending_input(transport, state)
     if not state.active or state.closed_event.is_set():
         return
+    log_input_window_transition(state)
     if state.input_window_open():
         return
     missing, exhausted = state.input_retransmit_due()
@@ -931,7 +947,13 @@ def service_input_window(transport, state: SessionState) -> None:
         state.active = False
         state.closed_event.set()
         return
-    state.log_replay_event("input_retransmit", missing)
+    # The attempt number is what distinguishes a link that is recovering slowly from one that is not
+    # recovering at all: a healthy gap clears in a handful, and an attempt count climbing toward
+    # MAX_INPUT_RETRANSMITS on one sequence number is a direction of the link that is not passing
+    # traffic, not a flow-control problem.
+    state.log_replay_event("input_retransmit", missing,
+                           f"attempt={state.input_retransmits} of {MAX_INPUT_RETRANSMITS} "
+                           f"interval={state.input_retransmit_interval:g}s")
     replay_frames_from(transport, state, missing)
 
 

src/mesh/RadioLibInterface.cpp

@@ -451,6 +451,14 @@ void RadioLibInterface::onNotify(uint32_t notification)
                     setTransmitDelay(); // the radio config moved, so re-run the delay and scan on it
                 } else {
                     if (isChannelActive()) { // check if there is currently a LoRa packet on the channel
+                        // The weak half of carrier sense, and the only one that was silent. busyRx in
+                        // canSendImmediately() is a latched PREAMBLE_DETECTED/HEADER_VALID IRQ and logs
+                        // its deferrals; this is a 2-symbol CAD, and it has already been established
+                        // clear by the time we get here - so every line below is a packet the strong
+                        // check missed and this one caught. Without the count there is no way to tell
+                        // how often the CAD is carrying carrier sense on its own, and no baseline
+                        // against which a suspected miss means anything.
+                        LOG_DEBUG("Can not send yet, channelActive, packet 0x%08x", txp->id);
                         if (!RadioTxHooks::holdsRadio(txp)) {
                             startReceive(); // try receiving this packet, afterwards we'll be trying to transmit again
                         }

src/platform/portduino/SimRadio.cpp

@@ -179,7 +179,10 @@ void SimRadio::onNotify(uint32_t notification)
                 setTransmitDelay(); // currently Rx/Tx-ing: reset random delay
             } else {
                 if (isChannelActive()) { // check if there is currently a LoRa packet on the channel
-                    // LOG_DEBUG("Channel is active: set random delay");
+                    // Same line as the RadioLib path, so a sim run and a hardware run can be counted
+                    // the same way. Note sim carrier sense is perfect and instantaneous, so this fires
+                    // for a different reason than it does on a radio.
+                    LOG_DEBUG("Can not send yet, channelActive, packet 0x%08x", txQueue.getFront()->id);
                     setTransmitDelay(); // reset random delay
                 } else {
                     // Send any outgoing packets we have ready