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()