Connect to CircuitPython without waiting out timeouts

cli/src/mpftp/pwa.py

@@ -314,7 +314,9 @@ def __init__(self, python: str, local_path: Optional[str] = None) -> None:
             [python, "-m", "mpftp.sidecar"],
             stdin=subprocess.PIPE,
             stdout=subprocess.PIPE,
-            stderr=subprocess.PIPE,
+            # The sidecar's warnings and MPFTP_TRACE lines go where ours do (the
+            # desktop app's host.log). A pipe nobody reads fills and hangs it.
+            stderr=None,
             text=True,
             bufsize=1,
             env=_wslenv_forwarded_env(python),

cli/src/mpftp/rawpaste.py

@@ -366,6 +366,31 @@ def exec_raw_no_follow(self, command: Any) -> Any:
                 self.use_raw_paste = True
             return super().exec_raw_no_follow(command)
 
+        #: How long to wait for CircuitPython to finish switching to the friendly REPL.
+        FRIENDLY_PROMPT_WAIT = 10.0
+
+        def exit_raw_repl(self) -> None:
+            super().exit_raw_repl()
+            if self.paced is not None and self.paced():
+                self._await_friendly_prompt()
+
+        def _await_friendly_prompt(self) -> None:
+            """Wait out CircuitPython's switch to the friendly REPL.
+
+            CircuitPython does not flip REPL modes the way MicroPython does:
+            Ctrl-B makes the raw REPL return, ``run_repl`` tears the VM down and
+            builds it again, and only then does the friendly REPL print its
+            banner and ``>>> ``. Input sent in between is dropped, so the
+            ``Ctrl-C, Ctrl-A`` of the next ``enter_raw_repl`` vanished and it
+            waited out its whole timeout (mpftp#155). The banner and prompt
+            are put back for whoever reads next, the REPL pane or the next
+            ``enter_raw_repl``, which throws them away.
+            """
+            ser = self._serial
+            prompt = b">>> "
+            data = ser.read_until(prompt, None, self.FRIENDLY_PROMPT_WAIT, None)
+            ser._ahead[0:0] = data
+
         def raw_paste_write(self, command_bytes: bytes) -> None:
             if self.paced is not None and self.paced():
                 paced_raw_paste_write(self, command_bytes)

cli/src/mpftp/sidecar.py

@@ -325,6 +325,28 @@ def port_is_uart_bridge(device: Optional[str]) -> bool:
     return False
 
 
