From 4a41d2942ef8b4622b42d6ef20d974e6c75d46c7 Mon Sep 17 00:00:00 2001 From: Brad Barnett <127794626+bdbarnett@users.noreply.github.com> Date: Mon, 14 Sep 2026 23:41:08 -0500 Subject: [PATCH 1/2] Add a read-only monitor that actually captures the native console. debug-tee from the CLI closed the private sidecar immediately, so the tee log stayed empty. monitor holds the port without REPL or DTR/RTS, and close() no longer deadlocks once a stdout reader is active. --- CHANGELOG.md | 17 ++++ cli/src/mpftp/cli.py | 235 ++++++++++++++++++++++++++++++++++++++++++- docs/agent-guide.md | 41 +++++++- 3 files changed, 288 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3146414..574d4de 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,20 @@ +## Unreleased + +- Add `monitor`: read-only console capture on a COM, held open for `--seconds` + (or until Ctrl-C), streaming bytes to stdout and appending to `--log-path`. + This is the capture `debug-tee` could not do from the CLI: the one-shot + `debug-tee` returned immediately and its private sidecar (and the tee thread) + died with the command, so the log always stayed empty. `monitor` keeps the + session alive for the whole window, so the sidecar's tee loop actually + writes. It never enters raw REPL and never toggles DTR/RTS, so a board + autostarted from `main.py` keeps running and its `stderr` / ESP-IDF panic + backtrace is captured — the missing piece for debugging native crashes and + C-module `fprintf(stderr, ...)` output that never reaches a Python-side log. +- Fix `SidecarClient.close()` deadlock after a streaming capture: the daemon + stdout reader used by `stream_repl` / `stream_debug_tee` owns the pipe, so a + graceful `disconnect` RPC in `close()` hung forever fighting it. `close()` + now terminates the process directly once a reader is active. + ## v0.0.5 (2026-09-07) - Add board CLI workflow test; pick .bin vs .uf2 and fix put -r, romfs, mpy-cross. diff --git a/cli/src/mpftp/cli.py b/cli/src/mpftp/cli.py index 4fe8cdf..7f70158 100755 --- a/cli/src/mpftp/cli.py +++ b/cli/src/mpftp/cli.py @@ -20,6 +20,7 @@ mpftp soft-reboot # Ctrl-D; runs main.py / code.py mpftp run script.py # default --no-follow (UI-safe) mpftp debug-tee COM50 + mpftp monitor COM4 --seconds 60 --log-path /tmp/con.log # capture console (panic/stderr) mpftp watch # tail activity log """ @@ -235,6 +236,26 @@ def stream_repl( """ raise NotImplementedError + def stream_debug_tee( + self, + device: str, + baud: int, + log_path: Optional[str], + on_notify: Callable[[str, dict], None], + duration: Optional[float] = None, + ) -> None: + """Read-only console capture on a second COM, held open for a duration. + + Unlike :meth:`call` + ``debug_tee_start`` (which stops the moment the + CLI returns and closes the private sidecar — mpftp#… the tee died with + it), this keeps the session alive so the sidecar's tee loop keeps + writing ``log_path`` and emitting ``debug_tee_data`` the whole time. + Never enters raw REPL and never toggles DTR/RTS, so a board autostarted + from ``main.py`` keeps running and its panic backtrace / ``stderr`` is + captured. Returns after ``duration`` seconds (or on KeyboardInterrupt). + """ + raise NotImplementedError + def close(self) -> None: pass @@ -309,6 +330,51 @@ def stream_repl( ): on_notify(msg["method"], msg.get("params") or {}) + def stream_debug_tee( + self, + device: str, + baud: int, + log_path: Optional[str], + on_notify: Callable[[str, dict], None], + duration: Optional[float] = None, + ) -> None: + self._id += 1 + req = { + "id": self._id, + "method": "debug_tee_start", + "params": {"device": device, "baud": baud, "log_path": log_path}, + } + deadline = time.time() + duration if duration is not None else None + with socket.create_connection((self.host, self.port), timeout=None) as s: + s.sendall((json.dumps(req) + "\n").encode("utf-8")) + buf = b"" + while True: + if deadline is not None: + remaining = deadline - time.time() + if remaining <= 0: + return + s.settimeout(remaining) + try: + chunk = s.recv(65536) + except socket.timeout: + return + if not chunk: + break + buf += chunk + while b"\n" in buf: + line, buf = buf.split(b"\n", 1) + text = line.decode("utf-8", "replace").strip() + if not text: + continue + msg = json.loads(text) + if msg.get("type") == "error": + raise RuntimeError(msg.get("error") or "rpc error") + if msg.get("type") == "notify" and msg.get("method") in ( + "debug_tee_data", + "debug_tee_error", + ): + on_notify(msg["method"], msg.get("params") or {}) + def _is_windows_python(python: str) -> bool: p = python.lower() @@ -386,6 +452,7 @@ def __init__(self, python: str) -> None: env=_wslenv_forwarded_env(python), ) self._id = 0 + self._reader_active = False assert self.proc.stdout # wait for ready deadline = time.time() + 20 @@ -446,6 +513,9 @@ def reader() -> None: return threading.Thread(target=reader, daemon=True).start() + # The daemon reader owns stdout from here on; close() must not issue a + # graceful disconnect RPC (it would deadlock fighting for the pipe). + self._reader_active = True deadline = time.time() + duration if duration is not None else None while True: remaining = (deadline - time.time()) if deadline is not None else None @@ -466,11 +536,95 @@ def reader() -> None: if msg.get("id") == self._id and msg.get("type") == "error": raise RuntimeError(msg.get("error") or "sidecar error") - def close(self) -> None: + def stream_debug_tee( + self, + device: str, + baud: int, + log_path: Optional[str], + on_notify: Callable[[str, dict], None], + duration: Optional[float] = None, + ) -> None: + assert self.proc.stdin and self.proc.stdout + self._id += 1 + start_id = self._id + self.proc.stdin.write( + json.dumps( + { + "id": start_id, + "method": "debug_tee_start", + "params": {"device": device, "baud": baud, "log_path": log_path}, + } + ) + + "\n" + ) + self.proc.stdin.flush() + + # Read on a daemon thread so a wall-clock duration can bound the + # capture (a plain readline() can't). The sidecar's tee loop writes + # log_path itself; draining here keeps its stdout pipe from filling + # and stalling that loop. + lines: "queue.Queue[Optional[str]]" = queue.Queue() + + def reader() -> None: + while True: + line = self.proc.stdout.readline() + lines.put(line or None) + if not line: + return + + threading.Thread(target=reader, daemon=True).start() + # The daemon reader owns stdout for the rest of this process, so a + # later close()/self.call() would deadlock fighting it for the pipe. + # Mark the session streaming so close() just terminates the proc. + self._reader_active = True + deadline = time.time() + duration if duration is not None else None try: - self.call("disconnect") - except Exception: - pass + while True: + remaining = (deadline - time.time()) if deadline is not None else None + if remaining is not None and remaining <= 0: + return + try: + line = lines.get( + timeout=max(0.0, remaining) if remaining is not None else None + ) + except queue.Empty: + return + if not line: + err = self.proc.stderr.read() if self.proc.stderr else "" + raise RuntimeError(f"sidecar closed: {err}") + msg = json.loads(line) + if msg.get("type") == "notify" and msg.get("method") in ( + "debug_tee_data", + "debug_tee_error", + ): + on_notify(msg["method"], msg.get("params") or {}) + continue + if msg.get("id") == start_id and msg.get("type") == "error": + raise RuntimeError(msg.get("error") or "sidecar error") + finally: + # The reader thread still owns stdout, so don't use self.call() + # here (it would race for the pipe). Fire-and-forget the stop so + # the sidecar releases the COM port; the reader drains the reply. + self._id += 1 + try: + self.proc.stdin.write( + json.dumps({"id": self._id, "method": "debug_tee_stop", "params": {}}) + + "\n" + ) + self.proc.stdin.flush() + time.sleep(0.3) + except Exception: + pass + + def close(self) -> None: + # A streaming capture (stream_repl/stream_debug_tee) left a daemon + # reader owning stdout; a graceful disconnect RPC would deadlock + # fighting it for the pipe, so skip straight to terminating the proc. + if not getattr(self, "_reader_active", False): + try: + self.call("disconnect") + except Exception: + pass if self.proc: self.proc.terminate() try: @@ -1092,6 +1246,56 @@ def cmd_debug_tee(ns: argparse.Namespace) -> None: client.close() +def cmd_monitor(ns: argparse.Namespace) -> None: + """Read-only console capture on a COM port, held open for a duration. + + This is the capture that ``debug-tee`` could not do from the CLI: the + one-shot ``debug-tee`` returned immediately and the private sidecar (and + its tee) died with the command, so the log stayed empty. ``monitor`` keeps + the session alive for ``--seconds`` (or until Ctrl-C), streaming bytes to + stdout and appending them to ``--log-path``. It never enters raw REPL and + never toggles DTR/RTS, so a board autostarted from ``main.py`` keeps + running and its ``stderr`` / panic backtrace is captured. + + Point it at the ESP console UART (the same COM as the REPL when the board + is *not* under mpftp control, e.g. running main.py) or the native USB CDC + debug port — whichever carries the firmware's console output. + """ + client, mode = get_client() + try: + log_path = ( + _wsl_path_for_windows_sidecar(ns.log_path) if ns.log_path else ns.log_path + ) + duration = float(ns.seconds) if ns.seconds else None + print( + "monitoring %s @ %d baud (read-only, %s) ..." + % ( + ns.device_mon, + ns.baud, + ("%gs" % duration) if duration else "Ctrl-C to stop", + ), + file=sys.stderr, + ) + + def on_notify(method: str, params: dict) -> None: + if method == "debug_tee_data": + b64 = params.get("data_b64") + if b64: + sys.stdout.buffer.write(base64.b64decode(b64)) + sys.stdout.buffer.flush() + elif method == "debug_tee_error": + print(f"[debug_tee_error] {params.get('message')}", file=sys.stderr) + + try: + client.stream_debug_tee( + ns.device_mon, ns.baud, log_path, on_notify, duration + ) + except KeyboardInterrupt: + pass + finally: + client.close() + + def cmd_bootloader(ns: argparse.Namespace) -> None: client, mode = get_client() try: @@ -1699,6 +1903,29 @@ def build_parser() -> argparse.ArgumentParser: dtee.add_argument("--stop", action="store_true", help="Stop an active debug tee") dtee.set_defaults(func=cmd_debug_tee) + mon = sub.add_parser( + "monitor", + help="Read-only console capture on a COM, held open for --seconds " + "(unlike debug-tee, does not die when the command returns)", + ) + mon.add_argument( + "device_mon", + help="Serial device carrying the firmware console (e.g. COM4 or the " + "native USB CDC debug port). Never enters REPL, never toggles DTR/RTS.", + ) + mon.add_argument("--baud", type=int, default=config.resolve("defaultBaud")) + mon.add_argument( + "--seconds", + type=float, + default=None, + help="Capture for this many seconds, then stop (default: until Ctrl-C)", + ) + mon.add_argument( + "--log-path", + help="Append raw bytes here too (default: stdout only)", + ) + mon.set_defaults(func=cmd_monitor) + rtc = sub.add_parser("rtc", parents=[device_opts], help="Get or set RTC") rtc.add_argument("--set", action="store_true", help="Set RTC from host") rtc.set_defaults(func=cmd_rtc) diff --git a/docs/agent-guide.md b/docs/agent-guide.md index b6c26d6..e4799f5 100644 --- a/docs/agent-guide.md +++ b/docs/agent-guide.md @@ -110,6 +110,7 @@ that must land intact. Startup script is usually `main.py` (MP) or `code.py` (CP ./scripts/mpftp soft-reboot # Ctrl-D; runs main.py / code.py ./scripts/mpftp hard-reset ./scripts/mpftp debug-tee COM50 # second port read-only (native USB CDC) +./scripts/mpftp monitor COM4 --seconds 60 --log-path /tmp/con.log # capture console (panic/stderr) ./scripts/mpftp mip github:org/repo # MicroPython only (default target /lib) ./scripts/mpftp circup adafruit_display_text # CircuitPython only → /lib over serial ``` @@ -203,6 +204,42 @@ a capture failure sets `"ok": false` and a `capture_error` key rather than raising past the point where you'd lose the fact that the run itself succeeded. +### Capturing the native console (panic backtraces, C `stderr`) + +`watch-repl` and `run --follow` show what the **Python VM** prints, but they +connect on the control port and drop the board to the REPL, so a board +autostarted from `main.py` stops running under them. That is the wrong tool +when you need the **ESP-IDF console**: the panic/`Guru Meditation` backtrace +from a native crash, `ESP_LOG` output, and any `fprintf(stderr, ...)` from a +user C module. None of those reach a Python-side log — they go straight to the +console UART. + +Use `monitor` for that. It opens a port **read-only**, never enters raw REPL, +and never toggles DTR/RTS (no board reset), so the firmware keeps running while +you capture. Run it in the background, reproduce, then read the log: + +```bash +# Board is running main.py; console is on the control UART when nothing holds it. +mpftp hard-reset -d COM4 && mpftp disconnect -d COM4 # clean boot, release the port +mpftp monitor COM4 --seconds 90 --log-path /tmp/con.log & # read-only capture, no reset +# ... trigger the crash/repro (e.g. drive playback over the network) ... +grep -iE 'guru|backtrace|panic|abort|\[mymod\]' /tmp/con.log +``` + +Which port carries the console depends on the board's +`CONFIG_ESP_CONSOLE_*`: on a single-UART board it is the **same COM as the +REPL** (capture it only when nothing else holds the port — i.e. the board is on +`main.py` and no `exec`/`run`/RPC session is open); on a dual-USB board it may +be the native USB CDC (`role: cdc_debug` in `mpftp ports`). If `monitor COM4` +is silent during a crash, try the other port. + +`monitor` supersedes `debug-tee` for time-bounded capture. `debug-tee` starts a +read-only tee but returns immediately, and from the CLI the private sidecar +(and the tee) dies with the command — the log stays empty. `monitor` holds the +session open for `--seconds` (or until Ctrl-C) so the tee actually writes. +`monitor` also refuses nothing by port role, so point it at whichever COM +carries the console. + **Rules of thumb** - Debug with `exec` / `eval` / `run` before rewriting `main.py` / `code.py`. @@ -446,7 +483,9 @@ where it hung. | `Access is denied` / `transport_dead` after hung `exec`/`run` | Sidecar releases the COM handle automatically (was tracked in [PyDevices/mpftp#3](https://github.com/PyDevices/mpftp/issues/3), fixed via a bounded serial write-timeout); `disconnect` then `resume`/`connect`. If still busy: reload extension window, then replug USB only as last resort | | `timeout waiting for first EOF` | Board still running (UI loop). Use `run` without `--follow` / `exec --no-follow`, then `interrupt` or `soft-reset` | | Soft-reset left UI dead after deploy | Expected: soft-reset skips `main.py`. Use `soft-reboot` or `hard-reset` to run startup | -| Dual USB (UART + native CDC) | `mpftp ports` shows `role` (`repl` vs `cdc_debug`); control on UART, `debug-tee` on CDC | +| Dual USB (UART + native CDC) | `mpftp ports` shows `role` (`repl` vs `cdc_debug`); control on UART, `monitor`/`debug-tee` on CDC | +| Native crash / reboot with no Python traceback | Panic backtrace + `ESP_LOG` + C `fprintf(stderr)` only hit the console UART. `hard-reset` + `disconnect`, then `mpftp monitor --seconds N --log-path …` (read-only, no reset), reproduce, grep the log. `watch-repl`/`run --follow` won't do this — they drop the board to the REPL | +| `monitor`/`debug-tee` log is empty | `debug-tee` from the CLI dies with the command (empty log) — use `monitor`, which holds the port open. If `monitor` is still silent, the console is on the *other* COM (try the native USB CDC, or the REPL UART), or nothing is being printed | | `could not enter raw repl` after flash | Detect; erase + reflash MicroPython; corrupt FS boot loops block soft-reset | | Wrong board / no Wi-Fi on P4 | Detect + MicroPython hints; pick `C5_WIFI` / `C6_WIFI` explicitly if needed | | Build: required tree not found | Symlink under firmware workspace or set env (`IDF_PATH`, `EMSDK`, …); Locate… in UI | From adbf60768ba930d513864219d7f113dc99de44ca Mon Sep 17 00:00:00 2001 From: Brad Barnett <127794626+bdbarnett@users.noreply.github.com> Date: Tue, 15 Sep 2026 00:46:52 -0500 Subject: [PATCH 2/2] monitor: stop the tee on the RPC path too The tee lives in the session, not in the socket that started it. The subprocess client sends debug_tee_stop on its own pipe when the capture ends; the RPC client just closed its stream, so with the extension running -- which is the path get_client() prefers -- monitor --seconds N returned and left the sidecar reading that COM forever: port held against the next connect, log growing, and nothing said so. The new test drives a real socket server and asserts both methods arrive. Against the previous commit it sees only debug_tee_start. --- CHANGELOG.md | 4 ++ cli/src/mpftp/cli.py | 71 +++++++++++++----------- cli/tests/test_monitor_capture.py | 90 +++++++++++++++++++++++++++++++ 3 files changed, 135 insertions(+), 30 deletions(-) create mode 100644 cli/tests/test_monitor_capture.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 574d4de..7773086 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,10 @@ autostarted from `main.py` keeps running and its `stderr` / ESP-IDF panic backtrace is captured — the missing piece for debugging native crashes and C-module `fprintf(stderr, ...)` output that never reaches a Python-side log. +- `monitor` stops the tee when the capture ends, on both transports. The tee + runs inside the session rather than inside the socket that asked for it, so + an RPC-mode client that simply closed its stream left the COM port held and + the log growing until something called `debug-tee --stop`. - Fix `SidecarClient.close()` deadlock after a streaming capture: the daemon stdout reader used by `stream_repl` / `stream_debug_tee` owns the pipe, so a graceful `disconnect` RPC in `close()` hung forever fighting it. `close()` diff --git a/cli/src/mpftp/cli.py b/cli/src/mpftp/cli.py index 7f70158..3cd9db9 100755 --- a/cli/src/mpftp/cli.py +++ b/cli/src/mpftp/cli.py @@ -247,8 +247,8 @@ def stream_debug_tee( """Read-only console capture on a second COM, held open for a duration. Unlike :meth:`call` + ``debug_tee_start`` (which stops the moment the - CLI returns and closes the private sidecar — mpftp#… the tee died with - it), this keeps the session alive so the sidecar's tee loop keeps + CLI returns and closes the private sidecar, so the tee died with it), + this keeps the session alive so the sidecar's tee loop keeps writing ``log_path`` and emitting ``debug_tee_data`` the whole time. Never enters raw REPL and never toggles DTR/RTS, so a board autostarted from ``main.py`` keeps running and its panic backtrace / ``stderr`` is @@ -345,35 +345,46 @@ def stream_debug_tee( "params": {"device": device, "baud": baud, "log_path": log_path}, } deadline = time.time() + duration if duration is not None else None - with socket.create_connection((self.host, self.port), timeout=None) as s: - s.sendall((json.dumps(req) + "\n").encode("utf-8")) - buf = b"" - while True: - if deadline is not None: - remaining = deadline - time.time() - if remaining <= 0: + try: + with socket.create_connection((self.host, self.port), timeout=None) as s: + s.sendall((json.dumps(req) + "\n").encode("utf-8")) + buf = b"" + while True: + if deadline is not None: + remaining = deadline - time.time() + if remaining <= 0: + return + s.settimeout(remaining) + try: + chunk = s.recv(65536) + except socket.timeout: return - s.settimeout(remaining) - try: - chunk = s.recv(65536) - except socket.timeout: - return - if not chunk: - break - buf += chunk - while b"\n" in buf: - line, buf = buf.split(b"\n", 1) - text = line.decode("utf-8", "replace").strip() - if not text: - continue - msg = json.loads(text) - if msg.get("type") == "error": - raise RuntimeError(msg.get("error") or "rpc error") - if msg.get("type") == "notify" and msg.get("method") in ( - "debug_tee_data", - "debug_tee_error", - ): - on_notify(msg["method"], msg.get("params") or {}) + if not chunk: + break + buf += chunk + while b"\n" in buf: + line, buf = buf.split(b"\n", 1) + text = line.decode("utf-8", "replace").strip() + if not text: + continue + msg = json.loads(text) + if msg.get("type") == "error": + raise RuntimeError(msg.get("error") or "rpc error") + if msg.get("type") == "notify" and msg.get("method") in ( + "debug_tee_data", + "debug_tee_error", + ): + on_notify(msg["method"], msg.get("params") or {}) + finally: + # The tee lives in the shared session, not in this socket: closing + # the stream leaves it reading the COM forever, so the next + # connect finds the port busy and the log keeps growing. The + # subprocess client stops it on its own pipe; here a fresh call() + # is enough, and a dead session is not worth raising over. + try: + self.call("debug_tee_stop") + except Exception: + pass def _is_windows_python(python: str) -> bool: diff --git a/cli/tests/test_monitor_capture.py b/cli/tests/test_monitor_capture.py new file mode 100644 index 0000000..6ec258d --- /dev/null +++ b/cli/tests/test_monitor_capture.py @@ -0,0 +1,90 @@ +"""``mpftp monitor``: a bounded read-only console capture. + +The capture itself is covered by watch-repl's shape; what is easy to get +wrong is the end of it. The tee runs inside the session, not inside the +socket that asked for it, so a client that just walks away leaves the COM +port held open and the log growing. Both transports must stop it. +""" + +from __future__ import annotations + +import json +import socket +import threading +import unittest + +from mpftp.cli import TcpClient + + +class TcpClientStopsTheTeeTests(unittest.TestCase): + def test_a_bounded_capture_sends_debug_tee_stop(self): + server = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + server.bind(("127.0.0.1", 0)) + server.listen(2) + host, port = server.getsockname() + methods: list[str] = [] + + def serve(): + # First connection: the capture. Second: whatever the client + # sends once the duration is up. + for _ in range(2): + conn, _addr = server.accept() + with conn: + buf = b"" + while b"\n" not in buf: + chunk = conn.recv(4096) + if not chunk: + return + buf += chunk + req = json.loads(buf.split(b"\n", 1)[0]) + methods.append(req["method"]) + conn.sendall( + ( + json.dumps( + {"type": "result", "id": req["id"], "result": {"ok": True}} + ) + + "\n" + ).encode() + ) + if req["method"] == "debug_tee_start": + conn.sendall( + ( + json.dumps( + { + "type": "notify", + "method": "debug_tee_data", + "params": {"data_b64": "aGk="}, + } + ) + + "\n" + ).encode() + ) + # Then go quiet: the client's duration must expire. + conn.settimeout(3) + try: + conn.recv(4096) + except (socket.timeout, OSError): + pass + + t = threading.Thread(target=serve, daemon=True) + t.start() + try: + client = TcpClient(host, port) + events: list[tuple[str, dict]] = [] + client.stream_debug_tee( + "COM4", + 115200, + None, + lambda method, params: events.append((method, params)), + duration=0.25, + ) + finally: + t.join(timeout=5) + server.close() + + self.assertEqual([("debug_tee_data", {"data_b64": "aGk="})], events) + self.assertEqual(["debug_tee_start", "debug_tee_stop"], methods) + + +if __name__ == "__main__": + unittest.main()