Files
firmware/bin/dmshell_client.py
977b1d775c Dmshell (#11976)
* Very WIP dmshell

* Dumb fixes

* Interactive mode

* Try to re-request missed sequences

* troubleshoot dropped packets

* Don't firehose missing packets

* Attempt at better responsiveness

* DMShell heartbeat

* dmshell client serial support and tweaks

* Remove some dead code and LLM overcomplication

* Trunk

* Use RemoteShell in protobufs

* Make the DMShell tests compile

* Harden against possible memory overflows

* Minor cleanups

* No Child Left Behind

* simplify pt 1

* Refactor and Simplify

* Make new protobuf value consistent

* dmshell reliability tweaks

* Add real Lock handling on Portduino

* talking stick

* latest test changes

* Guard the DMShell TX-queue check against a null RadioLibInterface

runOnce() dereferenced RadioLibInterface::instance unconditionally. It is
null on any node whose radio is not RadioLib-backed - meshtasticd with
Lora.Module sim, and the serialHal path - so the first runOnce after a
session went active segfaulted the process.

* Revert the DMShell half-duplex turn-taking ("talking stick") scheme

Before: a DMShell session gated every transmission on a token. The server
only sent shell output while it held the turn; with no token it emitted an
RTS and waited (rate-limited to one per 250 ms) for the client to grant one.
Each grant, yield and re-grant was its own LoRa frame, so an unprompted burst
of shell output cost a full RTS -> grant round trip before the first byte
moved, and a long burst paid another yield/grant pair every 8 frames. On a
link where a single frame already takes a noticeable fraction of a second,
that turned interactive use into seconds of latency per exchange.

After: both ends transmit as soon as they have something to send, which is
how the module behaved before the scheme landed. The flags field stays in the
wire format but is written as 0 and ignored, so nothing in the protobuf
changes and a peer still running the turn-taking build is simply not answered
in kind.

The scheme was introduced in f25e3e893 and refined in 11a14bdda. Neither
commit is reverted wholesale, because both carry unrelated work that stays:

- 11a14bdda's NodeDB.h fix, narrowing the pre-hop drop policy to reject only
  HopStartStatus::INVALID, is untouched.
- The client's hop_limit fix (default 3 plus a --hop-limit flag) and its
  packet.decoded.bitfield assignment are re-applied on top of the revert;
  they address the far-end pre-hop drop, not channel access.
- 5e2d6d225's null guard on RadioLibInterface::instance is re-applied.

Removed with the scheme: the TURN_FLAG_GRANT/MORE/RTS constants and the
TURN_BUDGET_FRAMES, RTS_RETRY_MS and TURN_LINGER_MS tunables; the per-session
turnManaged, hasToken, lastRtsMs, turnDeadlineMs and turnFramesSent state;
applyTurnFlags, ptyHasOutput, serviceTurn, sendOutputFrame, sendTurnGrant and
sendRts; and on the client the TxIntent queue, the sender thread that owned
the token, and the --no-turn-taking, --turn-budget and --turn-reclaim flags.
Nothing else referenced any of it - no test covered the scheme.

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

* DMShell: stop an unfillable gap becoming an endless retry storm

A lost frame could put a DMShell session into a retransmission loop that never
terminated, and the faster the modem preset the sooner it happened. Three causes,
all in the recovery path:

Both ends keep a replay history bounded at 50 *frames*, so the wall-clock span it
covers scales with the preset - about two minutes on LongFast, under seven seconds
on ShortTurbo - while the client's retry timers are fixed in seconds. Once a
requested frame aged out, resendFramesFrom() logged "not found in history" and
returned, telling the peer nothing. Neither side advances past a hole, so the peer
asked again every second until the five-minute idle timeout. Report the eviction
and close the session instead: the request is unanswerable, and saying so turns a
dead session into a diagnosable one.

Every frame arriving above a gap produced its own replay request, and each request
cost the sender a duplicate replay, so one loss cost as many extra transmissions
as the sender had frames in flight. Damp the requests per sequence number, over an
interval derived from getPacketTime() rather than a constant, since one frame's
airtime spans 100 msec on ShortTurbo and over 2 sec on LongFast. A different gap
is still reported immediately, so recovery gains no round trip. The client backs
its own retry off exponentially to 30 sec for the same reason.

A teardown could sit behind a gap: CLOSE and CLOSED both went through the ordering
check, so a session ending because a gap could not be filled was itself buffered
behind that gap. Both are now acted on out of band. ERROR deliberately stays
ordered - it is not always terminal, and skipping its sequence number would open a
gap of its own.

Also drops a sendAck() whose replay field underflowed to 0xffffffff when called
with no argument, which the peer read as a request for a sequence number that had
never been sent.

The sequence and history bookkeeping moves to DMShellRecovery.h, which takes the
time as an argument and pulls in no platform headers, so test_dmshell_recovery
covers it - including the damping boundaries and the millis() wrap.

DMSHELL_LEGACY_RECOVERY=1 on the node, paired with --legacy-recovery on the
client, restores the previous behaviour on the same build so a session can be
measured with and without the fix.

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

* DMShell: act on the first hardware measurements of the retry storm

A two-radio bench run on US/ShortTurbo (473 frames one-way, plus a short
bidirectional run) measured what the previous commit was guessing at, and
three things follow from it.

The client could not start at all. config.proto imports field_metadata.proto,
which was missing from required_protos; protoc resolves it via -I for
compilation but only emits a _pb2 module for files named on the command line,
so config_pb2 imported a module that was never written. Named it.

The missing-sequence backoff was tuned for the wrong failure. It doubled to a
30 s cap on the theory that each repeat was evidence the peer could not fill
the gap. On hardware every repeat was a collision on a gap that did fill: 8 of
8 recovered, worst case 5 attempts, zero unfillable. Doubling from the first
repeat made those recover 2-3x slower, which is plainly visible in an
interactive shell. Hold the base interval for the first four attempts and only
grow after that, with an 8 s ceiling - the ceiling only has to bound the
residue now that an evicted frame is reported in one round trip.

Eviction turns out to be symmetric, so the client needs the same report the
firmware got. prune_sent_frames would have made the client's ring hold only
unacked frames, but its one call site is commented out, so tx_history is a flat
last-50-sent ring exactly like txHistory and can be outrun the same way. When
the peer asks for a frame the client no longer holds, close the session and log
replay_evicted instead of logging replay_unavailable and leaving the peer asking
until the idle timeout. --legacy-recovery keeps the old silent behaviour for the
A/B.

Also document the contiguity invariant DMShellTxHistoryWindow derives its
retained range from, at the one choke point every remembered frame passes
through.

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

* DMShell: bound unacknowledged output instead of the replay ring

Hardware runs at both ends of the preset range showed the replay-eviction
failure is ratio-specific, not preset-specific: whichever side has the higher
frame rate outruns its own ring first. On ShortTurbo the server sends ~3
frames/s against a keystroke every 1.5 s, so the server's ring goes; on
LongFast the client sends many small frames against few large ones, so the
client's goes, and a LongFast run logged 106 unanswerable replay requests with
zero firmware evictions. Enlarging or time-bounding a ring on one side would
therefore have moved the failure to the other side rather than fixing it.

Bound the outstanding data instead. The server tracks the peer's cumulative
receive cursor and stops generating new output once four frames are
unacknowledged, so it can never get more than a window ahead of a gap and can
always still answer the replay request for it. Ring size stops mattering, at
any preset, on both sides.

This also removes the zombie session without touching the idle timer. The
timer could never fire because the server refreshed it with its own output
while the send path was unbounded; a sender blocked on a closed window stops
sending, so it stops refreshing, and the existing five-minute timeout finally
applies to a peer that has vanished. The self-refresh was only a bug in the
absence of a bound.

The window needs the peer to acknowledge, and on a one-way stream the client
transmitted nothing at all - its heartbeat is suppressed while inbound traffic
keeps arriving - so it now sends a bare ack every second in-order frame. The
ack interval must not exceed the server's window or the two deadlock until the
heartbeat breaks it; both are configurable so the pair can be swept, and
DMSHELL_TX_WINDOW=0 or legacy mode restores the unbounded behaviour for the
A/B on one build.

Liveness and the flow-control cursor now come from every authenticated
in-session frame rather than only those passing the ordering gate. An
out-of-order frame still proves the peer is alive and still carries a valid
cursor, and during a gap it may be the only kind arriving.

Also raise the OPEN_OK wait onto its own --open-timeout. A lost OPEN costs a
full frame airtime, ~2.2 s on LongFast against ~0.1 s on ShortTurbo, and a
measured LongFast session needed 150 s to open against a 10 s default.

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

* DMShell: log window open/close transitions

The window opens and closes several times a second, so per-poll logging would
drown the log, but with no line at all there is no way to tell from a run
whether the bound ever engaged - which is the first thing to check on the next
hardware run. Log only the transitions, with the outstanding count.

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

* DMShell: retransmit from the sender when the window latches shut

The window stopped the retry storms and cut the frames needed per delivered
line by 60x, but it introduced a silent permanent stall, reproduced on
hardware in both runs at around 20 s: the window closes one last time and
never reopens, while frames keep arriving from the peer and the session stays
open looking healthy.

The cause is that recovery was entirely receiver-driven, and the window
removed the stimulus it depended on. A lost frame freezes the peer's
cumulative cursor at the last in-order sequence number. The sender then fills
its window against that frozen cursor and stops. From there nothing can make
progress: the peer only asks for a replay when a frame arrives carrying a
higher sequence number, and with the window shut none ever does. The peer's
own INPUT frames carry the frozen cursor, and neither the INPUT path nor
anything else on the ordered path triggers a replay - only ACK and PING do.

So the sender now takes responsibility for its own unacknowledged data, which
is the "no sender-side retransmit timer" gap named in the original analysis.
While the window is shut it retransmits the frame the peer's cursor says is
missing, one round trip apart, derived from the modem config the way replay
requests already are. It resends the missing frame rather than something new,
because sending something new would push the sender further ahead of the gap,
which is what the window exists to prevent.

The client had a second, independent hole in the same path. Its heartbeat is
what makes the server retransmit via the PING handler, but heartbeat_due keyed
off traffic in either direction, so the client's own keystrokes reset it -
typing faster than HEARTBEAT_IDLE_DELAY_SEC suppressed the heartbeat
completely. Measured: zero heartbeats in 60 s while typing every 1.5 s into a
stalled session, against four when idle. An interactive user was silencing
their own recovery. It now keys off inbound silence alone, so a healthy stream
still sends none.

Either change alone breaks the deadlock; both are correct independently.

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

* DMShell: stop retransmitting to a peer that has gone away

Bounding the outstanding data left one unbounded behaviour behind. A sender
whose window is shut repeats the frame the peer's cursor says is missing, and
nothing ever ends that: it stays under the replay ring so nothing is evicted,
and the idle timeout keeps being refreshed while the peer sends anything at
all. On the bench the session became a zombie twice, repeating one sequence
number 88 and 89 times and still going 67 s after the client had exited,
because the client's teardown did not survive the link.

A healthy link on the same rig needed at most 11 repeats of a single sequence
number, so the allowance is 25 per sequence number, reset whenever the peer's
cursor advances. It is a frame count rather than a duration because the
retransmission interval already derives from the modem config, so it scales
with the preset by itself - about 11 s on ShortTurbo, 114 s on LongFast. When
it runs out the session closes as peer_unresponsive: the evidence says the
peer vanished rather than that the link failed. DMSHELL_MAX_RETRANSMITS=0
restores the old behaviour so one build can still be measured both ways.

Also flush the PTY's pending output when a peer's input carries the terminal's
interrupt character. A local line discipline does this for free; over LoRa the
~15 KiB the PTY holds is about 77 frames, 17 s of airtime on ShortTurbo and
nearly three minutes on LongFast, all of it output the user has just
cancelled. The flush happens before the interrupt is written through, so the
shell's own response to it survives.

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

* DMShell: bound unacknowledged input as well as output

The send window bounded the server's output and left the client's input
unbounded, so only half the original failure was fixed. Measured on hardware:
at ShortTurbo the server outran its own replay ring and the window fixed it,
but at LongFast - where keystrokes are emitted far faster than the server
drains them - the client outran its ring instead and the session still died
with replay_evicted seq=5 while its own ring had moved on to 12. Whichever end
has the higher frame rate loses, so both ends need the bound.

The client now tracks the server's cumulative receive cursor from the ack_seq
and last_rx_seq that already ride on every inbound frame, holds typed input
locally once four frames are unacknowledged, and sends it in order as the
cursor advances. Overflowing the local hold is reported rather than silent,
because the bytes are the user's.

Bounding the sender re-creates the latch it created on the server: with the
window full the server never sees a sequence number above the gap, so it never
asks for the replay that would reopen us, and its only trigger is an arriving
frame. So the client also repeats the frame the cursor says is missing while
the window is shut, escalating the interval the way a replay re-ask does - it
cannot read the modem config the way the firmware can - and gives up after 25
repeats, matching the firmware's bound.

For that to work the server has to acknowledge input even when it has no
output: a keystroke a program swallows would otherwise leave the client's
window full against a silent peer. So the server sends a bare ACK carrying its
cursor after two in-order frames with nothing of its own to send, and answers
a repeated frame with one directly. A replay request carries the same cursor
and counts as that answer; a damped gap stays silent, which is what the
damping is for. Frames the server originates already carry the live cursor, so
a busy stream sends no extra frames at all.

Input sends are serialised across the input and heartbeat threads: both flush
the held bytes, and two takes interleaving with two sends would put the user's
keystrokes on the wire out of order.

DMSHELL_INPUT_WINDOW sizes the client bound and 0 disables it, so one build can
still be measured both ways; --legacy-recovery disables it too.

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

* DMShell client: fix the window-transition counts

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.

(The client half of 8384c66 on the bench branch; its radio-side scan logging
stays out of the DMShell branch.)

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* DMShell: name the op and seq on an inbound frame

"Received a DMShell message" could not answer the question that matters when a
gap will not close: whether the peer's replay arrived and was discarded, or
never arrived. It is logged before the session and ordering checks, so a frame
rejected by either still shows up, which is what makes the two cases separable
from one log stream.

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

* DMShell: hold out-of-order frames instead of discarding them

The receiver had no reorder buffer at all. A frame arriving above a gap was
dropped even though it arrived intact, so the peer had to send it again once the
gap filled - a round trip per frame that was already in hand. Measured at
LongFast: the sequence numbers the receiver kept asking for had arrived a dozen
times each, and the session advanced roughly one frame per round trip while
delivering 24 lines in 300 s. Read as loss, it looked like a 5% link; it was
frames arriving and being thrown away.

Frames above the gap are now held, eight slots deep - twice the peer's default
send window, so a well-behaved peer can never fill it and an unbounded one is
bounded here - and delivered in order the moment the gap fills. When the buffer
is full the highest sequence number is the one dropped, because the gap fills
from below and the lowest are needed soonest.

Two things fall out of it. The op handling is now applySessionFrame(), reached
from the radio and from the buffer alike. And a replay request is suppressed for
a sequence number already held: the ordering window deals only in sequence
numbers it has passed to the session, so it cannot know what the buffer has, and
asking for a frame we are holding is pure channel load.

Simulated against the discarding version across loss rates from 5% to 40%, this
roughly halves the transmissions needed per frame delivered - 2.1 to 1.1 at 10%
loss - with the larger saving in wall-clock time, since each frame no longer
costs its own round trip.

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

* DMShell client: send with hop_limit 0, like the firmware already does

A non-zero hop limit on our frames arms two mechanisms in the peer's
firmware that this protocol wants nothing from, and both cost airtime in
the direction that matters.

NextHopRouter::sendWithNextHop starts its own relay retransmissions for a
packet whose gate it passes - (hop_limit > 0 || want_ack) with a known
next hop - so the sending node repeats each of our frames up to twice
more, then floods the last attempt and resets the learned next hop. Those
repeats reuse the packet id, so the destination discards them in
shouldFilterReceived as dupes after paying for them on the air; they
never reach DMShell, which is why they were invisible in per-sequence
arrival counts.

To stop them, ReliableRouter::sniffReceived answers every frame whose
next_hop names it with a 0-hop routing ACK. That is one extra
transmission per input frame, from the peer, competing on a half-duplex
channel with the shell output it is trying to send us.

The firmware end of the session already sends with hop_limit 0, so
DMShell is a direct-neighbour protocol in both directions either way, and
the asymmetry bought nothing. hop_start 0 survives the receiver's pre-hop
drop policy because classifyHopStart accepts it when the Data bitfield is
present, and perhapsEncode sets that on every locally-originated packet -
which is what makes the firmware's own hop_limit 0 frames arrive here.

--hop-limit 3 restores the old behaviour for a same-binary comparison.

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

* DMShell client: time input retransmissions off the measured round trip

The input retransmission reused the replay re-ask escalation: a flat 1 s
for four attempts, then doubling to an 8 s ceiling. One second is shorter
than a single frame's time on air at LongFast (~2.2 s), so a repeat went
out while the frame it was repeating was still being transmitted, and
another behind that. Worse, the deadline was armed by the poll that
noticed the frame rather than by the frame itself, and advancing the
peer's cursor cleared it - so the moment one frame was acknowledged, the
next one, possibly sent milliseconds earlier, was repeated on the
following poll. Measured at LongFast over 300 s: 117 retransmissions and
105 arrivals for 22 distinct sequence numbers, against 17 replay requests
from the peer. The duplication was almost entirely ours.

Two changes, both of which need only what this side can observe:

A frame is never repeated before it has been outstanding for a full
interval. SentShellFrame now carries the time it was last handed to the
API, and the first deadline for a sequence number is measured from that
rather than from the tick that noticed it.

The interval itself comes from the link instead of a constant. Every time
the peer's cumulative cursor passes a frame we sent, the time from
sending it to seeing that is folded into a smoothed estimate, and the
interval is twice the estimate, floored at the old 1 s and capped at the
old 8 s. This side cannot see the modem preset, so measuring beats
deriving, and the OPEN/OPEN_OK exchange supplies the first sample before
any keystroke is sent. The replay re-ask uses the same base, for the same
reason: it was asking again before an answer could arrive.

The run bound is untouched: still exactly MAX_INPUT_RETRANSMITS repeats
of one sequence number before the session is declared unrecoverable, and
a frame that has aged out of the ring still fires immediately.

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

* DMShell client: report the round trip the interval is derived from

The retransmission interval is now measured rather than constant, so a run
has to be able to show what it measured. Reporting it only when a
retransmission happens would describe the traffic instead of the
mechanism - the same mistake that made an earlier input-window diagnostic
read as a latch - so the estimate is reported from the poll, which runs
whether or not anything is queued.

The first sample goes to the transcript as well as the replay log, since
it is what tells the operator whether the interval matches the preset in
use, and it lands before any keystroke is sent. After that it is reported
again only once it has moved by a quarter, which on a settled link is
never. The retransmission line names the estimate alongside the interval.

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

* Lock: make the Portduino mutex implementation conditional on Portduino

Two independent build breaks, both from de6269c6 "Add real Lock handling on
Portduino", and both invisible here because every build on this branch has
been `-e native`.

Before: `-e rak_wismesh_pocket` fails at `src/concurrency/Lock.cpp:4` with
`logging.h: No such file or directory`. That header belongs to the Portduino
framework and the include was unconditional, so it broke every target that
is not Portduino: the whole nRF52 family, ESP32 and RP2040 (which take the
FreeRTOS branch and never needed it) and STM32WL. Nothing else in the tree
includes it, and nothing in this file needs it - `LOG_INFO`, `LOG_WARN` and
`console` all arrive through configuration.h, which pulls in
DebugConfiguration.h and SerialConsole.h.

Removing it exposes the second break, which is the real one. The pthread
implementation sat behind a bare `#else`, so it applied to every target
without FreeRTOS - and that set is not "Portduino", it is "Portduino plus
STM32WL". STM32WL builds on arm-none-eabi newlib, which has no pthread.h at
all, so `pthread_mutex_t mutex;` in the header fails to name a type for every
translation unit that includes Lock.h. Before de6269c6 that branch was
no-ops, so nothing outside Portduino ever relied on real locking there.

After: the split is three-way. FreeRTOS keeps its semaphore, Portduino gets
the pthread mutex, and anything else falls back to the upstream no-ops. The
header also includes pthread.h itself on the Portduino path instead of
relying on Arduino.h to have pulled it in.

Verified by compiling Lock.cpp three ways against stand-ins for
freertosinc.h and configuration.h: the FreeRTOS path, the Portduino path,
and a target with neither, the last one with an include path that makes
pthread.h a hard error so it stands in for newlib. All three build clean
under -Wall -Wextra. The same harness reproduces both original failures
exactly. This is not a substitute for CI, which is still the first real
build of the affected targets.

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

* Lock: stop logging on every mutex acquisition on Portduino

Before: `Lock::lock()` emitted `LOG_WARN("Lock")` on every successful
acquisition, and `LOG_INFO("Attempt to lock an already locked Lock!")`
whenever the mutex was already held. There are ~300 lock sites in the tree,
and they include the hottest paths on the device: spiLock around every SPI
transaction, cryptLock around every encrypt and decrypt, and deferredLock on
every received packet. So each of those paid a formatted write to the console
before doing its work.

That matters beyond noise on this branch specifically, because the open
question here is radio-thread latency - a false preamble is abandoned after
~8 ms at ShortTurbo, and one CH341 SPI transaction was already measured at
4-8 ms. Logging inside the lock that serialises those transactions puts I/O
on exactly the path being measured, so it has to go before the next round's
numbers mean anything.

The already-locked line also could not do what it claimed. `locked` records
that the mutex is held by somebody, so an ordinary contention between two
threads - the normal case for spiLock - triggers it just as readily as a
thread re-entering its own lock. It logged before blocking, too, so on a
genuine recursive lock it printed and then hung.

After: the Portduino implementation locks and unlocks, and says nothing. The
`locked` field goes with the lines that read it; nothing else used it.

Recursive-lock detection would be worth having, but it needs the owning
thread recorded and compared against the caller, not a bare held flag, and
that is a deliberate change rather than something to slip into a build fix.
Reverting this commit restores the old lines without touching the build fix
underneath it.

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

* dmshell client: add --peer-log to capture the node's own log

Measuring the radio's own timing on a board whose logs do not reach a serial
console meant choosing between running the session and capturing the log,
because both want the single USB port.  There was no need to choose: the log
already rides the stream the client is reading.  RedirectablePrint's log path
calls log_to_serial for every line, SerialConsole::log_to_serial hands it to
StreamAPI::emitLogRecord, and that writes it as FromRadio.log_record on the same
stream the client takes packets from.  The client was parsing those frames and
discarding them.

--peer-log <file> writes them out instead, one line per record carrying the
local clock, the node's own clock, the level, the thread and the message.  The
local timestamp is what lines a capture up against the client transcript and
against the other node's log.  Records are dropped, as before, when the option
is absent.

The node only emits them when config.security.debug_log_api_enabled is set,
which defaults off; the help text says so.  The write path is called from the
reader loop and swallows OSError, since a full disk should cost the log rather
than the session, and it holds its own lock because a trace-level node produces
thousands of lines a minute.  Log records deliberately do not refresh the
inbound-activity clock: they come from the local node, and letting them stand in
for peer traffic would suppress the heartbeat that drives recovery.

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

* DMShell client: report a session's traffic when it ends

Every measurement round so far has counted dropped and resent frames by
grepping a session log by hand, and in round 7 that produced a median over two
differently-selected populations because three different log lines carry a
last-look figure and only two of them belong to the same deadline. Counting in
the client removes that class of error from the measurement.

--stats prints a summary to stderr when the session ends; --stats-json writes
the same object to a file, which is what an A/B actually needs. Both run from
the same finally block that closes the peer log, so a session that timed out or
was interrupted still reports - that is the run whose numbers matter most.

The counters hook the paths every frame already passes through rather than
adding new ones: note_received_seq classifies inbound frames, send_shell_frame
is the single transmit choke point, and log_replay_event already sees the whole
replay lifecycle. That last one counts before taking its lock, because the write
it guards is skipped when no --replay-log was asked for and the counts must not
depend on a flag.

Two of the numbers are the ones worth comparing between runs. Inbound loss is
the gap between the peer's highest sequence number and what we delivered in
order, which is observable from this end; outbound loss is not, so the
retransmission count stands in for it. transmissions_per_frame is every frame
handed to the radio divided by the frames we originated, so it prices
retransmissions, replays and acks as the airtime they cost.

The counters are cumulative for the session and sit behind their own lock.
input_retransmits and missing_request_attempts deliberately stay as they are:
they reset per sequence number and describe the current gap, not the run.
Distinct gaps are counted on insertion into requested_missing_seqs rather than
per request, since the set drops a sequence number once it is replayed and the
ratio between requests and gaps is the damping working.

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

* DMShell: stop logging at WARN on every frame

Three lines on the hot path were left at WARN: both PTY reads, which fire once
per OUTPUT frame, and the packet-building line in sendFrameToPeer, which fires
once per frame of any kind. WARN is not filtered by log level on any normal
build, and when debug_log_api_enabled is on these also ride the API stream to
whatever client is attached.

This matters for what comes next rather than in principle. The next measurement
is dropped and resent frames under an interactive workload, where the thing
being measured is per-frame cost, and console I/O per frame is the same defect
as the per-acquisition lock logging removed in 59cded1 - which was measurably
load-bearing when it went.

TRACE rather than DEBUG, because the information is per-frame protocol detail
and MESHTASTIC_TRACE_LOGGING already defaults on for Portduino with a runtime
level gate, so a diagnostic run can still ask for it and an ordinary run pays
nothing. The recovery lines stay at WARN deliberately: they are damped, they
are rare, and they are what a measurement run counts.

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

* DMShell client: separate the resend count from total airtime overhead

transmissions_per_frame was every frame handed to the radio over the frames we
originated. That is a real quantity but the name invites reading it as a resend
ratio, and it is not one: in a session where the server is streaming output our
ACKs dominate it, so it can sit at 4.0 on a run with no loss at all. Renamed to
transmissions_per_originated_frame, and the printed line now says what it is.

The number actually wanted is resends, counted in note_frame_resent, which is
the single point both our replays for the peer and our own input
retransmissions pass through. resend_ratio is that over the frames we
originated.

Also fixes an undercount that the old name hid. note_received_seq returns "gap"
for a frame below the cursor when a gap is already open, because a replay
request is the action that frame triggers - so counting the outcome alone
missed the peer's resends during exactly the periods when the peer is
resending. Inbound frames are now counted twice over: what the frame is, judged
against the cursor before it moved, and separately what we did about it. So
duplicates means the peer put that frame on the wire twice, which with resends
above gives loss visible from both directions.

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

* DMShell: let an OUTPUT frame carry the ack when the window is open

Every frame already carries ack_seq, and sendFrameToPeer() zeroes
framesSinceOutbound because of it, so an OUTPUT frame settles the flow-control
debt for free. runOnce() was not taking advantage: the bare-ACK check ran ahead
of the PTY read and returned, so whenever output was waiting the server sent an
ACK and then the data, two frames carrying one cursor, with the data delayed by
a scheduler pass.

That happens more than the immediate read in applySessionFrame() suggests. The
read there runs the instant the input is written, so a shell that has not
produced its echo yet returns nothing, and the echo lands in runOnce() on the
next pass - where the debt is now due.

The bare ACK stays ahead of the window gate for the case the comment there
describes: while our own window is shut we retransmit, a retransmission carries
a stale cursor, and a bare ACK is then the only thing that keeps the peer's
window open when both directions are blocked at once. It is now limited to that
case, and the open-window case is settled after the read, where the counter has
already been cleared if anything went out. Guarded on session.active, because
the read loop also breaks there after closeSession() on EOF or a read error.

No behaviour changes when the PTY is empty: the ACK goes out in the same pass it
used to, just at the end of it.

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

* DMShell client: bound how long input can be held before it goes on the wire

The input batch window restarts on every byte, so it is an idle-gap timer, not
a window. Above one character per 0.5 s each keystroke refreshes the deadline
and nothing leaves until the 64-byte cap or an Enter. Driving the loop as
written at 5 char/s with no Enter gives 50 bytes per frame and a maximum hold
of 12.6 s: twelve seconds of typing with no echo, because the frame carrying it
had not been sent yet.

Keep the per-byte reset, which is what makes burst coalescing work, and cap the
total wait at 2 s from the first byte. Measured on the same driver: 5 char/s
with no Enter goes from 50 bytes and 12.6 s to 10 bytes and 2.0 s; 5 char/s
with Enter every ten characters is unchanged at 10 bytes, because the break on
\r already bounded it; 20 char/s still coalesces to 40 bytes per frame; and one
character per 1.5 s is untouched at one byte per frame and a 0.5 s hold, which
no client-side batching can improve on when the keystrokes are 1.5 s apart.

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

* DMShell: recover a lost OPEN_OK instead of waiting out the open timeout

Round 10 on hardware: the client sent OPEN, heard no OPEN_OK, and waited its
full 180 s --open-timeout, while the server had accepted the session and was
streaming the shell's prompt to nobody.

It could not recover, and not only because nothing retried. OPEN_OK is always
seq 1, and a replay request for seq N encodes as last_rx_seq = N - 1, which
both ends read as "no request" when it is 0. So the client saw the gap when
seq 2 and 3 arrived, and its request for seq 1 went out looking like a bare
ACK. A lost OPEN_OK was unrecoverable by design.

The client now repeats its OPEN while no OPEN_OK has arrived, 5 s doubling to
30 s, with the same session id and seq every time. A naive repeat would have
been worse than none: openSession() preempts the running session, so the
retry would fork a second shell over the first and discard its output. The
server now classifies an OPEN first (classifyOpen() in DMShellRecovery.h):
a repeat of the running session's id from its own peer resends OPEN_OK, and a
new id or another peer still preempts, as before. A repeat is ignored once
the peer's cursor shows it has OPEN_OK, because answering it would replay
seq 1, which on a long session has left the history and would close the
session as replay_evicted.

If the client does give up, it now sends CLOSE, which the server acts on out
of order, rather than leaving the session streaming until its own bounds
notice. Legacy recovery on either end keeps the old single OPEN, so the same
binaries still give an A/B baseline. The retry count is reported as
recovery.open_retries.

Six new cases in test_dmshell_recovery. classifyOpen() compiled and checked
standalone here; the module and the suite were not built, as pio cannot run in
this environment.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* DMShell: time the server's retransmission per frame, from measured ack latency

Round 10 on hardware: arm C, a bulk transfer with zero loss, had 34% of
the frames reaching the client be copies. The server's window-shut
retransmission had the two defects the client fixed in 0246db2:

- The wait was measured from the poll, not the frame. Every cursor
  advance cleared nextRetransmitMs, so the next unacknowledged frame,
  queued moments earlier and often still waiting for the radio, was
  repeated on the very next poll.
- The interval was one derived round trip (two max-length frames plus
  250 ms, ~658 ms at SHORT_FAST). The acknowledgement it waits for
  queues behind up to a window of our own frames, each sitting out a
  CSMA backoff, so it arrives later than that.

Each frame now carries the time it was last handed to the radio, first
send or resend. A cursor advance samples the latency to the frame it
reached, smoothed by a quarter exactly as the client does, and the
interval is twice that, floored at the derived round trip and capped at
REPLAY_REQUEST_MAX_MS. A frame is repeated only once that interval has
passed since its own send.

Also clears the replay history when a session opens. Entries match on
seq alone and every session numbers from 1, so a repeated OPEN could be
answered with the previous session's OPEN_OK.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* DMShell: make the OPEN retry testable, and log the retransmit interval

Round 11 on hardware confirmed the retransmit-timing fix but never
exercised the OPEN retry: no OPEN_OK was lost, so open_retries stayed 0.
The incident it guards against appeared once in a whole session.

--drop-open-ok N discards the first N OPEN_OK frames before any
accounting, as a frame lost on air is, and counts them in
recovery.open_ok_dropped. The client's repeated OPEN then has to recover
the session through the firmware's repeated-OPEN path.

The window-shut retransmit line now carries the interval it waited and
the ack latency estimate behind it. Round 11 measured a median of 5.8 s
from window close to first retransmit, which implies an estimate near
3 s at SHORT_FAST; this shows it directly.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* dmshell_client: stamp --peer-log lines to the millisecond

The host threw the resolution away: strftime gave whole seconds, and LogRecord.time is seconds too.
The stamp is still the arrival time on this host, so it carries the node's API and serial latency.
Measured against 448 frames with known air time, 79.5% of records arrive within 2 ms and 83.3%
within 15 ms, with a queueing tail (p90 +44 ms, p99 +152 ms).

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* DMShell: keep a sessionless ERROR out of the new session's sequence

A frame from an earlier run, still on air when a new client started,
reached the server with no session open. The server rejected it with an
ERROR that took the next sequence number, seq 1, and session id 0. The
new client, still waiting for its OPEN_OK, took that ERROR in order as
seq 1, then dropped the real OPEN_OK (also seq 1) as a duplicate and
acknowledged it. The acknowledgement moved the server's cursor for the
peer, so every repeated OPEN after that read as a late copy, and the
session never opened. Seen twice on the bench, in rounds 30 and 31.

Both ends are fixed; either alone breaks the chain.

- The server sends an ERROR for a frame outside any session of its own
  unsequenced (seq 0), unremembered, echoing the frame's session id.
- The client ignores any frame whose session id is not its own, surfacing
  an ERROR as an event but touching no sequence or cursor state.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

* Fix the Windows/macOS build and the native test crash

The Portduino Lock now takes a real pthread mutex instead of doing nothing,
so a null spiLock is a null dereference rather than a harmless no-op. Only
three of the 89 native suites call initSPI(), so every suite that builds a
NodeDB segfaulted in Lock::lock(). Give spiLock static storage on Portduino
so it is live before initSPI() runs; the embedded targets keep the lazy
construction, since their semaphore cannot be created from a static
initializer.

DMShell drives a login shell through forkpty() and includes <pty.h>, which
the Windows and macOS Portduino hosts do not have. Gate the module on
Linux rather than on ARCH_PORTDUINO alone.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Address the CodeRabbit review

Lock::lock(timeout) on Portduino now honours its deadline: poll
pthread_mutex_trylock to the deadline, since pthread_mutex_timedlock is not
portable to macOS, and return false rather than blocking for good. A zero
timeout no longer waits at all.

DMShell keeps the bytes a nonblocking PTY would not take. write() on a
nonblocking fd may accept less than it was given, and the receive cursor has
already moved past those bytes, so the tail is queued and retried ahead of
any later input rather than being dropped.

A killed shell child is now reaped. SIGKILL ends the process but does not
collect it, so the pid is kept until waitpid() confirms the exit instead of
being cleared straight after the signal.

PING replay uses the highest cursor the peer reported, as
notePeerReceiveCursor() already does. A stale last_rx_seq beside a higher
ack_seq asked for a replay from a frame the history had dropped, which ended
a session the peer was perfectly happy with.

A sequenced frame that never reaches the air gives its number back. The
callers draw from nextTxSeq before sendFrameToPeer(), so a failed packet
allocation or encode left a hole no replay could fill. The encode path also
leaked the packet it had allocated.

In the client, the config handshake now applies --timeout to each blocking
read, so a peer that never answers no longer hangs it for good, and a
non-TTY stdin waits for its queued input to be acknowledged before it sends
CLOSE - the server handles CLOSE ahead of any gap, so piped input longer
than the window was being truncated in silence.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Reformat with the pinned clang-format

Trunk Check runs clang-format 20.1.0 over whole modified files, and these two
spots predate this round of changes: the ternary in handleReceived(), a
LOG_WARN argument wrap, and one trailing comment in the recovery test. No
code changes.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Keep every unreaped child, and never take the lock late

A close arriving while the previous child was still dying overwrote the one
pending slot, so that pid was lost and its zombie stayed. Keep a small set of
pending children instead, each held until waitpid() confirms its exit.

The timed lock checked its deadline before sleeping, so a mutex that came
free during the sleep could be taken just past the deadline. Check
immediately before each retry instead.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Give the native tests a cryptLock

The same class of crash as spiLock, one layer further in: only Router's
constructor creates cryptLock, and a suite can reach the admin and crypto
paths that take it without ever building a Router. test_module_config died
in AdminModule::setPassKey for exactly that reason. Create it in
initializeTestEnvironment(), which 86 of the 89 suites call.

Router's constructor then has to stop asserting that the lock is null.
It now uses the idiom on the next line of the same constructor, the one
routingAuthCacheLock has always used: nothing in src/ ever deletes the
lock, so one that already exists is the process's only one.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Never drop a pending child pid

With every slot full, a further close dropped the pid and left a zombie.
Wait for the child in the first slot instead: it has had SIGKILL, which
cannot be caught or blocked, so it dies unless it is stuck in the kernel.
A blanket waitpid(-1) would be shorter but would swallow the exit status
of the popen() in PortduinoGlue.

reapChildIfExited() now treats ECHILD as the shell having exited, so a
child collected elsewhere still ends the session rather than leaving it to
the five-minute idle timeout.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Link the DMShell recovery suite

test_dmshell_recovery ERRORED at link with undefined references to setup
and loop from portduino's main.cpp. Portduino declares both extern "C",
and this is the only suite whose includes never reach a platform header:
DMShellRecovery.h deliberately pulls in nothing but mesh/Throttle.h so it
can be driven from a native test, and TestUtil.h stops at unity.h. The
definitions were therefore mangled and main() could not find them.

Include Arduino.h, as test_throttle already does.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Stop the test mocks deleting cryptLock

The mock routers freed the global crypt lock in their destructors, each
with a comment pointing at the reason: Router's constructor asserted the
global was null before allocating it, so a suite that built more than one
router had to hand it back. That assert is gone - the constructor now
reuses an existing lock, the same idiom as routingAuthCacheLock on the
next line - and nothing in src/ has ever freed it, so these deletes now
free a lock the mock does not own and leave the global null behind them.

test_admin_radio is where that bites: ~HamModeMockRouter runs from
tearDown, and the next test reaches AdminModule's receive path, which
takes LockGuard(cryptLock) - a null dereference now that the Portduino
Lock is a real mutex. The other six were the same hazard waiting for a
suite to add a test after them.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Bind client frames to the selected peer, and bound its reorder buffer

Two client-side holes CodeRabbit's architecture pass kept on its list.

The reader matched a frame to the session on the session id alone, which
is carried in the frame and so is not an identity: any sender whose
decoded packets reach this stream could match it and then write to the
terminal, move the cursors or close the session. Drop anything not from
the node --to selected.

The out-of-order dictionary had no bound, unlike the server's eight fixed
slots, so a peer that never filled a gap grew it for the life of the
session. Bound it at the same eight and evict by the same rule: the
lowest sequence numbers are needed soonest, so the highest held is the
one worth losing, and only to something lower than it.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Never signal a reaped pid, and never silently lose input

Two findings from CodeRabbit's pass over 401b7a6, both real.

reapChildIfExited() calls closeSession() once waitpid() has collected the
shell's exit - but closeSession() then sends SIGTERM to session.childPid,
which at that point names a pid the kernel is free to have handed to an
unrelated process. Clear the pid before closing, so nothing signals it.

A rejected INPUT answered with an ERROR. The frame's sequence number is
already acknowledged by the time the write is attempted, so the peer will
never send those bytes again and no replay can recover them; the client
treats ERROR as non-terminal and carries on with a hole in the command
line. Close the session instead, which for a shell is the lesser harm.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Bound the handshake frame scan by its deadline

--timeout was enforced per read, not over the scan for a frame marker. A
wrong port or a noisy serial line delivers bytes steadily, so every read
returns inside its own timeout and recv_stream_frame() never comes back to
the caller's clock - the handshake then runs past the deadline it was
given. Pass the deadline in and check it each time around the scan.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Hold the handshake deadline over a whole frame, and assert the payload

recv_stream_frame() checked the deadline only while scanning for the start
marker. A sender that trickles returns a byte inside every read timeout,
so a frame arriving one byte at a time still ran past --timeout; the
deadline now reaches recv_exact() and is checked per chunk.

The RemoteShell round-trip helper took a payload and never encoded it, so
the INPUT and CLOSE cases asserted an empty body and would have passed
against a serializer that dropped their bytes. Copy it in and assert it
back.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* Three narrow failure cases around the new timed lock

ReentrantSpiLock::lock(timeout) recorded this thread as the owner whether
or not the underlying lock was taken. That was harmless while Portduino's
timed lock could not fail - it blocked until it had the mutex - but this
branch gives it a real deadline, so a false result would leave the thread
passing the reentrancy check without holding the mutex and unlocking one
it never took. Claim ownership only on success.

Lock::Lock() ignored a failed pthread_mutex_init, leaving every later use
of the mutex undefined. Abort, as the FreeRTOS branch beside it does.

The client set the transport timeout once before reading a frame, so a
frame arriving near the deadline could run nearly a full read timeout past
it. recv_exact() now shortens the transport's timeout to what is left.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VeY5PczVYsxWNZhE2Cx4Sv

* DMShell client: bound a torn stream frame, and count the resyncs

Bench fixes that ran on every round since 46 but were never committed, so a
stash across a server rebuild silently dropped them. (The millisecond peer-log
stamps are already here as 17614a5ac.)

MAX_STREAM_FRAME bounds the length a header may claim: a torn header can name
any 16-bit value, and reading that many bytes stalls the session waiting for
bytes the node never sends. A byte that fails START2, or a rejected header, is
scanned again for the real frame's START1, as StreamAPI does.

STREAM_RESYNC and torn_frames count what the framing had to step over. A frame
destroyed on the USB stream is one the node did send and the radio did receive,
and it reaches the ledger as a replay request - indistinguishable from a frame
the radio never heard. A run reporting non-zero has lost frames to the
transport and its receive miss reads high by that much. Both are exported in
stats.json.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

---------

Co-authored-by: James Rich <james.a.rich@gmail.com>
Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
2026-10-02 03:48:17 +00:00

1952 lines
88 KiB
Python

#!/usr/bin/env python3
import argparse
import json
import os
import queue
import random
import shutil
import socket
import select
import subprocess
import sys
import tempfile
import termios
import threading
import time
import tty
from collections import Counter, deque
from dataclasses import dataclass, field
from pathlib import Path
from typing import Optional, TextIO
START1 = 0x94
START2 = 0xC3
# StreamAPI's own cap on a frame. A torn header can claim any 16-bit length, and reading that many
# bytes would stall the session waiting for bytes the node never sends, so anything larger is treated
# as a bad header and skipped rather than believed.
MAX_STREAM_FRAME = 512
# Every point at which the framing had to resynchronise. These matter to a measurement, not just to
# robustness: a frame destroyed on the USB stream is one the node did send and the radio did receive,
# and it reaches the ledger as a replay request - indistinguishable from a frame the radio never
# heard, which is what the bench is trying to measure. A run reporting non-zero here has lost frames
# to the transport and its receive miss reads high by that much.
STREAM_RESYNC = {"stray_bytes": 0, "bad_header": 0, "bad_start2": 0}
HEADER_LEN = 4
DEFAULT_API_PORT = 4403
# Zero, and this is about airtime rather than reachability. A non-zero hop limit arms two
# mechanisms in the firmware that DMShell wants nothing from. NextHopRouter::sendWithNextHop starts
# its own relay retransmissions for the packet - its gate is (hop_limit > 0 || want_ack) with a
# known next hop - and those repeats reuse the packet id, so the far end discards them in
# shouldFilterReceived as dupes after paying for them on the air. Then, to stop them,
# ReliableRouter::sniffReceived answers every single frame with a 0-hop routing ACK, which is an
# extra transmission from the peer in the same direction as its own shell output, on a half-duplex
# channel. Neither is visible to this protocol: DMShell carries its own sequence numbers and
# cursors, and sets want_ack = False for exactly that reason.
#
# Zero is also symmetric with the firmware, which already sends its side of the session with
# hop_limit = 0, so DMShell is a direct-neighbour protocol in both directions either way. It
# survives the receiver's pre-hop drop policy because hop_start == 0 is accepted when the Data
# bitfield is present (classifyHopStart in NodeDB.cpp) and perhapsEncode sets that on every
# locally-originated packet - which is what makes the firmware's own hop_limit = 0 frames arrive
# here. Raise it with --hop-limit only to restore the old behaviour for a comparison.
DEFAULT_HOP_LIMIT = 0
LOCAL_ESCAPE_BYTE = b"\x1d" # Ctrl+]
# The floor, and the bootstrap before a single round trip has been observed. It is not the interval:
# a flat 1 s is shorter than one frame's time on air at LongFast (~2.2 s), so repeating on it queues
# a second copy of a frame that is still being transmitted, and a third behind that. The live
# interval is derived from the measured acknowledgement latency instead - see
# _retransmit_base_interval_locked.
MISSING_SEQ_RETRY_INTERVAL_SEC = 1.0
# A gap the peer cannot fill used to be retried at a flat 1/sec until the 5-minute idle timeout, so
# the retry needs *some* bound. But measured on hardware, every repeat within the first few attempts
# was a collision on a gap that did fill (8 of 8 recovered, worst case 5 attempts), and backing off
# there only delays a recovery that was going to work - visibly, in an interactive shell. So hold the
# base interval for the first few attempts and only grow once "unfillable" is the better hypothesis.
# The ceiling is low because the firmware now reports a genuinely evicted frame in one round trip;
# this only has to bound the residue (a peer without that fix, or a lost teardown).
MISSING_SEQ_RETRY_FLAT_ATTEMPTS = 4
MISSING_SEQ_RETRY_MAX_SEC = 8.0
# How much of a new acknowledgement-latency sample to believe. Low, because the quantity we want is
# the preset's frame time, which does not change within a session, while any single sample also
# carries that frame's queueing and its collisions.
ACK_LATENCY_SMOOTHING = 0.25
# The interval is this multiple of the estimate: one frame out and one acknowledgement back are
# already in the estimate, so the margin is for the peer's own queue.
RETRANSMIT_LATENCY_MULTIPLIER = 2.0
# Report the estimate again once it has moved this much, which on a settled link is never.
ACK_LATENCY_REPORT_CHANGE = 0.25
INPUT_BATCH_WINDOW_SEC = .5
INPUT_BATCH_MAX_BYTES = 64
# The idle gap above restarts on every byte, so a steady typist can be held until the
# byte cap. Bound the wait from the first byte so input latency stays predictable.
INPUT_BATCH_MAX_HOLD_SEC = 2.0
HEARTBEAT_IDLE_DELAY_SEC = 5.0
HEARTBEAT_REPEAT_SEC = 15.0
HEARTBEAT_POLL_INTERVAL_SEC = 0.25
# The server bounds how much unacknowledged output it keeps in flight, so it needs our receive cursor
# to make progress. On a one-way stream we would otherwise transmit nothing at all - the heartbeat is
# suppressed while inbound traffic keeps arriving - so the stream would advance one window per
# heartbeat instead of continuously. Every frame we send already carries ack_seq, so this only has to
# fire when we have nothing else to say.
#
# Must not exceed the server's window (DMSHELL_TX_WINDOW, default 4), or it stalls: the server blocks
# with its window full while we are still waiting to accumulate frames, and only the heartbeat breaks
# the deadlock.
def _ack_after_frames() -> int:
raw = os.environ.get("DMSHELL_ACK_EVERY", "")
if not raw:
return 2
try:
return max(1, int(raw))
except ValueError:
print(f"[dmshell] ignoring unparseable DMSHELL_ACK_EVERY={raw!r}", file=sys.stderr)
return 2
ACK_AFTER_FRAMES = _ack_after_frames()
def _input_window_frames() -> int:
raw = os.environ.get("DMSHELL_INPUT_WINDOW", "")
if not raw:
return 4
try:
value = int(raw)
except ValueError:
print(f"[dmshell] ignoring unparseable DMSHELL_INPUT_WINDOW={raw!r}", file=sys.stderr)
return 4
if value < 0 or value > 50:
print(f"[dmshell] DMSHELL_INPUT_WINDOW={raw!r} outside 0-50, using 4", file=sys.stderr)
return 4
return value
# The mirror of the server's DMSHELL_TX_WINDOW, and the other half of the same failure. The server
# bounds its output; nothing bounded our input, so at LongFast - where we emit keystrokes far faster
# than the server drains them - our own 50-frame replay ring was outrun and the session died with
# replay_evicted, exactly as the server's did at ShortTurbo before it was bounded. 0 restores the
# unbounded behaviour for measuring one build both ways.
INPUT_WINDOW_FRAMES = _input_window_frames()
# Bytes of typed input held locally while the window is shut. The keystrokes are the user's, so
# dropping them is not an option; this is the backpressure, and the shape of the local terminal's own
# tty buffer. Generous, because the frames it holds are small and the alternative is losing input.
PENDING_INPUT_MAX_BYTES = 4096
# Out-of-order frames held while a gap is outstanding, mirroring DMShellRxReorder::SLOTS in the
# firmware: twice the peer's default send window, so a well-behaved peer never fills it.
REORDER_SLOTS = 8
# Consecutive retransmissions of one input frame before we give up on the server, matching the
# firmware's bound. The interval escalates the way a replay re-ask does, because unlike the firmware
# we cannot read the modem config: that puts the allowance at roughly 1 s x 4 then doubling to an 8 s
# ceiling, so 25 repeats span about two and a half minutes.
MAX_INPUT_RETRANSMITS = 25
# A lost OPEN or OPEN_OK costs a full frame airtime, which is ~2.2 s on LongFast against ~0.1 s on
# ShortTurbo, so the handshake needs far more headroom than the API socket does. Measured: a LongFast
# session needed 150 s to open.
DEFAULT_OPEN_TIMEOUT_SEC = 180.0
# Repeat the OPEN while no OPEN_OK has come back, doubling from the first interval to the ceiling. A lost
# OPEN_OK cannot be recovered any other way: it is always seq 1, and a replay request for seq 1 encodes as
# last_rx_seq 0, which both ends read as "no request". The firmware answers a repeat of the session it is
# already running by resending OPEN_OK, so a repeat that crosses a slow OPEN_OK in flight costs one
# duplicate frame and nothing else. The first interval sits just above a clean LongFast round trip, two
# frames of about 2.2 s each, and is still a small fraction of the timeout on every faster preset.
OPEN_RETRY_FIRST_SEC = 5.0
OPEN_RETRY_MAX_SEC = 30.0
def parse_args() -> argparse.Namespace:
parser = argparse.ArgumentParser(
description="Tiny DMShell client for Meshtastic native TCP API",
epilog=(
"Examples:\n"
" bin/dmshell_client.py --to !170896f7\n"
" bin/dmshell_client.py --to 0x170896f7 --command 'uname -a' --command 'id'"
),
formatter_class=argparse.RawDescriptionHelpFormatter,
)
parser.add_argument("--host", default="127.0.0.1", help="meshtasticd API host")
parser.add_argument("--port", type=int, default=DEFAULT_API_PORT, help="meshtasticd API port")
parser.add_argument(
"--serial",
nargs="?",
const="auto",
default=None,
help="use USB serial transport (optionally provide device path, default: auto-detect)",
)
parser.add_argument("--baud", type=int, default=115200, help="serial baud rate when using --serial")
parser.add_argument("--to", required=True, help="destination node number, e.g. !170896f7 or 0x170896f7")
parser.add_argument("--channel", type=int, default=0, help="channel index to use")
parser.add_argument(
"--hop-limit",
type=int,
default=DEFAULT_HOP_LIMIT,
help="hop limit (default %(default)s; non-zero arms the firmware's relay retransmissions "
"and makes the peer routing-ACK every frame)",
)
parser.add_argument(
"--peer-log",
type=Path,
default=None,
help="write the node's own LogRecords to this file. They arrive on the same API stream as "
"everything else, so this captures the radio's log during a live session without needing a "
"second port. Needs config.security.debug_log_api_enabled set on the node.",
)
parser.add_argument("--cols", type=int, default=None, help="initial terminal columns (default: detect local terminal)")
parser.add_argument("--rows", type=int, default=None, help="initial terminal rows (default: detect local terminal)")
parser.add_argument("--command", action="append", default=[], help="send a command line after opening")
parser.add_argument("--close-after", type=float, default=2.0, help="seconds to wait before closing in command mode")
parser.add_argument("--timeout", type=float, default=10.0, help="seconds to wait for API/session events")
parser.add_argument(
"--open-timeout",
type=float,
default=DEFAULT_OPEN_TIMEOUT_SEC,
help="seconds to wait for OPEN_OK (needs to be generous on slow presets; default %(default)s)",
)
parser.add_argument(
"--stats",
action="store_true",
help="print a traffic summary to stderr when the session ends",
)
parser.add_argument(
"--stats-json",
type=Path,
default=None,
help="write the same traffic summary to this file as JSON (implies --stats)",
)
parser.add_argument("--verbose", action="store_true", help="print extra protocol events")
parser.add_argument(
"--drop-open-ok",
type=int,
default=0,
metavar="N",
help="test only: discard the first N OPEN_OK frames as if lost on air, to exercise the OPEN retry",
)
parser.add_argument(
"--legacy-recovery",
action="store_true",
help="retry a missing sequence number at a flat 1/sec instead of backing off "
"(pair with DMSHELL_LEGACY_RECOVERY=1 on the node to measure the pre-fix behaviour)",
)
return parser.parse_args()
def repo_root() -> Path:
return Path(__file__).resolve().parent.parent
def load_proto_modules() -> object:
try:
import google.protobuf # noqa: F401
except ImportError as exc:
raise SystemExit("python package 'protobuf' is required to run this client") from exc
protoc = shutil.which("protoc")
if not protoc:
raise SystemExit("'protoc' is required to generate temporary Python protobuf bindings")
out_dir = Path(tempfile.mkdtemp(prefix="meshtastic_dmshell_proto_"))
proto_dir = repo_root() / "protobufs"
# Compile all required protos for DMShell client (mesh and dependencies)
# Excludes nanopb.proto and other complex build artifacts
required_protos = [
"mesh.proto",
"channel.proto",
"config.proto",
# config.proto imports this. protoc resolves it via -I for compilation but only emits a
# _pb2 module for files named on the command line, so without it config_pb2 imports a
# module that was never generated and the client cannot start.
"field_metadata.proto",
"device_ui.proto",
"module_config.proto",
"atak.proto",
"portnums.proto",
"telemetry.proto",
"xmodem.proto",
]
proto_files = [proto_dir / "meshtastic" / name for name in required_protos]
for pf in proto_files:
if not pf.exists():
raise SystemExit(f"could not find required proto file: {pf}")
# Create __init__.py to make meshtastic a package
(out_dir / "meshtastic").mkdir(exist_ok=True)
(out_dir / "meshtastic" / "__init__.py").touch()
# Build protoc command with just the meshtastic proto directory as include path
# protoc will use its built-in includes for standard google protobuf types
cmd = [protoc, f"-I{proto_dir}", f"--python_out={out_dir}", *[str(path) for path in proto_files]]
result = subprocess.run(cmd, capture_output=True, text=True)
if result.returncode != 0:
print(f"protoc stderr: {result.stderr}", file=sys.stderr)
print(f"protoc stdout: {result.stdout}", file=sys.stderr)
print(f"protoc command: {' '.join(cmd)}", file=sys.stderr)
raise SystemExit(f"protoc failed with return code {result.returncode}")
# Create _pb2_grpc module stub if not present (protoc 3.20+)
mesh_pb2_file = out_dir / "meshtastic" / "mesh_pb2.py"
if not mesh_pb2_file.exists():
raise SystemExit(f"protoc did not generate mesh_pb2.py in {out_dir / 'meshtastic'}")
sys.path.insert(0, str(out_dir))
try:
from meshtastic import mesh_pb2, portnums_pb2 # type: ignore
except ImportError as exc:
print("Failed to import protobuf modules. Output dir contents:", file=sys.stderr)
for item in (out_dir / "meshtastic").iterdir():
print(f" {item.name}", file=sys.stderr)
raise SystemExit(f"could not import meshtastic proto modules: {exc}") from exc
# Return an object that has both modules accessible
class ProtoModules:
pass
pb2 = ProtoModules()
pb2.mesh = mesh_pb2
pb2.portnums = portnums_pb2
return pb2
def parse_node_num(raw: str) -> int:
value = raw.strip()
if value.startswith("!"):
value = value[1:]
if value.lower().startswith("0x"):
return int(value, 16)
if any(ch in "abcdefABCDEF" for ch in value):
return int(value, 16)
return int(value, 10)
class SerialTransport:
def __init__(self, serial_obj):
self._serial = serial_obj
def recv(self, length: int) -> bytes:
return self._serial.read(length)
def settimeout(self, value) -> None:
self._serial.timeout = value
def sendall(self, data: bytes) -> None:
self._serial.write(data)
self._serial.flush()
def close(self) -> None:
self._serial.close()
def detect_meshtastic_serial_port() -> str:
try:
from serial.tools import list_ports
except ImportError as exc:
raise SystemExit("python package 'pyserial' is required for --serial mode") from exc
ports = list(list_ports.comports())
if not ports:
raise SystemExit("no serial ports found for --serial mode")
scored: list[tuple[int, str]] = []
for port in ports:
text = " ".join(
filter(
None,
[port.device, port.description, port.manufacturer, port.product, port.hwid],
)
).lower()
score = 0
if "meshtastic" in text:
score += 100
if "lora" in text or "mesh" in text:
score += 10
if "ttyacm" in (port.device or "").lower() or "ttyusb" in (port.device or "").lower():
score += 1
scored.append((score, port.device))
scored.sort(reverse=True)
best_score, best_device = scored[0]
if best_score <= 0 and len(scored) > 1:
raise SystemExit(
"could not confidently auto-detect a Meshtastic serial port; pass --serial /dev/ttyXXX explicitly"
)
return best_device
def open_transport(args: argparse.Namespace):
if args.serial is None:
sock = socket.create_connection((args.host, args.port), timeout=args.timeout)
sock.settimeout(None)
return sock
serial_path = args.serial
if serial_path == "auto":
serial_path = detect_meshtastic_serial_port()
print(f"[dmshell] using serial port {serial_path}", file=sys.stderr)
try:
import serial
except ImportError as exc:
raise SystemExit("python package 'pyserial' is required for --serial mode") from exc
try:
serial_obj = serial.Serial(serial_path, baudrate=args.baud, timeout=None, write_timeout=2)
except Exception as exc:
raise SystemExit(f"failed to open serial device {serial_path}: {exc}") from exc
return SerialTransport(serial_obj)
def recv_exact(transport, length: int, deadline: Optional[float] = None) -> bytes:
chunks = bytearray()
while len(chunks) < length:
# A trickling sender returns a byte inside every read timeout, so the per-read timeout alone
# cannot bound a frame that arrives one byte at a time. Checked per chunk when a caller has a
# deadline to keep, and the transport's own timeout is shortened to what is left of it - a
# timeout set once before the first read would let the last one run a full timeout past the
# deadline. Without a deadline the loop behaves as it always did.
if deadline is not None:
remaining = deadline - time.monotonic()
if remaining <= 0:
raise TimeoutError("incomplete stream-API frame at the deadline")
transport.settimeout(remaining)
piece = transport.recv(length - len(chunks))
if not piece:
raise ConnectionError("connection closed by transport")
chunks.extend(piece)
return bytes(chunks)
def detect_local_terminal_size() -> tuple[int, int]:
size = shutil.get_terminal_size(fallback=(100, 40))
cols = max(1, int(size.columns))
rows = max(1, int(size.lines))
return cols, rows
def resolve_initial_terminal_size(cols_override: Optional[int], rows_override: Optional[int]) -> tuple[int, int]:
detected_cols, detected_rows = detect_local_terminal_size()
cols = detected_cols if cols_override is None else max(1, cols_override)
rows = detected_rows if rows_override is None else max(1, rows_override)
return cols, rows
def recv_stream_frame(transport, deadline: Optional[float] = None) -> bytes:
"""Read one stream-API frame, skipping whatever precedes its start marker.
deadline is a time.monotonic() value that bounds the whole read, not each recv(). A transport
timeout cannot do that job: a wrong port or a noisy serial line delivers bytes steadily, every
read returns inside its own timeout, and neither the marker scan nor a frame arriving a byte at a
time ever comes back to the caller's clock.
"""
# Bytes read but not consumed: a failed START2 or a bad header can hold the real frame's START1
pending = []
def next_byte() -> int:
return pending.pop(0) if pending else recv_exact(transport, 1, deadline)[0]
while True:
if next_byte() != START1:
# A byte where a frame should begin: the stream is mid-resynchronisation.
STREAM_RESYNC["stray_bytes"] += 1
continue
second = next_byte()
if second != START2:
# That byte can itself be the START1 of the real frame (0x94 0x94 0xc3), as StreamAPI allows
STREAM_RESYNC["bad_start2"] += 1
pending.insert(0, second)
continue
header = bytes(next_byte() for _ in range(2))
length = (header[0] << 8) | header[1]
if length > MAX_STREAM_FRAME:
# Out of bounds: this was not a real header. Resynchronise on the next START1, which can be in it.
STREAM_RESYNC["bad_header"] += 1
pending[:0] = header
continue
body = bytes(pending[:length])
del pending[:length]
return body + recv_exact(transport, length - len(body), deadline)
def send_stream_frame(transport, payload: bytes) -> None:
if len(payload) > 0xFFFF:
raise ValueError("payload too large for stream API")
header = bytes((START1, START2, (len(payload) >> 8) & 0xFF, len(payload) & 0xFF))
transport.sendall(header + payload)
@dataclass
class SentShellFrame:
op: int
session_id: int
seq: int
ack_seq: int
payload: bytes = b""
cols: int = 0
rows: int = 0
flags: int = 0
last_tx_seq: int = 0
last_rx_seq: int = 0
# When this frame was last handed to the API, retransmissions included. Read for two things: no
# frame is repeated before it has been outstanding for a full interval, and the interval itself
# is measured from how long acknowledgement actually takes on this link.
sent_time: float = 0.0
@dataclass
class SessionState:
pb2: object # ProtoModules with mesh and portnums attributes
target: int
channel: int
verbose: bool
hop_limit: int = DEFAULT_HOP_LIMIT
session_id: int = field(default_factory=lambda: random.randint(1, 0x7FFFFFFF))
next_seq: int = 1
last_rx_seq: int = 0
next_expected_rx_seq: int = 1
highest_seen_rx_seq: int = 0
active: bool = False
stopped: bool = False
opened_event: threading.Event = field(default_factory=threading.Event)
closed_event: threading.Event = field(default_factory=threading.Event)
event_queue: "queue.Queue[str]" = field(default_factory=queue.Queue)
tx_lock: threading.Lock = field(default_factory=threading.Lock)
socket_lock: threading.Lock = field(default_factory=threading.Lock)
tx_history: deque[SentShellFrame] = field(default_factory=lambda: deque(maxlen=50))
pending_rx_frames: dict[int, object] = field(default_factory=dict)
last_requested_missing_seq: int = 0
last_missing_request_time: float = 0.0
missing_request_interval: float = MISSING_SEQ_RETRY_INTERVAL_SEC
missing_request_attempts: int = 0
frames_since_outbound: int = 0
legacy_recovery: bool = False
drop_open_ok: int = 0
requested_missing_seqs: set[int] = field(default_factory=set)
replay_log_lock: threading.Lock = field(default_factory=threading.Lock)
replay_log_file: Optional[TextIO] = None
replay_log_path: Optional[Path] = None
# The node's own log, arriving as FromRadio.log_record on this same stream. Separate lock and
# handle from the replay log: this one can run to thousands of lines a minute at trace level.
peer_log_lock: threading.Lock = field(default_factory=threading.Lock)
peer_log_file: Optional[TextIO] = None
peer_log_path: Optional[Path] = None
peer_log_records: int = 0
# Frames dropped mid-flight on the wire, skipped and resynchronised past rather than fatal.
torn_frames: int = 0
# Cumulative counters behind their own lock, for the end-of-session summary. Every one is
# monotonic for the life of the session, unlike input_retransmits and missing_request_attempts,
# which reset per sequence number and so describe the current gap rather than the run.
stats_lock: threading.Lock = field(default_factory=threading.Lock)
stats: Counter = field(default_factory=Counter)
stats_started_at: float = field(default_factory=time.monotonic)
last_transport_activity_time: float = field(default_factory=time.monotonic)
# Inbound only. The heartbeat has to key off the peer's silence, not off any traffic: our own
# keystrokes used to suppress it (see heartbeat_due).
last_inbound_time: float = field(default_factory=time.monotonic)
last_heartbeat_sent_time: float = 0.0
# Outbound flow control, mirroring the firmware's txWindow. peer_acked_tx_seq is the server's
# cumulative receive cursor over our frames; see note_peer_receive_cursor.
input_window_frames: int = INPUT_WINDOW_FRAMES
peer_acked_tx_seq: int = 0
input_window_blocked: bool = False
# Held across taking bytes off pending_input and transmitting them. The input thread and the
# heartbeat thread both flush, and two takes that interleave with two sends would put the user's
# keystrokes on the wire out of order.
input_lock: threading.Lock = field(default_factory=threading.Lock)
pending_input: bytearray = field(default_factory=bytearray)
pending_input_dropped: int = 0
next_input_retransmit_time: float = 0.0
input_retransmit_interval: float = MISSING_SEQ_RETRY_INTERVAL_SEC
input_retransmit_seq: int = 0
input_retransmits: int = 0
# Smoothed time from sending a frame to seeing the peer's cursor pass it. None until the first
# sample, which the OPEN/OPEN_OK exchange supplies before any input is sent.
ack_latency: Optional[float] = None
# The last value reported, so a run's log shows what the interval was derived from even when no
# retransmission ever happens. A diagnostic that only appears on the busy path describes the
# traffic rather than the mechanism.
ack_latency_reported: Optional[float] = None
def alloc_seq(self) -> int:
with self.tx_lock:
value = self.next_seq
self.next_seq += 1
return value
def current_ack_seq(self) -> int:
with self.tx_lock:
return self.last_rx_seq
def highest_sent_seq(self) -> int:
with self.tx_lock:
return max(0, self.next_seq - 1)
def note_outbound_packet(self, heartbeat: bool = False) -> None:
with self.tx_lock:
now = time.monotonic()
# Anything we send carries our receive cursor in ack_seq, so it settles the flow-control
# debt whatever its opcode.
self.frames_since_outbound = 0
if heartbeat:
self.last_heartbeat_sent_time = now
else:
self.last_transport_activity_time = now
def note_inbound_packet(self) -> None:
with self.tx_lock:
now = time.monotonic()
self.last_transport_activity_time = now
self.last_inbound_time = now
def heartbeat_due(self) -> bool:
"""Whether to probe a peer that has gone quiet.
Keyed on inbound silence alone. It used to key on traffic in either direction, so our own
keystrokes reset it - and typing faster than HEARTBEAT_IDLE_DELAY_SEC suppressed the heartbeat
entirely. That mattered because the server's PING handler is what retransmits a frame we are
missing, so an interactive user typing into a stalled session silenced their own recovery. A
healthy stream still sends no heartbeats, because inbound traffic keeps arriving.
"""
with self.tx_lock:
now = time.monotonic()
if (now - self.last_inbound_time) < HEARTBEAT_IDLE_DELAY_SEC:
return False
if self.last_heartbeat_sent_time <= self.last_inbound_time:
return True
return (now - self.last_heartbeat_sent_time) >= HEARTBEAT_REPEAT_SEC
def note_peer_receive_cursor(self, ack_seq: int, last_rx_seq: int) -> None:
"""Take the server's cumulative cursor over our frames from any inbound frame.
Both fields mean "the highest sequence number I have in order": the server sets ack_seq on
every frame it originates and last_rx_seq explicitly when it asks for a replay, so the larger
is the cursor. Clamped to what we have actually sent, so a confused peer cannot grant credit
past our own progress, and monotone, so a replay carrying a stale cursor cannot close the
window again. The mirror of the firmware's notePeerReceiveCursor().
"""
cursor = max(ack_seq, last_rx_seq)
with self.tx_lock:
highest_sent = max(0, self.next_seq - 1)
cursor = min(cursor, highest_sent)
if cursor <= self.peer_acked_tx_seq:
return
self._sample_ack_latency_locked(cursor)
self.peer_acked_tx_seq = cursor
# Progress proves the server is alive, so the run that would eventually declare it gone
# starts over, and the next stall gets a fresh interval. Clearing the deadline does not
# make the next frame instantly repeatable: input_retransmit_due re-arms it from that
# frame's own send time.
self.next_input_retransmit_time = 0.0
self.input_retransmit_interval = self._retransmit_base_interval_locked()
self.input_retransmit_seq = 0
self.input_retransmits = 0
def _sent_time_locked(self, seq: int) -> Optional[float]:
"""When we last transmitted seq, or None if the ring no longer holds it. Caller holds tx_lock."""
for frame in reversed(self.tx_history):
if frame.seq == seq:
return frame.sent_time or None
return None
def _sample_ack_latency_locked(self, cursor: int) -> None:
"""Fold the round trip for the frame the cursor just reached into the estimate.
The sample is the whole path we have to wait out before repeating anything: our frame's time
on air, the peer's processing, and its reply's time on air. Measuring it beats deriving it,
because this side cannot see the modem preset and the derivation would have to guess at
queueing. The first sample comes from OPEN/OPEN_OK, which is why an estimate exists before
any keystroke is sent. Caller holds tx_lock.
"""
sent_at = self._sent_time_locked(cursor)
if sent_at is None:
return
sample = time.monotonic() - sent_at
if sample <= 0:
return
if self.ack_latency is None:
self.ack_latency = sample
else:
self.ack_latency += ACK_LATENCY_SMOOTHING * (sample - self.ack_latency)
def _retransmit_base_interval_locked(self) -> float:
"""Give the first interval to wait before repeating anything. Caller holds tx_lock."""
if self.ack_latency is None:
return MISSING_SEQ_RETRY_INTERVAL_SEC
scaled = RETRANSMIT_LATENCY_MULTIPLIER * self.ack_latency
return min(max(scaled, MISSING_SEQ_RETRY_INTERVAL_SEC), MISSING_SEQ_RETRY_MAX_SEC)
def note_frame_resent(self, seq: int) -> None:
"""Restamp a frame we have just put back on the wire, so the next wait is measured from it."""
self.bump("frames_resent")
now = time.monotonic()
with self.tx_lock:
for frame in reversed(self.tx_history):
if frame.seq == seq:
frame.sent_time = now
return
def outstanding_input(self) -> int:
with self.tx_lock:
return max(0, self.next_seq - 1) - self.peer_acked_tx_seq
def input_window_open(self) -> bool:
with self.tx_lock:
if self.input_window_frames == 0:
return True
return (max(0, self.next_seq - 1) - self.peer_acked_tx_seq) < self.input_window_frames
def queue_input(self, data: bytes) -> int:
"""Hold typed input until the window reopens. Returns how many bytes had to be dropped."""
with self.tx_lock:
room = PENDING_INPUT_MAX_BYTES - len(self.pending_input)
if room <= 0:
self.pending_input_dropped += len(data)
return len(data)
kept = data[:room]
dropped = len(data) - len(kept)
self.pending_input.extend(kept)
self.pending_input_dropped += dropped
return dropped
def take_queued_input(self, limit: int) -> bytes:
with self.tx_lock:
if not self.pending_input:
return b""
chunk = bytes(self.pending_input[:limit])
del self.pending_input[:len(chunk)]
return chunk
def has_queued_input(self) -> bool:
with self.tx_lock:
return bool(self.pending_input)
def input_retransmit_due(self) -> tuple[Optional[int], bool]:
"""The input frame to repeat while the window is shut, and whether the allowance is spent.
Symmetric to the firmware's retransmitOldestUnacked, and needed for the same reason: with our
window full the server never sees a sequence number above the gap, so it never asks for the
replay that would reopen us. Its only trigger is an arriving frame, and we have stopped
sending. Without this the session latches silently.
"""
with self.tx_lock:
if self.input_window_frames == 0 or self.legacy_recovery:
return (None, False)
highest_sent = max(0, self.next_seq - 1)
missing = self.peer_acked_tx_seq + 1
if missing > highest_sent:
return (None, False)
now = time.monotonic()
if now < self.next_input_retransmit_time:
return (None, False)
if missing != self.input_retransmit_seq:
self.input_retransmit_seq = missing
self.input_retransmits = 0
self.input_retransmit_interval = self._retransmit_base_interval_locked()
# The deadline for a sequence number we have not repeated yet belongs to the frame,
# not to the tick that noticed it. Without this, the cursor advancing clears the
# deadline and the very next frame - which may still be on the air - is repeated on
# the following poll, which is how one keystroke turned into several copies.
sent_at = self._sent_time_locked(missing)
if sent_at is not None and now < sent_at + self.input_retransmit_interval:
self.next_input_retransmit_time = sent_at + self.input_retransmit_interval
return (None, False)
if self.input_retransmits >= MAX_INPUT_RETRANSMITS:
return (missing, True)
self.input_retransmits += 1
self.bump("input_retransmits_total")
if self.input_retransmits > MISSING_SEQ_RETRY_FLAT_ATTEMPTS:
self.input_retransmit_interval = min(self.input_retransmit_interval * 2, MISSING_SEQ_RETRY_MAX_SEC)
self.next_input_retransmit_time = now + self.input_retransmit_interval
return (missing, False)
def note_peer_reported_tx_seq(self, seq: int) -> None:
with self.tx_lock:
if seq > self.highest_seen_rx_seq:
self.highest_seen_rx_seq = seq
def note_received_seq(self, seq: int) -> tuple[str, Optional[int]]:
with self.tx_lock:
expected = self.next_expected_rx_seq
outcome = self._note_received_seq_locked(seq)
if seq != 0:
# Sequenced frames only. A control frame carries seq 0 and is counted by op instead, so
# rx_frames_total stays comparable with the peer's highest sent sequence number.
self.bump("rx_frames_total")
# What the frame is, judged against the cursor before this frame moved it.
if seq < expected:
self.bump("rx_frames_duplicate")
elif seq > expected:
self.bump("rx_frames_ahead_of_cursor")
else:
self.bump("rx_frames_new_in_order")
# And what we did about it, which is not the same thing: a duplicate arriving while a gap
# is open is classified as a gap, because that is the action it triggers.
self.bump(f"rx_action_{outcome[0]}")
return outcome
def _note_received_seq_locked(self, seq: int) -> tuple[str, Optional[int]]:
with self.tx_lock:
if seq == 0:
return ("process", None)
if seq < self.next_expected_rx_seq:
if self.highest_seen_rx_seq >= self.next_expected_rx_seq:
return ("gap", self.next_expected_rx_seq)
return ("duplicate", None)
if seq > self.next_expected_rx_seq:
if seq > self.highest_seen_rx_seq:
self.highest_seen_rx_seq = seq
return ("gap", self.next_expected_rx_seq)
self.last_rx_seq = seq
self.next_expected_rx_seq = seq + 1
if self.last_requested_missing_seq != 0 and self.next_expected_rx_seq > self.last_requested_missing_seq:
self.last_requested_missing_seq = 0
self.missing_request_interval = self._retransmit_base_interval_locked()
self.missing_request_attempts = 0
if seq > self.highest_seen_rx_seq:
self.highest_seen_rx_seq = seq
if self.highest_seen_rx_seq < self.next_expected_rx_seq:
self.highest_seen_rx_seq = 0
# Only an in-order frame moves the cursor the server is waiting on, so only this case
# creates a flow-control debt.
self.frames_since_outbound += 1
return ("process", None)
def remember_out_of_order_frame(self, shell) -> None:
held = False
dropped = False
with self.tx_lock:
if shell.seq <= self.next_expected_rx_seq:
return
if shell.seq in self.pending_rx_frames:
held = False # already waiting on this one
elif len(self.pending_rx_frames) < REORDER_SLOTS:
self.pending_rx_frames[shell.seq] = shell
held = True
else:
# Same rule as the firmware's DMShellRxReorder: the lowest sequence numbers are the
# ones needed soonest, so the highest held is the one worth losing, and only to
# something lower than it. Without a bound, a peer that never fills the gap grows this
# dictionary for as long as the session lasts.
highest = max(self.pending_rx_frames)
if shell.seq < highest:
del self.pending_rx_frames[highest]
self.pending_rx_frames[shell.seq] = shell
held = True
dropped = True
if shell.seq > self.highest_seen_rx_seq:
self.highest_seen_rx_seq = shell.seq
if held:
self.bump("rx_frames_held_for_gap")
if dropped:
self.bump("rx_frames_dropped_reorder_full")
def pop_next_buffered_frame(self):
with self.tx_lock:
return self.pending_rx_frames.pop(self.next_expected_rx_seq, None)
def pending_missing_seq(self) -> Optional[int]:
with self.tx_lock:
if self.highest_seen_rx_seq >= self.next_expected_rx_seq:
return self.next_expected_rx_seq
return None
def request_missing_seq_once(self) -> Optional[int]:
with self.tx_lock:
if self.highest_seen_rx_seq < self.next_expected_rx_seq:
return None
now = time.monotonic()
same_seq = self.last_requested_missing_seq == self.next_expected_rx_seq
if same_seq and (now - self.last_missing_request_time) < self.missing_request_interval:
return None
if same_seq and not self.legacy_recovery:
self.missing_request_attempts += 1
if self.missing_request_attempts > MISSING_SEQ_RETRY_FLAT_ATTEMPTS:
self.missing_request_interval = min(self.missing_request_interval * 2, MISSING_SEQ_RETRY_MAX_SEC)
else:
self.missing_request_attempts = 1
self.missing_request_interval = self._retransmit_base_interval_locked()
self.last_requested_missing_seq = self.next_expected_rx_seq
self.last_missing_request_time = now
return self.last_requested_missing_seq
def flow_control_ack_due(self) -> bool:
"""Whether the server is likely waiting on our receive cursor to reopen its send window."""
with self.tx_lock:
return self.frames_since_outbound >= ACK_AFTER_FRAMES
def set_receive_cursor(self, seq: int) -> None:
with self.tx_lock:
self.last_rx_seq = seq
self.next_expected_rx_seq = seq + 1
self.highest_seen_rx_seq = seq
def open_replay_log(self, session_id: int) -> None:
with self.replay_log_lock:
if self.replay_log_file is not None:
return
path = Path.cwd() / f"{session_id:08x}.log"
self.replay_log_file = path.open("a", encoding="utf-8")
self.replay_log_path = path
self.replay_log_file.write(f"{time.strftime('%Y-%m-%d %H:%M:%S')} session_open session=0x{session_id:08x}\n")
self.replay_log_file.flush()
def log_replay_event(self, event: str, seq: int, detail: str = "") -> None:
self.bump(f"replay_{event}")
with self.replay_log_lock:
if self.replay_log_file is None:
return
extra = f" {detail}" if detail else ""
self.replay_log_file.write(
f"{time.strftime('%Y-%m-%d %H:%M:%S')} {event} seq={seq}{extra}\n"
)
self.replay_log_file.flush()
def open_peer_log(self, path: Path) -> None:
handle = path.open("a", encoding="utf-8", errors="replace")
with self.peer_log_lock:
self.peer_log_file = handle
self.peer_log_path = path
def close_peer_log(self) -> None:
with self.peer_log_lock:
handle, self.peer_log_file = self.peer_log_file, None
if handle is not None:
handle.close()
def log_peer_record(self, record) -> None:
"""Write one of the node's own log lines.
Called from the reader loop, so it must never raise: losing the session because a log file
filled up would be worse than losing the log.
"""
with self.peer_log_lock:
if self.peer_log_file is None:
return
self.peer_log_records += 1
try:
self.peer_log_file.write(format_peer_log_record(record))
self.peer_log_file.flush()
except OSError:
pass
def bump(self, name: str, n: int = 1) -> None:
with self.stats_lock:
self.stats[name] += n
def op_names(self) -> dict[int, str]:
"""Op number -> name, read off the compiled protobuf rather than hard-coded."""
names = {}
for name in ("OPEN", "OPEN_OK", "INPUT", "OUTPUT", "RESIZE", "ACK", "PING", "PONG", "CLOSE", "CLOSED", "ERROR"):
value = getattr(self.pb2.mesh.RemoteShell, name, None)
if isinstance(value, int):
names[value] = name
return names
def stats_summary(self) -> dict:
"""A session's traffic, as counts and the two ratios worth comparing between runs.
Everything here is cumulative over the session. The loss figures are one-directional: we can
only count what arrived, so inbound loss is inferred from the gap between the peer's highest
sequence number and what we delivered in order, and outbound loss is not observable from this
end at all - our retransmission count is the proxy.
"""
with self.stats_lock:
c = dict(self.stats)
elapsed = max(time.monotonic() - self.stats_started_at, 1e-6)
with self.tx_lock:
peer_highest = max(self.highest_seen_rx_seq, self.last_rx_seq)
our_originated = max(self.next_seq - 1, 0)
rx_total = c.get("rx_frames_total", 0)
rx_ok = c.get("rx_frames_new_in_order", 0)
rx_dup = c.get("rx_frames_duplicate", 0)
tx_total = c.get("tx_frames_total", 0)
resends = c.get("frames_resent", 0)
out = {
"elapsed_sec": round(elapsed, 1),
"peer_highest_seq": peer_highest,
"inbound": {
"frames_arrived": rx_total,
"delivered_in_order": rx_ok,
# Frames the peer put on the wire twice, i.e. its resends reaching us. Judged on the
# sequence number alone, so a duplicate arriving during a gap still counts here even
# though the action it triggered was a replay request.
"duplicates": rx_dup,
"ahead_of_cursor": c.get("rx_frames_ahead_of_cursor", 0),
"triggered_replay_request": c.get("rx_action_gap", 0),
"held_for_gap": c.get("rx_frames_held_for_gap", 0),
# Frames the peer numbered that we never delivered. Negative is impossible; zero
# with a non-zero peer_highest_seq is a clean run.
"never_delivered": max(peer_highest - rx_ok, 0),
"loss_rate": round(1 - (rx_ok / peer_highest), 4) if peer_highest else None,
"duplicate_rate": round(rx_dup / rx_total, 4) if rx_total else None,
"output_bytes": c.get("rx_output_bytes", 0),
"output_bytes_per_sec": round(c.get("rx_output_bytes", 0) / elapsed, 1),
},
"outbound": {
"frames_transmitted": tx_total,
"frames_originated": our_originated,
# Frames we put back on the wire: our replays for the peer and our own input
# retransmissions, both of which route through note_frame_resent. This is the
# resend number; it is not the same thing as total overhead.
"resends": resends,
"resend_ratio": round(resends / our_originated, 4) if our_originated else None,
# Every frame handed to the radio over the frames we originated. Read this as total
# airtime overhead, NOT as a resend ratio: in a session where the server is streaming
# output, our ACKs dominate it and it says nothing about loss.
"transmissions_per_originated_frame": round(tx_total / our_originated, 3) if our_originated else None,
"input_retransmits": c.get("input_retransmits_total", 0),
"payload_bytes": c.get("tx_payload_bytes", 0),
"by_op": {},
},
# Frames the host could not parse and resynchronised past. Not a radio loss: the node
# sent them, the USB stream tore them. A run with a non-zero count here has lost frames
# to the transport, so its miss of OUTPUTs reads high by that much.
"torn_frames": self.torn_frames,
"stream_resync": dict(STREAM_RESYNC),
"recovery": {
"replay_requests_sent": c.get("replay_requests_sent", 0),
"replays_received": c.get("replay_replay_received", 0),
"replays_sent_to_peer": c.get("replay_replay_sent", 0),
"replay_unavailable": c.get("replay_replay_unavailable", 0),
"replay_evicted": c.get("replay_replay_evicted", 0),
"distinct_gaps": c.get("distinct_gaps", 0),
"open_retries": c.get("open_retries", 0),
"open_ok_dropped": c.get("open_ok_dropped", 0),
"request_reasons": {
k[len("replay_requests_sent_"):]: v
for k, v in sorted(c.items())
if k.startswith("replay_requests_sent_")
},
},
}
names = self.op_names()
for key, value in sorted(c.items()):
if key.startswith("tx_frames_op_"):
op = int(key[len("tx_frames_op_"):])
out["outbound"]["by_op"][names.get(op, f"op{op}")] = value
return out
def note_missing_seq_requested(self, seq: int, reason: str) -> None:
with self.tx_lock:
first_time = seq not in self.requested_missing_seqs
self.requested_missing_seqs.add(seq)
self.bump("replay_requests_sent")
self.bump(f"replay_requests_sent_{reason}")
if first_time:
# Distinct gaps, not requests. A gap asked about five times is one gap, and the ratio
# between the two is the damping working.
self.bump("distinct_gaps")
self.log_replay_event("missing_requested", seq, f"reason={reason}")
def note_replayed_seq_received(self, seq: int) -> None:
with self.tx_lock:
was_requested = seq in self.requested_missing_seqs
if was_requested:
self.requested_missing_seqs.remove(seq)
if was_requested:
self.log_replay_event("replay_received", seq)
def close_replay_log(self) -> None:
with self.replay_log_lock:
if self.replay_log_file is None:
return
self.replay_log_file.write(f"{time.strftime('%Y-%m-%d %H:%M:%S')} session_close\n")
self.replay_log_file.flush()
self.replay_log_file.close()
self.replay_log_file = None
def remember_sent_frame(self, frame: SentShellFrame) -> None:
if frame.seq == 0 or frame.op == self.pb2.mesh.RemoteShell.ACK:
return
with self.tx_lock:
self.tx_history.append(frame)
def prune_sent_frames(self, ack_seq: int) -> None:
if ack_seq <= 0:
return
with self.tx_lock:
self.tx_history = deque((frame for frame in self.tx_history if frame.seq > ack_seq), maxlen=50)
def replay_frames_from(self, start_seq: int) -> list[SentShellFrame]:
with self.tx_lock:
return [frame for frame in self.tx_history if frame.seq >= start_seq]
def oldest_retained_tx_seq(self) -> Optional[int]:
"""Lowest sequence number the replay ring still holds, or None while it is empty.
tx_history is appended in send order and sequence numbers are allocated monotonically, so
the leftmost entry is the oldest. Note prune_sent_frames() has no live call site, which
makes this a flat last-50-sent ring - the same shape as the firmware's txHistory, and
outrun the same way.
"""
with self.tx_lock:
for frame in self.tx_history:
return frame.seq
return None
def send_toradio(transport, toradio) -> None:
send_stream_frame(transport, toradio.SerializeToString())
def make_toradio_packet(pb2, state: SessionState, shell_msg) -> object:
packet = pb2.mesh.MeshPacket()
packet.id = random.randint(1, 0x7FFFFFFF)
packet.to = state.target
# The 'from' field is a reserved keyword in Python, so use setattr
setattr(packet, "from", 0)
packet.channel = state.channel
packet.hop_limit = state.hop_limit
packet.want_ack = False
packet.decoded.portnum = pb2.portnums.REMOTE_SHELL_APP
packet.decoded.payload = shell_msg.SerializeToString()
packet.decoded.want_response = False
packet.decoded.dest = state.target
packet.decoded.source = 0
# Mark has_bitfield (proto3 optional -> assigning even 0 sets presence) and leave OK_TO_MQTT clear,
# which is right for a private shell. Note: this is NOT what prevents the far-end pre-hop drop --
# that check runs before decryption and can't read the (encrypted) bitfield; a non-zero hop_limit
# is what keeps us alive there. The firmware also sets this for locally-originated packets, so this
# is mostly belt-and-suspenders for the post-decryption consumers (e.g. getHopsAway).
packet.decoded.bitfield = 0
toradio = pb2.mesh.ToRadio()
toradio.packet.CopyFrom(packet)
return toradio
def send_shell_frame(
transport,
state: SessionState,
op: int,
payload: bytes = b"",
cols: int = 0,
rows: int = 0,
session_id: Optional[int] = None,
ack_seq: Optional[int] = None,
seq: Optional[int] = None,
flags: int = 0,
last_tx_seq: int = 0,
last_rx_seq: int = 0,
remember: bool = True,
heartbeat: bool = False,
) -> int:
# Held across allocation and transmission both: the input, heartbeat and reader threads all send,
# and a sequence number that reaches the radio out of order reads as a gap at the far end.
with state.socket_lock:
sent = _send_shell_frame_locked(
transport, state, op, payload, cols, rows, session_id, ack_seq, seq, flags, last_tx_seq, last_rx_seq,
remember, heartbeat,
)
# Outside the socket lock: this is the only path every outbound frame takes, so counting here
# makes tx_frames_total the number of transmissions the radio was asked for, retransmissions and
# replays included. That is the denominator the resend ratio needs.
state.bump("tx_frames_total")
state.bump(f"tx_frames_op_{op}")
if payload:
state.bump("tx_payload_bytes", len(payload))
return sent
def _send_shell_frame_locked(
transport,
state: SessionState,
op: int,
payload: bytes,
cols: int,
rows: int,
session_id: Optional[int],
ack_seq: Optional[int],
seq: Optional[int],
flags: int,
last_tx_seq: int,
last_rx_seq: int,
remember: bool,
heartbeat: bool,
) -> int:
if seq is None:
seq = 0 if op == state.pb2.mesh.RemoteShell.ACK else state.alloc_seq()
if ack_seq is None:
ack_seq = state.current_ack_seq()
if session_id is None:
session_id = state.session_id
shell = state.pb2.mesh.RemoteShell()
shell.op = op
shell.session_id = session_id
shell.seq = seq
shell.ack_seq = ack_seq
shell.cols = cols
shell.rows = rows
shell.flags = flags
shell.last_tx_seq = last_tx_seq
shell.last_rx_seq = last_rx_seq
if payload:
shell.payload = payload
send_toradio(transport, make_toradio_packet(state.pb2, state, shell))
if remember:
state.remember_sent_frame(
SentShellFrame(
op=op,
session_id=session_id,
seq=seq,
ack_seq=ack_seq,
payload=payload,
cols=cols,
rows=rows,
flags=flags,
last_tx_seq=last_tx_seq,
last_rx_seq=last_rx_seq,
sent_time=time.monotonic(),
)
)
state.note_outbound_packet(heartbeat=heartbeat)
return seq
def send_ack_frame(transport, state: SessionState, replay_from: Optional[int] = None) -> None:
send_shell_frame(
transport,
state,
state.pb2.mesh.RemoteShell.ACK,
seq=0,
last_rx_seq=0 if replay_from is None else replay_from - 1,
remember=False,
)
def replay_frames_from(transport, state: SessionState, start_seq: int) -> None:
frame = next((f for f in state.replay_frames_from(start_seq) if f.seq == start_seq), None)
if frame is None:
oldest = state.oldest_retained_tx_seq()
if not state.legacy_recovery and oldest is not None and 0 < start_seq < oldest:
# The mirror of the firmware's eviction path. The peer is asking for a frame our own
# ring has already dropped, so it can never be answered, and the peer will not advance
# past the hole: it would keep asking until the idle timeout. End the session instead,
# and say why, so the run's log distinguishes this from a lossy link.
state.log_replay_event("replay_evicted", start_seq, f"oldest_retained={oldest}")
state.event_queue.put(
f"peer asked to replay seq={start_seq}, which has aged out of our {state.tx_history.maxlen}-frame history; closing session"
)
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE, remember=False)
state.active = False
state.closed_event.set()
return
#state.event_queue.put(f"replay unavailable from seq={start_seq}")
state.log_replay_event("replay_unavailable", start_seq)
return
state.log_replay_event("replay_sent", start_seq)
#state.event_queue.put(f"replay frame seq={start_seq}")
send_shell_frame(
transport,
state,
frame.op,
payload=frame.payload,
cols=frame.cols,
rows=frame.rows,
session_id=frame.session_id,
ack_seq=frame.ack_seq,
seq=frame.seq,
flags=frame.flags,
last_tx_seq=frame.last_tx_seq,
last_rx_seq=frame.last_rx_seq,
remember=False,
)
state.note_frame_resent(frame.seq)
# The node reports the level as an enum value. TRACE is 5 in the protobuf, but firmware older than the
# 'T' case in RedirectablePrint::getLogLevel() reports every LOG_TRACE as UNSET, so a capture full of
# UNSET lines is an old node rather than a broken one.
PEER_LOG_LEVEL_NAMES = {0: "UNSET", 5: "TRACE", 10: "DEBUG", 20: "INFO", 30: "WARN", 40: "ERROR", 50: "CRIT"}
def format_peer_log_record(record) -> str:
"""One line per record: local clock, the node's own clock, level, thread, message.
The local timestamp is what correlates this against the client transcript and the far node's log;
the record's own time is kept beside it because it can be zero or wrong before the RTC is set.
"""
level = PEER_LOG_LEVEL_NAMES.get(record.level, str(record.level))
source = record.source or "-"
message = record.message.rstrip("\n")
# Milliseconds, because correlating a radio event against the other nodes' logs needs better than
# the whole second strftime gives: a preamble is 10 ms and a busy scan's deaf window is about 13.
# This is the arrival time on this host, so it carries the node's API and serial latency with it;
# LogRecord.time is only seconds, so the node cannot tell us better than this today.
now = time.time()
stamp = f"{time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(now))}.{int((now % 1) * 1000):03d}"
return f"{stamp} node_time={record.time} {level:5} {source} {message}\n"
def log_ack_latency(state: SessionState) -> None:
"""Report the round-trip estimate the retransmission interval is derived from.
Called from the poll rather than from a retransmission, so a run that never retransmits still
records what this side measured. The first sample also goes to the transcript, because it is what
tells the operator whether the interval matches the preset in use.
"""
with state.tx_lock:
latest = state.ack_latency
if latest is None:
return
previous = state.ack_latency_reported
if previous is not None and abs(latest - previous) < ACK_LATENCY_REPORT_CHANGE * previous:
return
state.ack_latency_reported = latest
interval = state._retransmit_base_interval_locked()
first = previous is None
state.log_replay_event("ack_latency", 0, f"estimate={latest:.2f}s interval={interval:g}s")
if first:
state.event_queue.put(f"round trip measured at {latest:.2f}s; retransmission interval {interval:g}s")
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:
_flush_pending_input_locked(transport, state)
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():
return
chunk = state.take_queued_input(INPUT_BATCH_MAX_BYTES)
if not chunk:
return
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.INPUT, chunk)
def send_input(transport, state: SessionState, data: bytes) -> None:
"""Queue typed input and send what the window allows.
Everything goes through the queue even when the window is open, so bytes can only ever leave in
the order they were typed.
"""
dropped = state.queue_input(data)
if dropped:
state.event_queue.put(f"input buffer full, dropped {dropped} byte(s); the remote is not keeping up")
flush_pending_input(transport, state)
def service_input_window(transport, state: SessionState) -> None:
"""Keep a blocked input stream moving. Called from the heartbeat thread, which already polls."""
flush_pending_input(transport, state)
if not state.active or state.closed_event.is_set():
return
log_input_window_transition(state)
log_ack_latency(state)
if state.input_window_open():
return
missing, exhausted = state.input_retransmit_due()
if missing is None:
return
if exhausted:
state.log_replay_event("peer_unresponsive", missing, f"retransmits={MAX_INPUT_RETRANSMITS}")
state.event_queue.put(
f"remote has not acknowledged input seq={missing} after {MAX_INPUT_RETRANSMITS} retransmissions; closing session"
)
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE, remember=False)
state.active = False
state.closed_event.set()
return
# 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.
latency = "unmeasured" if state.ack_latency is None else f"{state.ack_latency:.2f}s"
state.log_replay_event("input_retransmit", missing,
f"attempt={state.input_retransmits} of {MAX_INPUT_RETRANSMITS} "
f"interval={state.input_retransmit_interval:g}s latency={latency}")
replay_frames_from(transport, state, missing)
def wait_for_config_complete(transport, pb2, timeout: float, verbose: bool) -> None:
nonce = random.randint(1, 0x7FFFFFFF)
toradio = pb2.mesh.ToRadio()
toradio.want_config_id = nonce
send_toradio(transport, toradio)
# Both transports are opened blocking, so the deadline has to be pushed down into each read:
# a peer that never answers - the wrong --port, a non-Meshtastic service, a serial device that
# ignores want_config_id - otherwise hangs here for good and --timeout means nothing.
deadline = time.monotonic() + timeout
try:
while True:
remaining = deadline - time.monotonic()
if remaining <= 0:
break
transport.settimeout(remaining)
try:
raw = recv_stream_frame(transport, deadline)
except (socket.timeout, TimeoutError):
continue
except ConnectionError:
# pyserial reports a read timeout as a short read, which recv_exact turns into
# this; a genuine disconnect before the deadline is still worth raising.
if time.monotonic() < deadline:
raise
break
fromradio = pb2.mesh.FromRadio()
fromradio.ParseFromString(raw)
variant = fromradio.WhichOneof("payload_variant")
if verbose and variant:
print(f"[api] fromradio {variant}", file=sys.stderr)
if variant == "config_complete_id" and fromradio.config_complete_id == nonce:
return
finally:
transport.settimeout(None)
raise TimeoutError("timed out waiting for config handshake to complete")
def decode_shell_packet(state: SessionState, packet) -> Optional[object]:
if packet.WhichOneof("payload_variant") != "decoded":
return None
if packet.decoded.portnum != state.pb2.portnums.REMOTE_SHELL_APP:
return None
# Only the node we selected can speak for this session. The session id alone is not an identity:
# it is carried in the frame, so any sender whose decoded packets reach this stream could match
# it and then write to our terminal, move our cursors or close the session. 'from' is a Python
# keyword, hence the getattr.
sender = getattr(packet, "from", 0)
if sender != state.target:
state.bump("rx_frames_other_sender")
return None
shell = state.pb2.mesh.RemoteShell()
shell.ParseFromString(packet.decoded.payload)
return shell
def reader_loop(transport, state: SessionState) -> None:
def handle_in_order_shell(shell) -> bool:
state.note_replayed_seq_received(shell.seq)
if shell.op == state.pb2.mesh.RemoteShell.OPEN_OK:
state.session_id = shell.session_id
state.open_replay_log(state.session_id)
state.set_receive_cursor(shell.seq)
state.active = True
state.opened_event.set()
state.event_queue.put(
f"opened session=0x{shell.session_id:08x} cols={shell.cols} rows={shell.rows}"
)
if state.replay_log_path is not None:
state.event_queue.put(f"replay log: {state.replay_log_path}")
elif shell.op == state.pb2.mesh.RemoteShell.OUTPUT:
if shell.payload:
state.bump("rx_output_bytes", len(shell.payload))
sys.stdout.buffer.write(shell.payload)
sys.stdout.buffer.flush()
elif shell.op == state.pb2.mesh.RemoteShell.ERROR:
message = shell.payload.decode("utf-8", errors="replace")
if state.replay_log_file is None:
state.open_replay_log(shell.session_id or state.session_id)
sanitized = message.replace("\n", "\\n")
state.log_replay_event("error_received", shell.seq, f"message={sanitized}")
state.event_queue.put(f"remote error: {message}")
elif shell.op == state.pb2.mesh.RemoteShell.PONG:
remote_last_tx_seq = shell.last_tx_seq
remote_last_rx_seq = shell.last_rx_seq
local_latest_tx_seq = state.highest_sent_seq()
if remote_last_rx_seq != 0 and remote_last_rx_seq < local_latest_tx_seq:
replay_frames_from(transport, state, remote_last_rx_seq + 1)
if remote_last_tx_seq > state.current_ack_seq():
state.note_peer_reported_tx_seq(remote_last_tx_seq)
req = state.request_missing_seq_once()
if req is not None:
state.note_missing_seq_requested(req, "heartbeat_status")
send_ack_frame(transport, state, replay_from=req)
#state.event_queue.put("pong")
return False
while not state.stopped:
try:
frame = recv_stream_frame(transport)
except Exception as exc:
if not state.stopped:
state.event_queue.put(f"connection error: {exc}")
state.closed_event.set()
return
try:
fromradio = state.pb2.mesh.FromRadio()
fromradio.ParseFromString(frame)
except Exception as exc:
# A torn frame is not a dead link. Log records and packets share one stream, so under
# load a dropped chunk truncates one mid-frame; recv_stream_frame resynchronises on the
# next START1 by itself. Ending the session here threw away a 300 s diagnostic run after
# a single bad frame with the node healthy throughout. Only the transport raising
# (ConnectionError from recv_exact) means the link is really gone.
state.torn_frames += 1
if state.torn_frames in (1, 10) or state.torn_frames % 100 == 0:
state.event_queue.put(f"skipped a torn frame ({state.torn_frames} so far): {exc}")
continue
variant = fromradio.WhichOneof("payload_variant")
if variant == "log_record":
# The node's own log, on the same stream as its packets. Nothing else in this client cares
# about it, and it is dropped unless --peer-log asked for it.
state.log_peer_record(fromradio.log_record)
continue
if variant == "packet":
shell = decode_shell_packet(state, fromradio.packet)
if not shell:
continue
if shell.session_id != state.session_id:
# Another session's frame, typically the server's reply to a frame from an earlier run still on
# air when this one started. Its seq and cursor belong to that session: taking its seq 1 in order
# made us drop our own OPEN_OK, also seq 1, as a duplicate. Surface an ERROR; touch no counter.
state.bump("rx_frames_other_session")
if shell.op == state.pb2.mesh.RemoteShell.ERROR:
message = shell.payload.decode("utf-8", errors="replace")
state.event_queue.put(f"remote error for another session=0x{shell.session_id:08x}: {message}")
continue
if state.drop_open_ok > 0 and shell.op == state.pb2.mesh.RemoteShell.OPEN_OK:
# Fault injection for --drop-open-ok: gone before any accounting, as a frame lost on air is.
state.drop_open_ok -= 1
state.bump("open_ok_dropped")
state.event_queue.put(f"dropped OPEN_OK session=0x{shell.session_id:08x} (--drop-open-ok)")
continue
state.note_inbound_packet()
# Before every opcode branch, including the ones that continue: an out-of-order frame is
# still proof the peer is alive and still carries a valid cursor, and during a gap it may
# be the only kind arriving. Mirrors where the firmware calls notePeerReceiveCursor().
state.note_peer_receive_cursor(shell.ack_seq, shell.last_rx_seq)
#state.prune_sent_frames(shell.ack_seq)
if shell.op == state.pb2.mesh.RemoteShell.CLOSED:
# Terminal, so act on it regardless of sequence order. Buffering a CLOSED behind a
# gap the peer has just told us it cannot fill left us retrying until the idle
# timeout. ERROR deliberately stays on the ordered path below: it is not always
# terminal, and skipping its sequence number would open a gap of its own.
message = shell.payload.decode("utf-8", errors="replace")
state.event_queue.put(f"session closed: {message}")
state.closed_event.set()
state.active = False
return
if shell.op == state.pb2.mesh.RemoteShell.ACK:
#state.event_queue.put("peer requested replay")
replay_from = shell.last_rx_seq + 1 if shell.last_rx_seq > 0 else None
if replay_from is not None:
#state.event_queue.put(f"peer requested replay from seq={replay_from}")
replay_frames_from(transport, state, replay_from)
continue
action, missing_from = state.note_received_seq(shell.seq)
if action == "duplicate":
req = state.request_missing_seq_once()
if req is not None:
state.note_missing_seq_requested(req, "duplicate")
send_ack_frame(transport, state, replay_from=req)
else:
# We already have this in order, so the peer has not seen our cursor - which is
# what a sender whose window is shut looks like. Answer with the cursor rather
# than nothing, or it retransmits until its own bound closes the session. The
# firmware answers our duplicates the same way.
send_ack_frame(transport, state)
continue
if action == "gap":
state.remember_out_of_order_frame(shell)
req = state.request_missing_seq_once()
if req is not None:
state.note_missing_seq_requested(req, "gap")
send_ack_frame(transport, state, replay_from=req)
continue
if handle_in_order_shell(shell):
return
while True:
buffered_shell = state.pop_next_buffered_frame()
if buffered_shell is None:
break
buffered_action, _ = state.note_received_seq(buffered_shell.seq)
if buffered_action != "process":
state.remember_out_of_order_frame(buffered_shell)
break
if handle_in_order_shell(buffered_shell):
return
req = state.request_missing_seq_once()
if req is not None:
state.note_missing_seq_requested(req, "post_process_gap")
send_ack_frame(transport, state, replay_from=req)
elif state.flow_control_ack_due():
# Bare ack: replay_from is None so last_rx_seq stays 0 and the peer does not read it
# as a replay request, but ack_seq still carries the cursor that reopens its window.
send_ack_frame(transport, state)
elif state.verbose and variant:
state.event_queue.put(f"fromradio {variant}")
def wait_for_open_ok(transport, state: SessionState, cols: int, rows: int, timeout_sec: float) -> None:
"""Send OPEN and wait for OPEN_OK, repeating the OPEN until one arrives or the timeout runs out.
Every repeat carries the same session id and sequence number as the first, which is what lets the
firmware recognise it as the same session rather than a new one that preempts it. Legacy mode sends
once, as before, so the same binary still gives an A/B baseline.
"""
pb2 = state.pb2
open_seq = send_shell_frame(transport, state, pb2.mesh.RemoteShell.OPEN, cols=cols, rows=rows)
deadline = time.monotonic() + timeout_sec
interval = OPEN_RETRY_FIRST_SEC
while True:
remaining = deadline - time.monotonic()
if remaining <= 0:
break
wait = remaining if state.legacy_recovery else min(interval, remaining)
if state.opened_event.wait(timeout=wait):
return
if state.legacy_recovery or time.monotonic() >= deadline:
break
send_shell_frame(
transport, state, pb2.mesh.RemoteShell.OPEN, cols=cols, rows=rows, seq=open_seq, remember=False
)
state.bump("open_retries")
state.event_queue.put(f"no OPEN_OK after {interval:.0f} s, repeating OPEN")
drain_events(state)
interval = min(interval * 2, OPEN_RETRY_MAX_SEC)
# The server may have accepted the session and be streaming into it. Tell it we are gone rather than
# leave it transmitting to nobody until its own bounds notice. CLOSE is acted on out of order, so it
# needs no OPEN_OK to have arrived; if the server never opened anything it is rejected harmlessly.
try:
send_shell_frame(transport, state, pb2.mesh.RemoteShell.CLOSE, remember=False)
except Exception:
pass
raise SystemExit("timed out waiting for OPEN_OK from remote DMShell")
def drain_events(state: SessionState) -> None:
while True:
try:
event = state.event_queue.get_nowait()
except queue.Empty:
return
print(f"[dmshell] {event}", file=sys.stderr)
def heartbeat_loop(transport, state: SessionState) -> None:
while not state.stopped and not state.closed_event.is_set():
if not state.active:
time.sleep(HEARTBEAT_POLL_INTERVAL_SEC)
continue
try:
service_input_window(transport, state)
except Exception as exc:
if not state.stopped:
state.event_queue.put(f"input window error: {exc}")
state.closed_event.set()
return
if state.heartbeat_due():
try:
send_shell_frame(
transport,
state,
state.pb2.mesh.RemoteShell.PING,
last_tx_seq=state.highest_sent_seq(),
last_rx_seq=state.current_ack_seq(),
remember=True,
heartbeat=True,
)
except Exception as exc:
if not state.stopped:
state.event_queue.put(f"heartbeat error: {exc}")
state.closed_event.set()
return
time.sleep(HEARTBEAT_POLL_INTERVAL_SEC)
def run_command_mode(transport, state: SessionState, commands: list[str], close_after: float) -> None:
for command in commands:
send_input(transport, state, (command + "\n").encode("utf-8"))
# The window may still be holding part of a command, so give it the same grace the output gets
# before tearing the session down.
deadline = time.monotonic() + close_after
while state.has_queued_input() and not state.closed_event.is_set() and time.monotonic() < deadline:
time.sleep(HEARTBEAT_POLL_INTERVAL_SEC)
remaining = deadline - time.monotonic()
if remaining > 0:
time.sleep(remaining)
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE)
state.closed_event.wait(timeout=close_after + 5.0)
def run_interactive_mode(transport, state: SessionState) -> None:
def read_local_command() -> str:
prompt = "\r\n[dmshell] local command (resume|close|ping|resize C R): "
sys.stderr.write(prompt)
sys.stderr.flush()
buf = bytearray()
while True:
ch = os.read(sys.stdin.fileno(), 1)
if not ch:
sys.stderr.write("\r\n")
sys.stderr.flush()
return "close"
b = ch[0]
if b in (10, 13):
sys.stderr.write("\r\n")
sys.stderr.flush()
return buf.decode("utf-8", errors="replace").strip()
if b in (8, 127):
if buf:
buf.pop()
sys.stderr.write("\b \b")
sys.stderr.flush()
continue
if b < 32:
continue
buf.append(b)
sys.stderr.write(chr(b))
sys.stderr.flush()
def handle_local_command(cmd: str) -> bool:
if cmd in ("", "resume"):
return True
if cmd == "close":
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE)
return False
if cmd == "ping":
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.PING)
return True
if cmd.startswith("resize "):
parts = cmd.split()
if len(parts) != 3:
state.event_queue.put("usage: resize COLS ROWS")
return True
try:
cols = int(parts[1])
rows = int(parts[2])
except ValueError:
state.event_queue.put("usage: resize COLS ROWS")
return True
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.RESIZE, cols=cols, rows=rows)
return True
state.event_queue.put(f"unknown local command: {cmd}")
return True
print(
"Raw input mode active. All keys (including Ctrl+C/Ctrl+X) are sent to remote. Ctrl+] for local commands.",
file=sys.stderr,
)
if not sys.stdin.isatty():
# Fallback for non-TTY stdin: still send input as it arrives.
while not state.closed_event.is_set():
drain_events(state)
data = sys.stdin.buffer.read(INPUT_BATCH_MAX_BYTES)
if not data:
# The input window holds at most INPUT_WINDOW_FRAMES frames in flight, so piped
# input longer than that is still queued here. The server handles CLOSE out of
# order, ahead of any gap, so sending it now truncates the script silently.
while (state.has_queued_input() or state.outstanding_input() > 0) and not state.closed_event.is_set():
drain_events(state)
time.sleep(HEARTBEAT_POLL_INTERVAL_SEC)
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE)
break
send_input(transport, state, data)
return
fd = sys.stdin.fileno()
old_attrs = termios.tcgetattr(fd)
try:
tty.setraw(fd)
while not state.closed_event.is_set():
drain_events(state)
ready, _, _ = select.select([sys.stdin], [], [], 0.05)
if not ready:
flush_pending_input(transport, state)
continue
data = os.read(fd, 1)
if not data:
send_shell_frame(transport, state, state.pb2.mesh.RemoteShell.CLOSE)
break
if data == LOCAL_ESCAPE_BYTE:
keep_running = handle_local_command(read_local_command())
if not keep_running:
break
continue
# Coalesce a short burst of bytes to reduce packet overhead for fast typing.
batched = bytearray(data)
enter_local_command = False
deadline = time.monotonic() + INPUT_BATCH_WINDOW_SEC
hold_until = time.monotonic() + INPUT_BATCH_MAX_HOLD_SEC
while len(batched) < INPUT_BATCH_MAX_BYTES:
remaining = min(deadline, hold_until) - time.monotonic()
if remaining <= 0:
break
more_ready, _, _ = select.select([sys.stdin], [], [], remaining)
if not more_ready:
break
next_byte = os.read(fd, 1)
if not next_byte:
break
if next_byte == LOCAL_ESCAPE_BYTE:
enter_local_command = True
break
batched.extend(next_byte)
if next_byte == b'\r' or next_byte == b'\t':
break
deadline = time.monotonic() + INPUT_BATCH_WINDOW_SEC
if batched:
send_input(transport, state, bytes(batched))
if enter_local_command:
keep_running = handle_local_command(read_local_command())
if not keep_running:
break
finally:
termios.tcsetattr(fd, termios.TCSADRAIN, old_attrs)
def report_session_stats(state: SessionState, json_path: Optional[Path]) -> None:
"""Print the session's traffic summary, and optionally write it as JSON for an A/B."""
summary = state.stats_summary()
if json_path is not None:
try:
json_path.write_text(json.dumps(summary, indent=2, sort_keys=True) + "\n", encoding="utf-8")
print(f"[dmshell] wrote traffic summary to {json_path}", file=sys.stderr)
except OSError as exc:
# Never let a bad path lose the numbers: they still go to stderr below.
print(f"[dmshell] could not write {json_path}: {exc}", file=sys.stderr)
inbound = summary["inbound"]
outbound = summary["outbound"]
recovery = summary["recovery"]
lines = [
f"session {summary['elapsed_sec']}s, peer reached seq {summary['peer_highest_seq']}",
" in : {arrived} frames arrived, {ok} new in order, {dup} duplicate (the peer's resends), "
"{ahead} ahead of the cursor, {held} held for a gap".format(
arrived=inbound["frames_arrived"], ok=inbound["delivered_in_order"],
dup=inbound["duplicates"], ahead=inbound["ahead_of_cursor"], held=inbound["held_for_gap"],
),
" {never} never delivered, loss {loss}, duplicate {duprate}".format(
never=inbound["never_delivered"],
loss=_as_percent(inbound["loss_rate"]),
duprate=_as_percent(inbound["duplicate_rate"]),
),
" {b} output bytes, {bps}/s".format(b=inbound["output_bytes"], bps=inbound["output_bytes_per_sec"]),
" out: {orig} frames originated, {resent} resent ({rratio} per originated frame), "
"{rt} input retransmits".format(
orig=outbound["frames_originated"], resent=outbound["resends"],
rratio=outbound["resend_ratio"], rt=outbound["input_retransmits"],
),
" {tx} transmissions in total ({ratio} per originated frame), acks included - "
"total airtime overhead, not a resend ratio".format(
tx=outbound["frames_transmitted"], ratio=outbound["transmissions_per_originated_frame"],
),
" by op: " + (", ".join(f"{k}={v}" for k, v in sorted(outbound["by_op"].items())) or "none"),
" rec: {req} replay requests over {gaps} distinct gaps, {got} replays received, "
"{sent} sent to peer, {unavail} unavailable, {evict} evicted".format(
req=recovery["replay_requests_sent"], gaps=recovery["distinct_gaps"],
got=recovery["replays_received"], sent=recovery["replays_sent_to_peer"],
unavail=recovery["replay_unavailable"], evict=recovery["replay_evicted"],
),
]
if recovery["request_reasons"]:
lines.append(" request reasons: " + ", ".join(f"{k}={v}" for k, v in recovery["request_reasons"].items()))
for line in lines:
print(f"[dmshell] {line}", file=sys.stderr)
def _as_percent(value: Optional[float]) -> str:
return "n/a" if value is None else f"{value * 100:.2f}%"
def main() -> int:
args = parse_args()
pb2 = load_proto_modules()
state = SessionState(
pb2=pb2,
target=parse_node_num(args.to),
channel=args.channel,
verbose=args.verbose,
hop_limit=args.hop_limit,
legacy_recovery=args.legacy_recovery,
drop_open_ok=max(0, args.drop_open_ok),
input_window_frames=0 if args.legacy_recovery else INPUT_WINDOW_FRAMES,
)
if state.input_window_frames == 0:
print("[dmshell] input window disabled, typed input may run away from a gap", file=sys.stderr)
else:
print(f"[dmshell] bounding unacknowledged input to {state.input_window_frames} frames", file=sys.stderr)
cols, rows = resolve_initial_terminal_size(args.cols, args.rows)
if args.peer_log is not None:
state.open_peer_log(args.peer_log)
print(f"[dmshell] writing the node's own log to {args.peer_log}", file=sys.stderr)
transport = open_transport(args)
try:
wait_for_config_complete(transport, pb2, args.timeout, args.verbose)
reader = threading.Thread(target=reader_loop, args=(transport, state), daemon=True)
reader.start()
wait_for_open_ok(transport, state, cols, rows, max(args.open_timeout, args.timeout))
heartbeat = threading.Thread(target=heartbeat_loop, args=(transport, state), daemon=True)
heartbeat.start()
drain_events(state)
if args.command:
run_command_mode(transport, state, args.command, args.close_after)
else:
run_interactive_mode(transport, state)
state.stopped = True
drain_events(state)
reader.join(timeout=1.0)
heartbeat.join(timeout=1.0)
state.close_replay_log()
finally:
transport.close()
if args.peer_log is not None:
state.close_peer_log()
print(f"[dmshell] captured {state.peer_log_records} log records from the node", file=sys.stderr)
if args.stats or args.stats_json is not None:
report_session_stats(state, args.stats_json)
return 0
if __name__ == "__main__":
raise SystemExit(main())