From eeb7b299e66272c4513d3a05b69802f6d2317677 Mon Sep 17 00:00:00 2001 From: Jack Platten Date: Fri, 24 Jul 2026 20:31:10 -0700 Subject: [PATCH] chore(scripts): add a pty probe for debugging prompt renders Timing bugs in the render path cannot be seen by calling fish_prompt from a script: the bug is in when fish renders, not in what one render prints. This drives a real interactive fish in a pty, with an isolated HOME built from the working copy, and takes steps for typing, pasting several lines at once, waiting, and resizing the window either with or without letting fish notice. --trace rewrites the prompt in that copy to log every render, dispatch and signal handler run, which is how the two staleness bugs behind the last three commits were found. It matches exact lines and exits with the anchor it wanted when they move, so it cannot quietly log nothing. The README covers what to run and how to read the log. Manual tool only; mise and CI do not touch it. Co-authored-by: Claude Opus 5 --- AGENTS.md | 4 + scripts/prompt_probe/README.md | 158 +++++++++++++++++ scripts/prompt_probe/probe.py | 304 +++++++++++++++++++++++++++++++++ 3 files changed, 466 insertions(+) create mode 100644 scripts/prompt_probe/README.md create mode 100755 scripts/prompt_probe/probe.py diff --git a/AGENTS.md b/AGENTS.md index aaff4a6..350c183 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -31,6 +31,10 @@ python3 littlecheck.py tests/_tide_item_node.test.fish Test files mock external commands (e.g. `node`, `git`) via [clownfish][clownfish]'s `mock` function — see `tests/_tide_item_node.test.fish` for the pattern. `tests/test_setup.fish` defines `_tide_decolor` (strips ANSI codes for assertions) and sets `_tide_side` for right-prompt items. +### Debugging the async render path + +Timing bugs in the render path — a stale prompt, a missed repaint, two renders racing — usually can't be seen by calling `fish_prompt` from a script, since the bug is in *when* fish renders rather than in what one render prints. `scripts/prompt_probe/probe.py` drives a real interactive fish in a pty (isolated `HOME`, keystrokes, window resizes) and can log every render, dispatch and signal handler run. It is a manual tool, not part of `mise run test`; see `scripts/prompt_probe/README.md`. + ## Architecture ### Item-based prompt composition diff --git a/scripts/prompt_probe/README.md b/scripts/prompt_probe/README.md new file mode 100644 index 0000000..15eb0ca --- /dev/null +++ b/scripts/prompt_probe/README.md @@ -0,0 +1,158 @@ +# prompt_probe + +A manual debugging tool for tide's async render path. It runs an interactive +fish in a pty, types at it, resizes it, and prints what landed on the screen — +optionally with a log of every prompt render, background dispatch and signal +handler run. + +Nothing here is wired into `mise run test` or CI. The littlecheck tests in +`tests/` are the automated check; this is for the bugs those tests can't see +until you know what to assert. + +```fish +python3 scripts/prompt_probe/probe.py --trace 'raw:false\nsleep 1\n' +``` + +## Why a pty + +The prompt is drawn by a real terminal loop reacting to keystrokes, window +size changes and SIGUSR1 from background render jobs. Calling `fish_prompt` +from a script tells you what one render prints; it tells you nothing about +*when* fish renders, how many times, or what state it had at that moment. Most +staleness bugs live in that ordering: + +- a render job finishing while a command is still running, so fish handles the + signal a second later than you'd expect +- two renders in flight at once, because you pressed Enter before the first + finished +- a window resize fish only notices after the foreground command exits + +## What it does + +1. Copies this working copy's `functions/` and `conf.d/` into an isolated + `$HOME` (`$XDG_CACHE_HOME/tide-prompt-probe-home`, or `~/.cache/…`), and + seeds a small prompt config the first time. Your real fish config is never + touched or read. The copy is refreshed on every run, so you always probe + the code you have checked out. +2. Starts `fish -i` under a pty, and answers the terminal capability questions + fish 4.x asks at startup. Skip that and fish waits for replies that never + come, printing no prompt at all. +3. Runs your steps in order, reading output as it goes. +4. Prints the transcript with escape sequences stripped, and each step marked + `<<< like this >>>`. + +The seeded config uses plain words instead of glyphs, so the transcript can be +grepped: `OK` / `FAIL 1` for the status item, `DUR 1.02s` for cmd_duration, +plus the working directory. Pass `--items 'status pwd vcs'` to change the item +list. + +Items beyond those three need colour and icon variables the seed doesn't set, +and will print errors instead of rendering. To get a full set, configure the +probe `$HOME` once: + +```fish +python3 scripts/prompt_probe/probe.py --shell # then: tide configure +``` + +`--shell` hands your terminal to the isolated fish, which is also the easiest +way to poke at the prompt by hand — type, resize the window, run a +full-screen program — without installing anything into your own config. The +probe `$HOME` persists between runs, so configure it once; `--reset` wipes it. + +Add `--trace` to log an interactive session. Nothing can print the log after +handing over the terminal, so the probe prints its path instead; watch it from +a *second* terminal, or read it afterwards: + +```fish +python3 scripts/prompt_probe/probe.py --shell --trace +tail -f ~/.cache/tide-prompt-probe-home/render.log # from another terminal +``` + +Watching from inside the traced shell would log your own `tail` and muddy what +you are reading. + +## Steps + +| Step | What it does | +| --- | --- | +| `sleep 1; false` | types the line, presses Enter, then reads for `--settle` seconds | +| `cmd:CMD` | the same, for a command that would otherwise look like another step | +| `raw:TEXT` | writes TEXT as-is, `\n` included, then reads for `--settle` seconds | +| `keys:TEXT` | writes TEXT as-is, then reads for 0.2s — use before `wait`/`resize` | +| `wait:2` | just reads for 2 seconds | +| `resize:90` | resizes to 90 columns and signals fish, so it notices at once | +| `resizequiet:70` | resizes without signalling fish | + +`raw:` is how you get two commands into fish's input buffer at once, so the +second starts while the first prompt's render is still in flight — the easiest +way to reproduce an overlap by hand. + +`resizequiet:` is what a full-screen program looks like. During a foreground +command fish isn't in the terminal's foreground process group, so it gets no +SIGWINCH and only learns the new size once the command exits — a different +code path from a resize at the prompt, and one that used to leave the prompt +stale. + +## Reading `--trace` + +`--trace` rewrites the prompt in the probe's copy of tide, adding a log line +per event: + +``` +1784950146.652 PROMPT argv='' repaint= cycle=1 <- fish asked for a prompt +1784950146.665 dispatch: pid=57605 cycle=1 <- a background render started +1784950146.679 handler: reading pid=57605 … <- its result arrived +1784950146.691 PROMPT argv='' repaint=1 cycle=1 <- the repaint it asked for +``` + +What to look for: + +- **A gap between `dispatch` and `handler`** longer than a render takes means + fish sat on the signal — it was running a foreground command. +- **`repaint=` matching `cycle=`** on a prompt means that render deliberately + skipped starting a job, because it is the repaint the handler asked for. A + match at the *start* of a new cycle would be a bug: that prompt paints + pre-command content. +- **Two `dispatch` lines with no `handler` between them** means renders + overlapped, so one job is about to be superseded. +- **A `handler` line with `lines=0`** means the newest job hasn't published + yet and the signal came from a straggler. + +Timestamps cost a `perl` fork per line, so tracing perturbs the timing it +measures. Use it to establish ordering, not to benchmark. + +The log lives at `/render.log` and is **deleted at the start of +every run**, so it only ever holds the latest one — copy it elsewhere to keep +it. Every run also resyncs `functions/` from the repo, which removes the trace +patch, so `--trace` belongs on the run you actually want traced: a run without +it leaves an unpatched prompt that logs nothing. + +## Recipes + +```fish +# two commands at once: the second starts while a render is in flight +python3 scripts/prompt_probe/probe.py --trace 'raw:false\nsleep 3\n' + +# resize while a command runs, then again after +python3 scripts/prompt_probe/probe.py 'keys:sleep 3\n' 'wait:0.5' 'resize:90' 'wait:3' + +# what a full-screen program does: size changes, fish finds out afterwards +python3 scripts/prompt_probe/probe.py 'keys:sleep 3\n' 'wait:0.5' 'resizequiet:70' 'wait:3' + +# leave a slow repo render behind by cd-ing straight out of it +# (needs a configured probe $HOME for the vcs item -- see above) +python3 scripts/prompt_probe/probe.py --items 'status cmd_duration pwd vcs' \ + "raw:cd $PWD\ncd /tmp\n" +``` + +After each one, check the last prompt in the transcript against what actually +happened: right exit status, right duration, right directory. A brief wrong +prompt that corrects itself is normal — the prompt is async by design. A wrong +prompt that survives until the next keystroke is the bug. + +## When the anchors drift + +`--trace` patches `functions/fish_prompt.fish` by matching exact lines. Change +those lines and the probe exits with the anchor it wanted and how many times it +found it. Fix `TRACE_PATCHES` in `probe.py`; don't work around it, since a +silently unpatched prompt logs nothing and looks like "no renders happened". diff --git a/scripts/prompt_probe/probe.py b/scripts/prompt_probe/probe.py new file mode 100755 index 0000000..25882ac --- /dev/null +++ b/scripts/prompt_probe/probe.py @@ -0,0 +1,304 @@ +#!/usr/bin/env python3 +"""Drive tide's prompt in a real interactive fish, inside a pty. + +A manual debugging tool for the async render path -- staleness, missed +repaints, background-job races. Not part of `mise run test`. + +See README.md in this directory for what it does and how to read its output. +""" + +import argparse +import fcntl +import os +import pty +import re +import select +import shutil +import signal +import struct +import subprocess +import sys +import termios +import time +from pathlib import Path + +REPO = Path(__file__).resolve().parents[2] + +# Legible stand-ins for tide's glyphs, so the transcript can be grepped: +# `OK`/`FAIL 1` for the status item, `DUR 1.02s` for cmd_duration. +SEED_CONFIG = """ +set -U tide_left_prompt_items status cmd_duration pwd +set -U tide_right_prompt_items +set -U tide_prompt_add_newline_before false +set -U tide_left_prompt_frame_enabled false +set -U tide_right_prompt_frame_enabled false +set -U tide_prompt_min_cols 1 +set -U tide_prompt_pad_items false +set -Ux tide_status_icon OK +set -Ux tide_status_icon_failure FAIL +set -U tide_status_bg_color normal +set -U tide_status_bg_color_failure normal +set -Ux tide_cmd_duration_icon DUR +set -Ux tide_cmd_duration_threshold 100 +set -Ux tide_cmd_duration_decimals 2 +set -U tide_cmd_duration_bg_color normal +set -U tide_pwd_icon '' +set -U tide_pwd_icon_home '' +set -U tide_pwd_icon_unwritable '' +set -U tide_pwd_bg_color normal +""" + +# `--trace` rewrites the prompt in the probe's own copy of tide, so every +# render, dispatch and signal handler run lands in a log with a timestamp. +# Each anchor must match exactly as many times as stated, so this fails +# loudly when fish_prompt.fish moves rather than tracing nothing. +LOG_FUNCTION = """function _tide_probe_log + set -l stamp (command perl -MTime::HiRes -e 'printf "%.3f", Time::HiRes::time()' 2>/dev/null) + test -n "$stamp" || set stamp (command date +%s) + command printf '%s %s\\n' $stamp "$argv" >>@LOG@ +end + +""" + +TRACE_PATCHES = [ + ( + 1, + "set_color normal | read -l color_normal", + LOG_FUNCTION + "set_color normal | read -l color_normal", + ), + ( + 1, + " set -l rendered (cat $_tide_prompt_tmpfile.$_tide_last_pid 2>/dev/null)", + " set -l rendered (cat $_tide_prompt_tmpfile.$_tide_last_pid 2>/dev/null)\n" + ' _tide_probe_log " handler: reading pid=$_tide_last_pid lines="(count $rendered)" cycle=$_tide_cycle"', + ), + ( + 1, + " set -g _tide_last_pid $last_pid", + " set -g _tide_last_pid $last_pid\n" + ' _tide_probe_log " dispatch: pid=$last_pid cycle=$_tide_cycle"', + ), + ( + 2, + " set -lx _tide_status \\$status\n _tide_pipestatus=\\$pipestatus if test", + " set -lx _tide_status \\$status\n" + " set -l _tide_probe_ps \\$pipestatus\n" + " _tide_probe_log \\\"PROMPT argv='\\$argv' repaint=\\$_tide_repaint cycle=\\$_tide_cycle\\\"\n" + " _tide_pipestatus=\\$_tide_probe_ps if test", + ), +] + +ESCAPES = [ + re.compile(r"\x1b\[[0-9;?>]*[a-zA-Z]"), + re.compile(r"\x1b[\]P][^\x07\x1b]*(\x07|\x1b\\)?"), + re.compile(r"\x1b[()][B0]"), + re.compile(r"\x1b[=>]"), +] + + +def probe_home(): + base = os.environ.get("XDG_CACHE_HOME") or os.path.expanduser("~/.cache") + return Path(base) / "tide-prompt-probe-home" + + +def build_home(args): + """Sync this working copy of tide into an isolated, reusable $HOME.""" + home = probe_home() + config = home / ".config" / "fish" + + if args.reset: + shutil.rmtree(home, ignore_errors=True) + + fresh = not (config / "fish_variables").exists() + config.mkdir(parents=True, exist_ok=True) + + # Always resync, so the probe runs whatever is checked out right now. + for name in ("functions", "conf.d"): + shutil.rmtree(config / name, ignore_errors=True) + shutil.copytree(REPO / name, config / name) + + log = home / "render.log" + log.unlink(missing_ok=True) + if args.trace: + patch_prompt(config / "functions" / "fish_prompt.fish", log) + + seed = SEED_CONFIG if fresh else "" + if args.items: + seed += f"\nset -U tide_left_prompt_items {args.items}\n" + if seed: + run_fish(home, seed) + + return home, log + + +def patch_prompt(path, log): + source = path.read_text() + for expected, anchor, replacement in TRACE_PATCHES: + found = source.count(anchor) + if found != expected: + sys.exit( + f"--trace: expected {expected} occurrence(s) of this anchor in " + f"{path.name}, found {found}. The prompt has changed; update " + f"TRACE_PATCHES in {Path(__file__).name}.\n anchor: {anchor!r}" + ) + replacement = replacement.replace("@LOG@", str(log)) + source = source.replace(anchor, replacement) + path.write_text(source) + + +def run_fish(home, script): + env = dict(os.environ, HOME=str(home), XDG_CONFIG_HOME=str(home / ".config")) + env.pop("XDG_CACHE_HOME", None) + result = subprocess.run( + ["fish", "-c", script], env=env, capture_output=True, text=True + ) + if result.returncode != 0: + sys.exit(f"config setup failed:\n{result.stderr}") + + +def spawn(home, cols, lines, cwd): + env = dict(os.environ, HOME=str(home), XDG_CONFIG_HOME=str(home / ".config")) + env["TERM"] = "xterm-256color" + env.pop("XDG_CACHE_HOME", None) + + pid, fd = pty.fork() + if pid == 0: + os.chdir(cwd or str(home)) + os.execvpe("fish", ["fish", "-i"], env) + + fcntl.ioctl(fd, termios.TIOCSWINSZ, struct.pack("HHHH", lines, cols, 0, 0)) + return pid, fd + + +class Session: + def __init__(self, pid, fd): + self.pid, self.fd = pid, fd + self.out = [] + + def drain(self, seconds): + end = time.time() + seconds + while True: + left = end - time.time() + if left <= 0: + return + ready, _, _ = select.select([self.fd], [], [], left) + if not ready: + continue + try: + data = os.read(self.fd, 65536) + except OSError: + return + if not data: + return + # fish 4.x asks the terminal what it can do and waits for the + # replies. A bare pty never answers, so stand in for a terminal + # -- without this fish blocks at startup and prints no prompt. + if b"\x1b]11;?" in data: + os.write(self.fd, b"\x1b]11;rgb:0000/0000/0000\x1b\\") + if b"\x1b[0c" in data: + os.write(self.fd, b"\x1b[?62;22c") + self.out.append(data.decode("utf8", "replace")) + + def send(self, text): + os.write(self.fd, text.encode()) + + def resize(self, cols, lines, notify): + fcntl.ioctl(self.fd, termios.TIOCSWINSZ, struct.pack("HHHH", lines, cols, 0, 0)) + if notify: + os.kill(self.pid, signal.SIGWINCH) + + def mark(self, text): + self.out.append(f"\n<<< {text} >>>\n") + + def transcript(self): + text = "".join(self.out) + for pattern in ESCAPES: + text = pattern.sub("", text) + return text.replace("\r", "") + + +def run_steps(session, steps, settle, lines): + for step in steps: + kind, _, value = step.partition(":") + if kind == "wait": + session.drain(float(value)) + continue + if kind in ("resize", "resizequiet"): + session.mark(step) + session.resize(int(value), lines, notify=kind == "resize") + session.drain(0.2) + continue + + session.mark(step) + if kind == "raw": + session.send(value.replace("\\n", "\n")) + session.drain(settle) + elif kind == "keys": + session.send(value.replace("\\n", "\n")) + session.drain(0.2) + else: + session.send((value if kind == "cmd" else step) + "\n") + session.drain(settle) + + +def main(): + parser = argparse.ArgumentParser( + description="Drive tide's prompt in an interactive fish inside a pty.", + epilog="steps: CMD | cmd:CMD | raw:TEXT | keys:TEXT | wait:SECONDS | " + "resize:COLS | resizequiet:COLS (see README.md)", + ) + parser.add_argument("steps", nargs="*", help="what to do, in order") + parser.add_argument("--items", help='value for tide_left_prompt_items, e.g. "status pwd vcs"') + parser.add_argument("--trace", action="store_true", help="log every render, dispatch and handler run") + parser.add_argument("--settle", type=float, default=2.5, help="seconds to read after a command (default 2.5)") + parser.add_argument("--cols", type=int, default=100) + parser.add_argument("--lines", type=int, default=40) + parser.add_argument("--cwd", help="directory to start fish in (default: the probe $HOME)") + parser.add_argument("--reset", action="store_true", help="delete the probe $HOME and reseed its config") + parser.add_argument( + "--shell", + action="store_true", + help="hand over to the isolated fish instead of running steps, e.g. to run `tide configure` in it", + ) + args = parser.parse_args() + + if not (REPO / "functions" / "fish_prompt.fish").exists(): + sys.exit(f"cannot find tide's functions/ under {REPO}") + + home, log = build_home(args) + + if args.shell: + print(f"=== probe $HOME: {home}") + if args.trace: + # Nothing prints the log after an exec, and watching it from + # inside the traced shell would log the watching itself. + print(f"=== render log: {log}") + print(f"=== watch it from another terminal: tail -f {log}") + print("=== exit the shell to come back") + # exec replaces this process, so anything still sitting in Python's + # stdout buffer would never be written. + sys.stdout.flush() + env = dict(os.environ, HOME=str(home), XDG_CONFIG_HOME=str(home / ".config")) + env.pop("XDG_CACHE_HOME", None) + os.chdir(args.cwd or str(home)) + os.execvpe("fish", ["fish", "-i"], env) + + pid, fd = spawn(home, args.cols, args.lines, args.cwd) + session = Session(pid, fd) + + session.drain(2.0) + run_steps(session, args.steps, args.settle, args.lines) + session.drain(1.0) + session.send("exit\n") + session.drain(1.0) + + print(f"=== probe $HOME: {home}") + print("=== transcript") + print(session.transcript()) + if args.trace: + print("=== render log") + print(log.read_text() if log.exists() else "(empty -- no renders logged)") + + +if __name__ == "__main__": + main()