+#: Vendors whose boards have no EN/IO0 wired to DTR/RTS: Raspberry Pi (RP2040,
+#: RP2350) and Adafruit's native-USB boards.
+_NO_ESP_RESET_VIDS = frozenset({0x2E8A, 0x239A})
+
+
+def port_can_be_esp_download(device: Optional[str]) -> bool:
+    """False when ``device`` is a port whose DTR/RTS pulse cannot reset an ESP32
+    out of download mode (an RP2 or Adafruit native-USB port); True when it can
+    or when we can't tell."""
+    if not device:
+        return True
+    try:
+        import serial.tools.list_ports
+
+        for p in serial.tools.list_ports.comports():
+            if p.device == device:
+                return p.vid not in _NO_ESP_RESET_VIDS
+    except Exception:
+        pass
+    return True
+
+
 def port_is_native_cdc(device: Optional[str]) -> bool:
     """True when ``device`` is a CDC port served by firmware on the chip itself.
 
@@ -446,6 +468,34 @@ def build_circup_web_argv(
 _emit_lock = threading.Lock()
 
 
+def trace_enabled() -> bool:
+    """True when ``MPFTP_TRACE`` is set (and not ``0``): the sidecar then writes
+    where a connect or first command spends its time to stderr, which the
+    desktop app keeps in ``host.log``."""
+    return os.environ.get("MPFTP_TRACE", "") not in ("", "0")
+
+
+_TRACE_START = [0.0]
+
+
+def trace(stage: str, restart: bool = False) -> None:
+    """One ``mpftp trace +seconds stage`` line when tracing is on. ``restart``
+    zeroes the clock first, so the seconds count from the start of an operation."""
+    import time
+
+    if restart or not _TRACE_START[0]:
+        _TRACE_START[0] = time.monotonic()
+    if not trace_enabled():
+        return
+    try:
+        sys.stderr.write(
+            "mpftp trace +%.3fs %s\n" % (time.monotonic() - _TRACE_START[0], stage)
+        )
+        sys.stderr.flush()
+    except Exception:
+        pass
+
+
 def _emit(obj: dict[str, Any]) -> None:
     out = _rpc_out if _rpc_out is not None else sys.stdout
     line = json.dumps(obj, ensure_ascii=False) + "\n"
@@ -840,7 +890,9 @@ def connect(
         retry_delay = 0.4
 
         with self._lock:
+            trace("connect %s start" % device, restart=True)
             self.disconnect()
+            trace("previous session closed")
             self.baud = baud
             self.filesystem_warning = None
             last_probe_err: Optional[Exception] = None
@@ -850,6 +902,7 @@ def connect(
                 try:
                     self.transport = self._open_transport(device, baud)
                     _bound_write_timeout(self.transport)
+                    trace("attempt %d: port open" % attempt)
                 except (webrepl.WebReplAuthError, ble.BleAuthError) as e:
                     # Retrying a wrong password only repeats the refusal.
                     raise RuntimeError(str(e)) from e
@@ -874,6 +927,7 @@ def connect(
                 try:
                     rtc = self._probe_micropython(self.transport)
                 except Exception as e:
+                    trace("attempt %d: probe failed: %s" % (attempt, str(e).splitlines()[0][:80]))
                     try:
                         self.transport.close()
                     except Exception:
@@ -896,6 +950,7 @@ def connect(
                 self.last_device = device
                 if network:
                     self._answered.add(device)
+                trace("connected (%s)" % (self.interpreter or "micropython"))
                 return self._connect_result(device, baud, rtc, retries=attempt - 1)
             # Unreachable: the loop always returns or raises on the last attempt.
             raise RuntimeError(
@@ -1090,6 +1145,11 @@ def _reset_esp_to_app(self, serial: Any) -> None:
 
         if isinstance(serial, (webrepl.WebSocketSerial, ble.BleSerial)):
             return  # no EN/IO0 lines over the air
+        port = getattr(serial, "port", None)
+        if isinstance(port, str) and not port_can_be_esp_download(port):
+            # A Pico or other RP2 board: nothing is wired to DTR/RTS, and the
+            # 1.6 s wait for an ESP32 boot banner is just time lost (mpftp#155).
+            return
 
         try:
             serial.dtr = False  # IO0 released (not held for download)
@@ -1161,26 +1221,47 @@ def ctrl_c() -> None:
                         f"serial handle dead during interrupt: {e}"
                     ) from e
 
-        def poke_enter_repl_key(data: bytes) -> None:
-            # CircuitPython waits for any key before showing the friendly REPL.
-            if data_has_enter_repl_prompt(data):
-                try:
-                    serial.write(b"\r")
-                except Exception as e:
-                    if is_dead_serial_error(e):
-                        raise RuntimeError(
-                            f"serial handle dead during REPL poke: {e}"
-                        ) from e
-                time.sleep(0.15)
+        def await_friendly_prompt(seen: bytes) -> None:
+            # CircuitPython starts its REPL on a fresh VM and drops what
+            # arrives meanwhile (about 3 s on an RP2350), so a Ctrl-A sent
+            # before the prompt is lost (mpftp#155). Press the key it asks
+            # for, if it asks, and wait for the prompt. A board can miss a key
+            # sent just after it asks, so press it again each second; one
+            # that arrives while the REPL starts is dropped and does no harm.
+            poked_at = None
+            deadline = time.monotonic() + 6.0
+            while b">>> " not in seen and time.monotonic() < deadline:
+                now = time.monotonic()
+                if data_has_enter_repl_prompt(seen) and (
+                    poked_at is None or now - poked_at >= 1.0
+                ):
+                    try:
+                        serial.write(b"\r")
+                    except Exception as e:
+                        if is_dead_serial_error(e):
+                            raise RuntimeError(
+                                f"serial handle dead during REPL poke: {e}"
+                            ) from e
+                    trace("REPL key pressed" if poked_at is None else "REPL key pressed again")
+                    poked_at = now
+                time.sleep(0.05)
                 try:
                     n = serial.inWaiting()
                     if n:
-                        note_bytes(serial.read(n))
+                        data = serial.read(n)
+                        note_bytes(data)
+                        seen += data
                 except Exception as e:
                     if is_dead_serial_error(e):
                         raise RuntimeError(
-                            f"serial handle dead during REPL poke: {e}"
+                            f"serial handle dead waiting for the REPL: {e}"
                         ) from e
+            trace("REPL woken" if b">>> " in seen else "REPL not woken")
+
+        def poke_enter_repl_key(data: bytes) -> None:
+            # CircuitPython waits for any key before showing the friendly REPL.
+            if data_has_enter_repl_prompt(data):
+                await_friendly_prompt(data)
 
         def interrupt_storm() -> None:
             # Thorough interrupt (see micropython#7867 / Thonny pipkin).
@@ -1189,18 +1270,38 @@ def interrupt_storm() -> None:
                 if delay:
                     time.sleep(delay)
                 ctrl_c()
-            time.sleep(0.05)
-            try:
-                n = serial.inWaiting()
-                if n:
-                    data = serial.read(n)
-                    note_bytes(data)
-                    poke_enter_repl_key(data)
-            except Exception as e:
-                if is_dead_serial_error(e):
-                    raise RuntimeError(
-                        f"serial handle dead during interrupt storm: {e}"
-                    ) from e
+            # A program can take longer to stop than the storm lasts. Give it
+            # a second to say so, or a raw REPL try sent now is spent as the
+            # key that starts the REPL.
+            data = b""
+            deadline = time.monotonic() + 1.0
+            while True:
+                time.sleep(0.05)
+                try:
+                    n = serial.inWaiting()
+                    if n:
+                        data += serial.read(n)
+                except Exception as e:
+                    if is_dead_serial_error(e):
+                        raise RuntimeError(
+                            f"serial handle dead during interrupt storm: {e}"
+                        ) from e
+                    break
+                if (
+                    b">>> " in data
+                    or b"KeyboardInterrupt" in data
+                    or data_has_enter_repl_prompt(data)
+                    or data.rstrip().endswith(b">")
+                    or time.monotonic() >= deadline
+                ):
+                    break
+            note_bytes(data)
+            # A stopped program: on CircuitPython the storm's own keys may
+            # already have started the REPL, so wait for its prompt too.
+            if data_has_enter_repl_prompt(data) or (
+                b"KeyboardInterrupt" in data and b">>> " not in data
+            ):
+                await_friendly_prompt(data)
 
         # Probe the handle before investing in the handshake.
         try:
@@ -1221,13 +1322,18 @@ def interrupt_storm() -> None:
             note_bytes(after)
             poke_enter_repl_key(after)
 
+        trace("peek done")
         interrupt_storm()
+        trace("interrupt storm done")
 
         def try_raw(soft_reset: bool, per: float) -> bool:
+            trace("enter raw REPL (soft_reset=%s, up to %.1fs)" % (soft_reset, per))
             try:
                 t.enter_raw_repl(soft_reset=soft_reset, timeout_overall=per)
+                trace("raw REPL entered")
                 return True
             except Exception:
+                trace("raw REPL not entered")
                 try:
                     n = serial.inWaiting()
                     if n:
@@ -1256,15 +1362,18 @@ def try_raw(soft_reset: bool, per: float) -> bool:
 
         # Two short tries, then one app-mode reset (covers silent download mode
         # where the banner was already drained), then two more tries.
+        # The first allows for CircuitPython, which takes 3.2 s or more to
+        # answer Ctrl-A on an RP2350 (mpftp#155).
         schedule = [
-            ("try", 3.5),
+            ("try", 5.0),
             ("try", 3.5),
             ("reset", 0.0),
             ("try", 5.0),
             ("try", 5.0),
         ]
         for action, per in schedule:
             if action == "reset":
+                trace("reset step")
                 self._reset_esp_to_app(serial)
                 after = self._serial_peek(serial, 0.3)
                 note_bytes(after)
@@ -1283,7 +1392,7 @@ def try_raw(soft_reset: bool, per: float) -> bool:
                             return
                     except Exception as e:
                         last_err = e
-                    continue
+                continue
             try:
                 if try_raw(False, per):
                     if last_err is not None:
@@ -1383,20 +1492,15 @@ def _finish_clean_after_raw(
     ) -> None:
         """After raw REPL is open: detect interpreter and apply clean semantics."""
         interpreter = self._detect_interpreter(t)
+        trace("interpreter detected: %s" % interpreter)
         if not want_clean:
             return
         if interpreter == "circuitpython":
-            # Thonny CP clear_repl: exit raw → enter raw (no Ctrl-D soft-reboot).
-            try:
-                if t.in_raw_repl:
-                    t.exit_raw_repl()
-            except Exception:
-                pass
-            try:
-                t.in_raw_repl = False
-            except Exception:
-                pass
-            t.enter_raw_repl(soft_reset=False, timeout_overall=10.0)
+            # Thonny's clear_repl leaves raw REPL and enters it again. Here that
+            # buys nothing: on CircuitPython every switch between the friendly
+            # and the raw REPL already rebuilds the VM (main.c run_repl), so the
+            # one that brought us here left it clean, and the extra round trip
+            # cost two more rebuilds and a wait for each (mpftp#155).
             try:
                 t.exec(
                     "try:\n"
@@ -1527,18 +1631,25 @@ def _probe_micropython(self, t: Any) -> Optional[list[int]]:
         friendly↔raw toggle (Ctrl-D would run code.py).
         """
         self._take_control(t, clean=True, timeout_overall=20.0)
+        trace("board under control")
         rtc: Optional[list[int]] = None
         try:
             rtc = self._apply_rtc(t)
         except Exception:
             # Some ports lack machine.RTC / rtc.RTC; don't fail the connection.
             pass
+        trace("clock checked")
         self.board_identity = None
         if (self.interpreter or "micropython") == "micropython":
             try:
                 self.board_identity = wifiboard.parse_identity(t.exec(wifiboard.IDENTITY_CODE))
             except Exception:
                 pass  # identity is for remembering Wi-Fi boards; never fail a connect
+        if self.interpreter == "circuitpython":
+            # Leaving raw REPL rebuilds the VM and so does the next command's
+            # entering it again. Stay in raw REPL: commands run from there, and
+            # the REPL pane leaves it when it opens (mpftp#155).
+            return rtc
         try:
             if t.in_raw_repl:
                 t.exit_raw_repl()
@@ -1700,9 +1811,12 @@ def _enter_raw(self, soft_reset: bool = False) -> None:
             if soft_reset:
                 self._take_control_resilient(t, clean=True, timeout_overall=20.0)
             else:
+                trace("command: entering raw REPL", restart=True)
                 try:
                     t.enter_raw_repl(soft_reset=False, timeout_overall=8.0)
+                    trace("command: raw REPL entered")
                 except Exception:
+                    trace("command: quick entry failed, taking control")
                     self._take_control_resilient(t, clean=False, timeout_overall=20.0)
 
     def _leave_raw_to_repl(self) -> None:
@@ -4123,9 +4237,11 @@ def repl_start(self) -> dict[str, Any]:
             # shows two (mpftp#154).
             shown = self._prompt_pending
             self._prompt_pending = False
+            trace(f"REPL pane opening, in raw REPL: {t.in_raw_repl}")
             if t.in_raw_repl:
                 self._drop_raw_prompt(t)
                 t.exit_raw_repl()
+                trace("left raw REPL for the pane")
                 shown = True
             self._repl_mode = True
             self._start_repl_reader()
@@ -4150,6 +4266,7 @@ def repl_write(self, data_b64: str) -> dict[str, Any]:
         data = base64.b64decode(data_b64)
         with self._lock:
             t = self._require()
+            trace(f"REPL input, {len(data)} bytes, in raw REPL: {t.in_raw_repl}")
             if t.in_raw_repl:
                 t.exit_raw_repl()
             if not self._repl_mode: