diff --git a/docs/maintainer/internals.md b/docs/maintainer/internals.md index f5a263e8..17c59a8c 100644 --- a/docs/maintainer/internals.md +++ b/docs/maintainer/internals.md @@ -43,6 +43,8 @@ These are mistakes already made here; each was silent rather than loud, which is **`internal/daemon` must not depend on a cloud package.** What an engine should serve is `inference.DeployConfig`, in `internal/inference` — a leaf that imports only the standard library. Both the daemon and the cloud control plane speak it, so neither has to import the other to be described: a daemon is handed one over its control API, and `internal/remote` persists one against an environment. The dependency used to run the other way, `internal/daemon` importing `internal/remote` for the type and for a config-directory helper that only forwarded to `internal/config.Dir`, which made the package that knows nothing about AWS depend on the package that is nothing but AWS. Keep new shared vocabulary in `internal/inference` only where it describes an engine's workload and needs nothing of ours to express; anything cloud-shaped — `IsInstanceType` and the rest of the EC2 vocabulary — stays in `internal/remote`. +**A captured engine's stdout is a pseudo-terminal, and the normaliser above it is a line model, not a screen emulator.** llama.cpp's download bar prints nothing when its stdout is not a terminal, and the download happens in-process before the HTTP listener comes up — there is no status API to scrape — so the capture (the daemon and the serve view) presents the engine's stdout as a PTY: the only way the progress reaches the engine log at all. `ptylog.go` turns the terminal stream into the log's lines as a column, and three of its rules are easy to break by "simplifying". The engine's up-down cursor dance is *part of each redraw* — the bar's state is drawn between a cursor-up and a cursor-back-down, the cursor parked on an anchor line — so a cursor move must move the drawing between the column's lines and never end a line: committing on a move records every state as a "final" one and resets the dedup, which is how the first design put the whole download, state for state, in the log. A state's replacement is lazy — a carriage return settles the state drawn before it, and the line's content is cleared only by the next text byte — so `S\r\r\n`, the PTY's ONLCR turning a lone `\n` into a CRLF, commits `S` intact. And the tick at the interval's half-rate runs on *every* line of the column, because a bar's last state outlives the engine's move off its line: the download finishes, the engine goes quiet on stdout, and the log still owes it. Because the engine's stdout is now a terminal, the capture branch sets `NO_COLOR=1` in the engine's environment: llama.cpp routes its log lines to stderr and colours them by whether it sees a terminal — *stdout* among them — and the normaliser never sees the stderr path, so without it escapes would reach the log file. The bar draws no colour, so nothing is lost; the forwarding paths (piped `serve`, off-terminal `serve --api`) set nothing and must stay byte-for-byte what the engine wrote — a test pins the raw `\r` surviving. Where no pseudo-terminal can be opened — Windows, a restricted environment — the fallback writes stdout to the log file directly, no worse than the capture did before, and the engine is told `NO_COLOR` the same way; a test stands the opening in for with a failure to keep that branch alive. The pump always drains — the throttle delays the log's writes, never the reads, so the engine can never wedge on a full terminal — and the log file closes only after the pump's final record, never under it. + ## Dashboard (`fleet_dashboard.go` and friends) A few Bubble Tea/lipgloss specifics that are easy to break by "simplifying": diff --git a/go.mod b/go.mod index 5ad6a2a2..cf6bcd69 100644 --- a/go.mod +++ b/go.mod @@ -19,6 +19,7 @@ require ( github.com/charmbracelet/lipgloss v1.1.0 github.com/charmbracelet/x/ansi v0.11.8 github.com/charmbracelet/x/exp/teatest v0.0.0-20260816001655-68d539dca504 + github.com/creack/pty v1.1.24 github.com/godbus/dbus/v5 v5.2.2 github.com/muesli/termenv v0.16.0 github.com/spf13/cobra v1.10.2 diff --git a/go.sum b/go.sum index 46df6727..f4db32a3 100644 --- a/go.sum +++ b/go.sum @@ -63,6 +63,8 @@ github.com/clipperhouse/displaywidth v0.11.0/go.mod h1:bkrFNkf81G8HyVqmKGxsPufD3 github.com/clipperhouse/uax29/v2 v2.7.0 h1:+gs4oBZ2gPfVrKPthwbMzWZDaAFPGYK72F0NJv2v7Vk= github.com/clipperhouse/uax29/v2 v2.7.0/go.mod h1:EFJ2TJMRUaplDxHKj1qAEhCtQPW2tJSwu5BF98AuoVM= github.com/cpuguy83/go-md2man/v2 v2.0.6/go.mod h1:oOW0eioCTA6cOiMLiUPZOpcVxMig6NIQQ7OS05n1F4g= +github.com/creack/pty v1.1.24 h1:bJrF4RRfyJnbTJqzRLHzcGaZK1NeM5kTC9jGgovnR1s= +github.com/creack/pty v1.1.24/go.mod h1:08sCNb52WyoAwi2QDyzUCTgcvVFhUzewun7wtTfvcwE= github.com/danieljoos/wincred v1.2.3 h1:v7dZC2x32Ut3nEfRH+vhoZGvN72+dQ/snVXo/vMFLdQ= github.com/danieljoos/wincred v1.2.3/go.mod h1:6qqX0WNrS4RzPZ1tnroDzq9kY3fu1KwE7MRLQK4X0bs= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= diff --git a/internal/daemon/daemon_test.go b/internal/daemon/daemon_test.go index 01b297f1..ee61f98c 100644 --- a/internal/daemon/daemon_test.go +++ b/internal/daemon/daemon_test.go @@ -127,6 +127,51 @@ func TestSupervisorCleanExitIsStopped(t *testing.T) { } } +func TestStartRefusesAnEmptyCommand(t *testing.T) { + s := NewSupervisor(filepath.Join(t.TempDir(), "engine.log")) + if err := s.Start(nil); err == nil { + t.Fatal("starting with no engine command succeeded") + } + if state, _, _ := s.Status(); state != StateIdle { + t.Errorf("state = %s, want idle", state) + } + // And a wait on a supervisor that never started is already over. + if err := s.Wait(); err != nil { + t.Errorf("Wait = %v, want nil, on a supervisor that never started", err) + } +} + +func TestStartRefusesAnUnreachableLogPath(t *testing.T) { + dir := t.TempDir() + + // A file where the log's directory must be: the directory cannot be + // made, and the start must fail saying nothing ran. + blocker := filepath.Join(dir, "in the way") + if err := os.WriteFile(blocker, nil, 0o600); err != nil { + t.Fatal(err) + } + s := NewSupervisor(filepath.Join(blocker, "engine.log")) + if err := s.Start([]string{"/bin/sh"}); err == nil { + t.Fatal("starting with an unreachable log directory succeeded") + } + if state, _, _ := s.Status(); state != StateIdle { + t.Errorf("state = %s, want idle", state) + } + + // A directory where the log's file must be: the file cannot be opened. + logDir := filepath.Join(dir, "engine.log") + if err := os.Mkdir(logDir, 0o700); err != nil { + t.Fatal(err) + } + s = NewSupervisor(logDir) + if err := s.Start([]string{"/bin/sh"}); err == nil { + t.Fatal("starting with a directory for the log succeeded") + } + if state, _, _ := s.Status(); state != StateIdle { + t.Errorf("state = %s, want idle", state) + } +} + func TestSupervisorStopEscalatesToKill(t *testing.T) { s := NewSupervisor(filepath.Join(t.TempDir(), "engine.log")) s.Grace = 100 * time.Millisecond diff --git a/internal/daemon/pty_unix.go b/internal/daemon/pty_unix.go new file mode 100644 index 00000000..abc81dfd --- /dev/null +++ b/internal/daemon/pty_unix.go @@ -0,0 +1,36 @@ +//go:build !windows + +package daemon + +import ( + "os" + + "github.com/creack/pty" +) + +// ptyWindow is the window a captured engine's pseudo-terminal reports. Wide +// enough that an engine sizes its terminal output for an ordinary screen — a +// download bar among them — and narrow enough that the recorded lines stay +// compact in the view's pane and for the log's other readers. +var ptyWindow = &pty.Winsize{Rows: 50, Cols: 80} + +// attachPTY opens a pseudo-terminal for a captured engine's stdout: the +// master is what the supervisor reads, the slave is what the engine's stdout +// holds. An error means no pseudo-terminal could be opened — the unsupported +// platform among them — and the capture falls back to the log file. It is a +// variable so a test can stand in for the opening and exercise that +// fallback. +var attachPTY = openPTY + +func openPTY() (master, slave *os.File, err error) { + master, slave, err = pty.Open() + if err != nil { + return nil, nil, err + } + if err := pty.Setsize(master, ptyWindow); err != nil { + master.Close() + slave.Close() + return nil, nil, err + } + return master, slave, nil +} diff --git a/internal/daemon/pty_windows.go b/internal/daemon/pty_windows.go new file mode 100644 index 00000000..bc7e8032 --- /dev/null +++ b/internal/daemon/pty_windows.go @@ -0,0 +1,14 @@ +//go:build windows + +package daemon + +import ( + "errors" + "os" +) + +// attachPTY has no pseudo-terminal on Windows: the capture falls back to the +// log file, no worse than it did before the pseudo-terminal existed. +var attachPTY = func() (*os.File, *os.File, error) { + return nil, nil, errors.New("no pseudo-terminal on this platform") +} diff --git a/internal/daemon/ptylog.go b/internal/daemon/ptylog.go new file mode 100644 index 00000000..d0efbfdd --- /dev/null +++ b/internal/daemon/ptylog.go @@ -0,0 +1,444 @@ +package daemon + +import ( + "io" + "sync" + "time" +) + +// ptyRedrawInterval is the frequency a redrawing line's states are recorded +// at while the redraw goes on. It sits under the serve view's own poll +// cadence, so the pane sees fresh states as they land, and bounds a chatty +// bar — a download makes a thousand updates — to a legible run of lines. +const ptyRedrawInterval = 2 * time.Second + +// ptyLog turns a captured engine's terminal output — the bytes the +// pseudo-terminal's master hands over — into clean lines for the engine log. +// +// It keeps the terminal's lines as a column, the way the screen holds them, +// and a line the engine redraws in place — a download progress bar among +// them — is recorded as its state rather than as a run of raw overwrites. +// The rules: +// +// - The terminal's CRLF line ending becomes the log's LF, and a bare LF +// commits the line the same way. Committing a line records it — a plain +// line as written, a redrawing line as its final state — and moves the +// drawing to the line below; the committed line stays where it is, and +// a cursor move may come back to it. +// - A carriage return that is not a line ending starts a new state of the +// line the engine is drawing: what follows replaces the state, it does +// not append to it. A state is complete when the engine moves on — a +// new state, a newline, an erase, or the end of the stream — never in +// the middle of its bytes, so a state is never recorded half-drawn. +// - A redrawing line is recorded as its state: the first state always, the +// final state always, and a further distinct state at most once per +// ptyRedrawInterval. Identical states are never repeated, and a state +// that is empty is never recorded — a blank line is a drawing, not +// output. +// - Cursor moves do not end a line: up and down move the drawing between +// the column's lines, which is how the engines redraw a bar in place — +// up to its line, the state, the cursor back down to the anchor. A home +// returns the drawing to the top of the column. A move lands the +// drawing on the line it arrives at: the state the line holds stands, +// and whatever the engine writes there next begins a new state of the +// line, not an extension of what it held. +// - Erase sequences shape the state the way they shape the terminal's +// line: a whole-line erase ends the state drawn on it and clears what +// it holds; an erase to the end of the line erases from the cursor, +// which sits at the end of the state, and so changes nothing. +// - A plain line — one the engine never redrew — is recorded as written, +// when its newline or the end of the stream commits it. +// - Every other escape is dropped, and one that is not part of the +// redraw's own unit ends the state drawn before it. No escape reaches +// the log. +type ptyLog struct { + // mu guards the state below: the pump feeds it from its own goroutine + // while the tick's runs its own, and a state the tick records and a + // line the pump commits are the same fields. + mu sync.Mutex + w io.Writer + now func() time.Time + interval time.Duration + + lines []*ptyLine // the screen's lines, top down; the drawing is on lines[row] + row int + + esc int // the escape sequence's state; escNone among plain bytes + csiParam byte // the last parameter of the CSI sequence being read +} + +// ptyLine is one line of the screen the normaliser keeps. +type ptyLine struct { + content []byte // the content of the line as drawn + drawing bool // the line is one the engine is redrawing + pendingCR bool // a carriage return is held, to tell CRLF apart from a redraw + replacing bool // a held carriage return settled as a redraw: the next + // text byte starts a new state, replacing the content the line held + committed bool // the line is recorded and untouched since + + recorded bool // a state of the redraw has been recorded + last []byte // the last recorded state + lastAt time.Time +} + +// The escape sequence's states. +const ( + escNone = iota + escStart // after the escape itself + escCSI // after the intro: the parameter bytes, then a final + escOSC // after the OSC intro: consumed to the BEL or the ST + escOSCST // the ST's escape, waiting on its backslash +) + +// newPTYLog builds the normaliser that writes its lines to w. now is +// injected so the frequency rule's boundary is testable without a clock. +func newPTYLog(w io.Writer, now func() time.Time) *ptyLog { + return &ptyLog{w: w, now: now, interval: ptyRedrawInterval, lines: []*ptyLine{{}}} +} + +// line is the line the drawing is on. +func (p *ptyLog) line() *ptyLine { + return p.lines[p.row] +} + +// extend makes the column hold at least up to the row: the lines between +// are empty, the way the screen's are. +func (p *ptyLog) extend(row int) { + for len(p.lines) <= row { + p.lines = append(p.lines, &ptyLine{}) + } +} + +// Write feeds one read of the pseudo-terminal to the normaliser. It always +// accepts the bytes — the pump must keep draining the terminal whatever the +// log's fate — and reports them all as written. +func (p *ptyLog) Write(b []byte) (int, error) { + p.mu.Lock() + defer p.mu.Unlock() + for _, c := range b { + p.byte(c) + } + return len(b), nil +} + +// byte is the normaliser's one step: the escape sequence's states first, +// then the line's. +func (p *ptyLog) byte(c byte) { + switch p.esc { + case escStart: + switch c { + case '[': + p.esc, p.csiParam = escCSI, 0 + case ']': + p.esc = escOSC + default: + // A two-byte sequence the log has no business in: the + // state drawn before it is done, and both bytes are + // dropped. + p.settleOnEscape() + p.esc = escNone + } + return + case escCSI: + switch { + case c >= 0x30 && c <= 0x3f: // parameter bytes + if c >= 0x30 && c <= 0x39 { + p.csiParam = c + } + case c >= 0x20 && c <= 0x2f: // intermediate bytes + case c >= 0x40 && c <= 0x7e: // the final byte decides what happens + p.csiFinal(c) + p.esc = escNone + default: + p.settleOnEscape() // malformed: the state is done, the bytes dropped + p.esc = escNone + } + return + case escOSC: + switch c { + case 0x07: // the BEL ends the sequence + p.settleOnEscape() + p.esc = escNone + case 0x1b: // the ST's escape + p.esc = escOSCST + } + return + case escOSCST: + // Whether the backslash arrives or not, the sequence is over. + p.settleOnEscape() + p.esc = escNone + return + } + + l := p.line() + switch c { + case 0x1b: + // What the escape does to the line's state is decided when the + // sequence ends. + p.esc = escStart + case '\r': + if l.pendingCR { + // A second carriage return: the first settled as a redraw + // start, and this one holds in its turn. + p.settle(l) + l.pendingCR = false + l.replacing = true + } + l.pendingCR = true + case '\n': + // Whether or not a carriage return held, a newline is a line + // ending: whatever state the line holds stands, and is + // committed with it. + l.pendingCR = false + l.replacing = false + p.commit() + default: + if l.pendingCR { + // A held carriage return that is not a line ending: the + // state drawn before it, if any, is complete, and a new + // state of the line begins. + p.settle(l) + l.pendingCR = false + l.replacing = true + l.drawing = true + } + if l.replacing { + l.content = l.content[:0] + l.replacing = false + } + l.content = append(l.content, c) + l.committed = false + } +} + +// settle is a state boundary on the line: the state drawn before it, if +// any, is complete. It does not touch the content: a redraw's replacement +// is deferred to the text byte that starts the new state — or the erase +// that takes the state away — so a state the engine drew stands when a +// newline ends the line, the way it stands on the screen. +func (p *ptyLog) settle(l *ptyLine) { + if l.drawing { + p.considerState(l) + } +} + +// settleOnEscape settles the line's held carriage return when the escape +// that just finished is not part of the redraw's own unit — the erase and +// the cursor moves are: they end or continue the drawing, and the state +// stands until one of them says otherwise. +func (p *ptyLog) settleOnEscape() { + if l := p.line(); l.pendingCR { + p.settle(l) + l.pendingCR = false + l.replacing = true + } +} + +// csiCount is the parameter of a CSI sequence's count, the way the +// terminal reads it: absent or zero means one. +func (p *ptyLog) csiCount() int { + if p.csiParam >= '1' && p.csiParam <= '9' { + return int(p.csiParam - '0') + } + return 1 +} + +// csiFinal is what a CSI sequence's final byte does to the drawing. +func (p *ptyLog) csiFinal(c byte) { + switch c { + case 'A': // the drawing moves up the column; the line it leaves stands + if n := p.csiCount(); p.row >= n { + p.row -= n + } else { + p.row = 0 + } + p.land() + case 'B': // the drawing moves down + p.row += p.csiCount() + p.extend(p.row) + p.land() + case 'H': // home: the top of the column + p.row = 0 + p.land() + case 'K': + if p.csiParam == '2' { // the whole line is erased: the state drawn is done + l := p.line() + p.settle(l) + l.pendingCR = false + l.replacing = false + l.content = l.content[:0] + } + // An erase to the end erases from the cursor, which sits at the + // end of the state: nothing of the log's to clear, and the state + // is not done for it. + case 'J': // an erase past the line's end clears what it holds + l := p.line() + p.settle(l) + l.pendingCR = false + l.replacing = false + l.content = l.content[:0] + default: + // A colour, a position the log does not model, a mode: the + // state drawn before the escape is done. + p.settleOnEscape() + } +} + +// land is what a cursor move does to the line it arrives at: the state the +// line is drawing stands — recorded if the time has come — and whatever the +// engine writes there next begins a new state of the line. Without the +// replacement, a home or an up onto a committed line would extend the +// content the line already holds. +func (p *ptyLog) land() { + l := p.line() + p.settle(l) + if len(l.content) > 0 { + l.replacing = true + } +} + +// commit ends the current line, as a newline does: a plain line is recorded +// as written — an empty one as a blank line, a bare newline's record — and +// a redrawing line records its final state. The line then stays in place; +// the drawing moves to the line below it. +func (p *ptyLog) commit() { + p.commitLine(p.line(), false) + p.row++ + p.extend(p.row) +} + +// commitLine records one line's content, the way a commit does, and marks +// it so the end of the stream does not record it a second time. A line +// touched again after its commit is recorded again, as the terminal shows +// it: corrected, not duplicated. +func (p *ptyLog) commitLine(l *ptyLine, atEOF bool) { + if l.committed { + return + } + switch { + case l.drawing: + p.recordFinal(l, l.content) + case len(l.content) > 0: + p.writeBytes(l.content) + case !atEOF: + p.writeBytes(l.content) // the blank line + } + l.committed = true +} + +// considerState records the line's current state when the frequency rule +// allows: the first state always, a further distinct state at most once per +// the interval. +func (p *ptyLog) considerState(l *ptyLine) { + if len(l.content) == 0 { + return + } + if l.recorded && string(l.content) == string(l.last) { + return + } + if !l.recorded || p.now().Sub(l.lastAt) >= p.interval { + p.writeBytes(l.content) + l.last = append([]byte(nil), l.content...) + l.lastAt = p.now() + l.recorded = true + } +} + +// tick records a redrawing line's pending state whose time has come, on +// every line of the column: a bar's last state outlives the engine's move +// off its line, and the log owes it the state anyway. The pump runs it at +// the interval's half-rate for the engine's life; the dedup and the +// interval make it a no-op on a line that has nothing pending, which is the +// normal state. +func (p *ptyLog) tick() { + p.mu.Lock() + defer p.mu.Unlock() + for _, l := range p.lines { + if l.drawing { + p.considerState(l) + } + } +} + +// finalize records whatever the stream leaves unfinished: each line of the +// column, top down, a redrawing line its final state — unthrottled, since +// nothing follows it — and a plain line its content. A held carriage return +// moves the cursor, it does not erase, so whatever state is drawn stands. +func (p *ptyLog) finalize() { + p.mu.Lock() + defer p.mu.Unlock() + for _, l := range p.lines { + l.pendingCR = false + p.commitLine(l, true) + } +} + +// recordFinal records the redraw's final state, unthrottled, unless it is +// the state the log already carries for the line. +func (p *ptyLog) recordFinal(l *ptyLine, b []byte) { + if len(b) == 0 { + return + } + if l.recorded && string(b) == string(l.last) { + return + } + p.writeBytes(b) + l.last = append([]byte(nil), b...) + l.lastAt = p.now() + l.recorded = true +} + +// writeBytes appends one line to the log, newline and all. A write that +// fails is swallowed: the log's fate is not the engine's, and the pump must +// keep draining the terminal. +func (p *ptyLog) writeBytes(line []byte) { + buf := append(append([]byte(nil), line...), '\n') + p.w.Write(buf) +} + +// pumpPTYLog reads the pseudo-terminal's master for the engine's life, +// normalising its stream into the log's lines on out. It always drains — +// the frequency rule delays the log's writes, never the read, so the engine +// can never wedge on a full terminal — and it records the final state before +// it closes done. +func pumpPTYLog(master io.Reader, out io.Writer, done chan<- struct{}) { + log := newPTYLog(out, time.Now) + stopping := make(chan struct{}) + go func() { + ticker := time.NewTicker(ptyRedrawInterval / 2) + defer ticker.Stop() + for { + select { + case <-ticker.C: + log.tick() + case <-stopping: + return + } + } + }() + buf := make([]byte, 32<<10) + for { + n, err := master.Read(buf) + if n > 0 { + log.Write(buf[:n]) + } + if err == nil { + continue + } + // The end of the stream: on some platforms the error arrives + // before the last bytes do, so read until it stops coming. + for { + n, err := master.Read(buf) + if n > 0 { + log.Write(buf[:n]) + } + if err != nil { + break + } + } + break + } + log.finalize() + close(stopping) + close(done) +} diff --git a/internal/daemon/ptylog_test.go b/internal/daemon/ptylog_test.go new file mode 100644 index 00000000..1fafc1da --- /dev/null +++ b/internal/daemon/ptylog_test.go @@ -0,0 +1,473 @@ +package daemon + +import ( + "bytes" + "fmt" + "io" + "strings" + "testing" + "time" +) + +// advance moves the shared test clock by hand. +func (c *fakeClock) advance(d time.Duration) { c.set(c.now().Add(d)) } + +// newTestPTYLog builds a normaliser writing to out on the test's clock. +func newTestPTYLog(out *bytes.Buffer, clock *fakeClock) *ptyLog { + return newPTYLog(out, clock.now) +} + +// update is one progress bar redraw, the way the engines draw them: a +// carriage return, the whole line, an erase to the end of it, and the +// carriage return that parks the cursor for the next. +func update(state string) string { + return "\r" + state + "\033[K\r" +} + +// TestPTYLogPlainLines passes a line through as written, CRLF and all: the +// terminal's line ending becomes the log's, and a bare newline commits the +// same way. +func TestPTYLogPlainLines(t *testing.T) { + out := new(bytes.Buffer) + clock := &fakeClock{} + log := newTestPTYLog(out, clock) + log.Write([]byte("booted\r\nsecond line\n")) + log.finalize() + if got := out.String(); got != "booted\nsecond line\n" { + t.Errorf("plain lines = %q", got) + } +} + +// TestPTYLogBareNewlineIsRecorded keeps the engine's own blank lines: a +// newline is a newline in the record. +func TestPTYLogBareNewlineIsRecorded(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("one\n\ntwo\n")) + log.finalize() + if got := out.String(); got != "one\n\ntwo\n" { + t.Errorf("a blank line was dropped: %q", got) + } +} + +// TestPTYLogProgressRun is the download: the engine announces itself with a +// newline, then redraws the bar a thousand times. With no time passing at +// all, the log gets the first state and the final one — and nothing between. +func TestPTYLogProgressRun(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + var b strings.Builder + b.WriteString("\n") // the bar's own announcement line + for i := 0; i <= 100; i++ { + b.WriteString(update(barState(i))) + } + log.Write([]byte(b.String())) + log.finalize() + + want := "\n" + barState(0) + "\n" + barState(100) + "\n" + if got := out.String(); got != want { + t.Errorf("the progress run\n got %q\nwant %q", got, want) + } + if strings.Contains(out.String(), "\033") { + t.Errorf("an escape reached the log: %q", out.String()) + } +} + +// barState is one state of a test's download bar. +func barState(pct int) string { + return "Downloading m.gguf " + strings.Repeat("─", pct/2) + " " + fmt.Sprintf("%3d%%", pct) +} + +// TestPTYLogProgressThrottled gives the bar a life measured in the interval: +// every state a further one apart lands in the log, so the record reads as +// the progression the download made. +func TestPTYLogProgressThrottled(t *testing.T) { + out := new(bytes.Buffer) + clock := &fakeClock{} + log := newTestPTYLog(out, clock) + const n = 5 + for i := 0; i < n; i++ { + if i > 0 { + clock.advance(ptyRedrawInterval + time.Second) + } + log.Write([]byte(update(barState(i * 20)))) + } + log.finalize() + + lines := strings.Split(strings.TrimRight(out.String(), "\n"), "\n") + if len(lines) != n { + t.Fatalf("the throttled run recorded %d lines, want %d:\n%s", len(lines), n, out.String()) + } + for i, line := range lines { + if line != barState(i*20) { + t.Errorf("line %d = %q, want %q", i, line, barState(i*20)) + } + } +} + +// TestPTYLogIdenticalStatesNeverRepeated: a bar that redraws the same state +// records it once, whatever the interval. +func TestPTYLogIdenticalStatesNeverRepeated(t *testing.T) { + out := new(bytes.Buffer) + clock := &fakeClock{} + log := newTestPTYLog(out, clock) + log.Write([]byte(update("Downloading m.gguf 4%"))) + clock.advance(ptyRedrawInterval * 10) + log.Write([]byte(update("Downloading m.gguf 4%"))) + clock.advance(ptyRedrawInterval * 10) + log.Write([]byte(update("Downloading m.gguf 4%"))) + log.finalize() + if got := out.String(); got != "Downloading m.gguf 4%\n" { + t.Errorf("identical states repeated: %q", got) + } +} + +// TestPTYLogEraseShapesTheState: a whole-line erase clears what the state +// holds, the way it clears the terminal's line. +func TestPTYLogEraseShapesTheState(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte(update("abc") + "\033[2K" + update("def") + "\n")) + log.finalize() + if got := out.String(); got != "abc\ndef\n" { + t.Errorf("erase = %q", got) + } +} + +// TestPTYLogErasePastTheLineClearsTheState: an erase of what is past the +// line's end takes the state the line holds away — recorded once it stood — +// and the line's commit has nothing left to record. +func TestPTYLogErasePastTheLineClearsTheState(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte(update("abc") + "\033[J\n")) + log.finalize() + if got := out.String(); got != "abc\n" { + t.Errorf("an erase past the line = %q", got) + } +} + +// barUnit is one redraw of a bar drawn the way the engines draw them: the +// bar sits on the line above an anchor the engine keeps returning to, so +// each redraw is a cursor up, the state and its erase, the cursor back +// down, and the carriage return that parks the anchor. +func barUnit(state string) string { + return "\033[1A" + update(state) + "\033[1B\r" +} + +// TestPTYLogRealEngineBarPattern is the single download's whole life: the +// bar announces itself with a newline, then redraws its line a hundred times +// — most of them the same state, the download creeping. The log gets the +// first state and the final one, and the repetition does not repeat. +func TestPTYLogRealEngineBarPattern(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + var b strings.Builder + b.WriteString("\n") // the bar's own announcement line + for i := 0; i < 5; i++ { + b.WriteString(barUnit(barState(0))) + } + b.WriteString(barUnit(barState(100))) + log.Write([]byte(b.String())) + log.finalize() + + want := "\n" + barState(0) + "\n" + barState(100) + "\n" + if got := out.String(); got != want { + t.Errorf("the progress run\n got %q\nwant %q", got, want) + } + if strings.Contains(out.String(), "\033") { + t.Errorf("an escape reached the log: %q", out.String()) + } +} + +// TestPTYLogInterleavedBars: several downloads drawn at once keep their +// states apart — each bar on its own line of the column, each recording its +// own first and final state, the anchor's line among them a blank one. +func TestPTYLogInterleavedBars(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + stream := "\n" + + barUnit("bar1 10%") + + barUnit("bar1 20%") + + "\n" + + barUnit("bar2 5%") + log.Write([]byte(stream)) + log.finalize() + want := "\nbar1 10%\n\nbar1 20%\nbar2 5%\n" + if got := out.String(); got != want { + t.Errorf("interleaved bars = %q, want %q", got, want) + } +} + +// TestPTYLogCursorHomeStartsANewState: an engine that returns home and writes +// without a carriage return — the terminal's rewrite, not an append — gets +// its line replaced, and the lines the drawing left stand as committed. +func TestPTYLogCursorHomeStartsANewState(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("one\ntwo\n\033[H ONE\n")) + log.finalize() + if got := out.String(); got != "one\ntwo\n ONE\n" { + t.Errorf("home onto a committed line = %q", got) + } +} + +// TestPTYLogCursorUpStartsANewState: an uncounted up — the parameter the +// terminal reads as one — lands the drawing on the line above, where the +// same replacement holds. +func TestPTYLogCursorUpStartsANewState(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("one\ntwo\033[A ONE\n")) + log.finalize() + if got := out.String(); got != "one\n ONE\ntwo\n" { + t.Errorf("an uncounted up = %q", got) + } +} + +// TestPTYLogCursorUpClampsAtTheTop: an up past the top of the column lands +// on the top line, which the replacement reaches the same way. +func TestPTYLogCursorUpClampsAtTheTop(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("one\ntwo\033[2A ONE\n")) + log.finalize() + if got := out.String(); got != "one\n ONE\ntwo\n" { + t.Errorf("an up past the top = %q", got) + } +} + +// TestPTYLogPendingStateLandsOnTheTick: a state the stream leaves pending — +// the download's last, after which the engine goes quiet on stdout — is not +// left out of the log for the engine's remaining life: the tick records it +// once its time has come, and not before. +func TestPTYLogPendingStateLandsOnTheTick(t *testing.T) { + out := new(bytes.Buffer) + clock := &fakeClock{} + log := newTestPTYLog(out, clock) + log.Write([]byte(update("Downloading m.gguf 1%"))) + log.tick() // the first state: recorded at once + if got := out.String(); got != "Downloading m.gguf 1%\n" { + t.Fatalf("the first state = %q", got) + } + clock.advance(ptyRedrawInterval / 2) + log.Write([]byte(update("Downloading m.gguf 100%"))) + // Under the interval from the last record: the new state waits. + log.tick() + if got := out.String(); got != "Downloading m.gguf 1%\n" { + t.Errorf("the tick recorded before its interval: %q", got) + } + clock.advance(ptyRedrawInterval) + log.tick() + if got := out.String(); got != "Downloading m.gguf 1%\nDownloading m.gguf 100%\n" { + t.Errorf("the tick = %q", got) + } + // And a tick with nothing pending records nothing again. + log.tick() + if got := out.String(); got != "Downloading m.gguf 1%\nDownloading m.gguf 100%\n" { + t.Errorf("a quiet tick repeated the state: %q", got) + } +} + +// TestPTYLogNoEscapeReachesTheLog: a coloured line loses its colour, keeps +// its words. +func TestPTYLogNoEscapeReachesTheLog(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("\033[31merror: it failed\033[0m\n")) + log.finalize() + if got := out.String(); got != "error: it failed\n" { + t.Errorf("colour = %q", got) + } + if strings.Contains(out.String(), "\033") { + t.Errorf("an escape reached the log: %q", out.String()) + } +} + +// TestPTYLogOSCTitleIsDropped: a window title the engine sets — consumed to +// its bell, the whole of it — never reaches the log, and the held carriage +// return it interrupts settles as the redraw's own. +func TestPTYLogOSCTitleIsDropped(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("abc\r\033]0;the title\007def\n")) + log.finalize() + if got := out.String(); got != "def\n" { + t.Errorf("an OSC to its bell = %q", got) + } +} + +// TestPTYLogOSCStopsAtTheStringTerminator: the other way an OSC ends — the +// string terminator, its escape and its backslash — takes the title the same +// way away. +func TestPTYLogOSCStopsAtTheStringTerminator(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("abc\r\033]0;the title\033\\def\n")) + log.finalize() + if got := out.String(); got != "def\n" { + t.Errorf("an OSC to its terminator = %q", got) + } +} + +// TestPTYLogTwoByteSequenceIsDropped: an escape the log has no business in — +// a reset among them — drops its two bytes and lets the line go on as +// written. +func TestPTYLogTwoByteSequenceIsDropped(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("abc\033cdef\n")) + log.finalize() + if got := out.String(); got != "abcdef\n" { + t.Errorf("a two-byte sequence = %q", got) + } +} + +// TestPTYLogCSIWithIntermediateByteIsDropped: a cursor position report among +// the CSI sequences with a byte between its parameters and its final — the +// log has no position to report either, and drops the whole sequence. +func TestPTYLogCSIWithIntermediateByteIsDropped(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("abc\033[ qdef\n")) + log.finalize() + if got := out.String(); got != "abcdef\n" { + t.Errorf("a CSI with an intermediate byte = %q", got) + } +} + +// TestPTYLogMalformedCSIIsDropped: a parameter that never meets its final +// byte ends the sequence malformed — the state drawn before it stands, and +// the bytes are dropped. +func TestPTYLogMalformedCSIIsDropped(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("abc\033[1\000def\n")) + log.finalize() + if got := out.String(); got != "abcdef\n" { + t.Errorf("a malformed CSI = %q", got) + } +} + +// TestPTYLogTrailingCarriageReturnKeepsTheLine: a carriage return at the end +// of a plain line moves the cursor, it does not erase the line. +func TestPTYLogTrailingCarriageReturnKeepsTheLine(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("hello\r")) + log.finalize() + if got := out.String(); got != "hello\n" { + t.Errorf("trailing CR = %q", got) + } +} + +// TestPTYLogTrailingCarriageReturnAfterTheFinalState: the bar's own trailing +// carriage return does not withhold the state it follows. +func TestPTYLogTrailingCarriageReturnAfterTheFinalState(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte(update("Downloading m.gguf 100%"))) + log.finalize() + if got := out.String(); got != "Downloading m.gguf 100%\n" { + t.Errorf("trailing CR after the final state = %q", got) + } +} + +// TestPTYLogUnnewlineledLineAtEndOfStream: output the engine never finished +// with a newline is the record's to keep. +func TestPTYLogUnnewlineledLineAtEndOfStream(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("loading model")) + log.finalize() + if got := out.String(); got != "loading model\n" { + t.Errorf("unnewlineled = %q", got) + } +} + +// TestPTYLogSplitStateRecordsWhole: a state that arrives over several reads +// is recorded once, at the end, never half-drawn in the middle. +func TestPTYLogSplitStateRecordsWhole(t *testing.T) { + out := new(bytes.Buffer) + log := newTestPTYLog(out, &fakeClock{}) + log.Write([]byte("\rHalf")) + log.Write([]byte("Done")) + log.Write([]byte("\n")) + log.finalize() + if got := out.String(); got != "HalfDone\n" { + t.Errorf("split state = %q", got) + } +} + +// TestPTYLogPumpDrainsAndFinalises runs the pump over a finished stream: the +// log gets the plain line and the bar's states, the final one among them, and +// done closes. +func TestPTYLogPumpDrainsAndFinalises(t *testing.T) { + stream := "booted\r\n" + update("bar 1%") + update("bar 2%") + out := new(bytes.Buffer) + done := make(chan struct{}) + pumpPTYLog(strings.NewReader(stream), out, done) + <-done + want := "booted\nbar 1%\nbar 2%\n" + if got := out.String(); got != want { + t.Errorf("the pump = %q, want %q", got, want) + } +} + +// scriptedRead is one read the pump's stream hands over. +type scriptedRead struct { + data []byte + err error +} + +// scriptedReader returns its reads in order, and the end of the stream — the +// end of the stream only — once they are spent: the master's own reads can +// end early with data still to come, so the test's reader must keep answering +// after the last scripted one. +type scriptedReader struct { + reads []scriptedRead + i int +} + +func (r *scriptedReader) Read(p []byte) (int, error) { + if r.i < len(r.reads) { + next := r.reads[r.i] + r.i++ + return copy(p, next.data), next.err + } + return 0, io.EOF +} + +// TestPTYLogPumpDrainsAfterAnEndOfStream covers the platform quirk the pump's +// drain loop exists for: on some platforms the end of the stream arrives with +// the last bytes, or before them — either way the pump keeps reading until it +// stops coming, and the log gets what the terminal owed it. +func TestPTYLogPumpDrainsAfterAnEndOfStream(t *testing.T) { + t.Run("the end of the stream rides with the last bytes", func(t *testing.T) { + master := &scriptedReader{reads: []scriptedRead{ + {data: []byte("booted\r\n")}, + {data: []byte("last line"), err: io.EOF}, + }} + out := new(bytes.Buffer) + done := make(chan struct{}) + pumpPTYLog(master, out, done) + <-done + if got := out.String(); got != "booted\nlast line\n" { + t.Errorf("the pump = %q", got) + } + }) + t.Run("the end of the stream arrives before the last bytes", func(t *testing.T) { + master := &scriptedReader{reads: []scriptedRead{ + {err: io.EOF}, + {data: []byte("late line\r\n")}, + {data: []byte("latest line"), err: io.EOF}, + }} + out := new(bytes.Buffer) + done := make(chan struct{}) + pumpPTYLog(master, out, done) + <-done + if got := out.String(); got != "late line\nlatest line\n" { + t.Errorf("the pump = %q", got) + } + }) +} diff --git a/internal/daemon/supervisor.go b/internal/daemon/supervisor.go index 1409767c..0573b06d 100644 --- a/internal/daemon/supervisor.go +++ b/internal/daemon/supervisor.go @@ -79,7 +79,12 @@ func (s *Supervisor) Start(argv []string) error { } cmd := exec.Command(argv[0], argv[1:]...) - var logFile *os.File + var ( + logFile *os.File + ptyMaster *os.File + ptySlave *os.File + ptyDone chan struct{} + ) if s.LogPath == "" { cmd.Stdout = os.Stdout cmd.Stderr = os.Stderr @@ -92,16 +97,48 @@ func (s *Supervisor) Start(argv []string) error { return err } logFile = f - cmd.Stdout = f cmd.Stderr = f + // The output is being written to a file, so the engine is told not + // to colour it: an engine that colours by whether it sees a + // terminal — and colours stderr by whether *stdout* is one, among + // other rules — would otherwise write escapes to the log through + // the stderr path, which the normaliser never sees. + cmd.Env = append(os.Environ(), "NO_COLOR=1") + // The engine's stdout is presented to it as a terminal: an engine + // that gates terminal output — a model download's progress among + // them — produces it, and the pump normalises it into the log's + // lines. Where no pseudo-terminal can be opened, stdout goes to + // the log directly, as before. + if master, slave, perr := attachPTY(); perr == nil { + cmd.Stdout = slave + ptyMaster, ptySlave = master, slave + ptyDone = make(chan struct{}) + go pumpPTYLog(master, f, ptyDone) + } else { + cmd.Stdout = f + s.log().Debug("no pseudo-terminal for the engine's stdout; it goes to the log file directly", + slog.String("error", perr.Error())) + } } setProcAttr(cmd) if err := cmd.Start(); err != nil { + if ptySlave != nil { + ptySlave.Close() + } + if ptyMaster != nil { + ptyMaster.Close() + <-ptyDone + } if logFile != nil { logFile.Close() } return err } + // The parent's copy of the slave is closed now: the engine holds its + // own, and the master's end of stream follows the engine's exit. + if ptySlave != nil { + ptySlave.Close() + } s.cmd = cmd s.argv = argv @@ -123,6 +160,13 @@ func (s *Supervisor) Start(argv []string) error { go func() { err := cmd.Wait() + // The engine is gone: end the pseudo-terminal's read, wait for + // the pump's final record, and only then close the log the pump + // wrote to. + if ptyMaster != nil { + ptyMaster.Close() + <-ptyDone + } if logFile != nil { logFile.Close() } diff --git a/internal/daemon/supervisor_pty_test.go b/internal/daemon/supervisor_pty_test.go new file mode 100644 index 00000000..1c60a4d8 --- /dev/null +++ b/internal/daemon/supervisor_pty_test.go @@ -0,0 +1,180 @@ +//go:build !windows + +package daemon + +import ( + "errors" + "io" + "os" + "path/filepath" + "strings" + "testing" +) + +// TestSupervisorPTYCapture is the end of the chain the unit tests cover in +// pieces: the capture presents the engine's stdout as a terminal, so the +// output an engine gates on a terminal — a model download's progress among +// them — reaches the engine log at all, and the line the engine redraws in +// place is recorded as its state rather than as raw overwrites. +func TestSupervisorPTYCapture(t *testing.T) { + logPath := filepath.Join(t.TempDir(), "engine.log") + s := NewSupervisor(logPath) + // The first line is written only because the engine sees a terminal on + // its stdout; the bar is drawn the way the engines draw them, carriage + // return and all; the last line never redraws. + engine := stubEngine(t, `if [ -t 1 ]; then echo 'a line only a terminal gets'; fi +printf '\rDownloading m.gguf 1%%\r' +printf '\rDownloading m.gguf 100%%\r' +printf '\n' +echo 'a plain line' +echo "no_color=${NO_COLOR:-unset}" +# A coloured line, the way an engine that colours by terminal presence +# would write one to stderr — and only when the engine was not told off. +if [ -z "${NO_COLOR:-}" ]; then printf '\033[31mred\033[0m\n' 1>&2; fi +echo 'a stderr line' 1>&2`) + + if err := s.Start([]string{engine}); err != nil { + t.Fatal(err) + } + // The state flips only after the pump's final record and the log file's + // close, so the log is whole by the time the state says stopped. + waitForState(t, s, StateStopped) + + data, err := os.ReadFile(logPath) + if err != nil { + t.Fatal(err) + } + got := string(data) + for _, want := range []string{ + "a line only a terminal gets\n", + "Downloading m.gguf 1%\n", + "Downloading m.gguf 100%\n", + "a plain line\n", + // The stderr side of the capture goes to the log unaltered, as + // before the pseudo-terminal existed. + "a stderr line\n", + // The engine was told its output is going to a file. + "no_color=1", + } { + if !strings.Contains(got, want) { + t.Errorf("the log is missing %q:\n%s", want, got) + } + } + if strings.Contains(got, "\033") { + t.Errorf("an escape reached the log:\n%q", got) + } + if strings.Contains(got, "\r") { + t.Errorf("a carriage return reached the log:\n%q", got) + } +} + +// TestSupervisorFallsBackWithoutAPTY covers the capture's fallback: where no +// pseudo-terminal can be opened, the engine's stdout goes to the log file as +// written — the carriage returns among them — and the engine is told its +// output is going to a file the same way. The spec's no-pseudo-terminal +// scenario, run with the opening stood in for so the branch is reachable +// whatever platform the test runs on. +func TestSupervisorFallsBackWithoutAPTY(t *testing.T) { + previous := attachPTY + attachPTY = func() (*os.File, *os.File, error) { + return nil, nil, errors.New("no pseudo-terminal on this platform") + } + t.Cleanup(func() { attachPTY = previous }) + + logPath := filepath.Join(t.TempDir(), "engine.log") + s := NewSupervisor(logPath) + engine := stubEngine(t, `if [ -t 1 ]; then echo 'a line only a terminal gets'; fi +printf '\rDownloading m.gguf 1%%\r' +printf '\rDownloading m.gguf 100%%\r' +printf '\n' +echo 'a plain line' +echo "no_color=${NO_COLOR:-unset}"`) + + if err := s.Start([]string{engine}); err != nil { + t.Fatal(err) + } + waitForState(t, s, StateStopped) + + data, err := os.ReadFile(logPath) + if err != nil { + t.Fatal(err) + } + got := string(data) + // The engine never saw a terminal on its stdout: the output it gates on + // one is absent, and the bar's carriage returns stand in the log as + // written — the redraw's own double among them, the normaliser being + // what the fallback has no part in. + if strings.Contains(got, "a line only a terminal gets") { + t.Errorf("the engine saw a terminal it was not given:\n%s", got) + } + if !strings.Contains(got, "\rDownloading m.gguf 1%\r\rDownloading m.gguf 100%\r\n") { + t.Errorf("the fallback altered the engine's stdout:\n%q", got) + } + if !strings.Contains(got, "a plain line\n") { + t.Errorf("the log is missing a plain line:\n%s", got) + } + // The fallback is still the capture: the engine was told its output is + // going to a file. + if !strings.Contains(got, "no_color=1") { + t.Errorf("the fallback changed the engine's environment:\n%s", got) + } + if strings.Contains(got, "\033") { + t.Errorf("an escape reached the log:\n%q", got) + } +} + +// TestSupervisorForwardingIsVerbatim covers the capture's other branch: with +// no log path, the engine's output goes to the supervisor's own stdio +// verbatim — no pseudo-terminal, no normaliser, and no log file — the +// off-the-terminal serve case. +func TestSupervisorForwardingIsVerbatim(t *testing.T) { + // Deterministic whatever the test runner's own environment says: the + // forwarding path must leave the engine's colouring to the engine, and + // an empty NO_COLOR is the "unset" answer for the question below. + t.Setenv("NO_COLOR", "") + oldOut, oldErr := os.Stdout, os.Stderr + defer func() { os.Stdout, os.Stderr = oldOut, oldErr }() + outR, outW, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + errR, errW, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + os.Stdout, os.Stderr = outW, errW + + s := NewSupervisor("") + engine := stubEngine(t, `printf 'raw \r bytes\n' +echo "no_color=${NO_COLOR:-unset}" +echo 'stderr as written' 1>&2`) + if err := s.Start([]string{engine}); err != nil { + t.Fatal(err) + } + waitForState(t, s, StateStopped) + outW.Close() + errW.Close() + out, err := io.ReadAll(outR) + if err != nil { + t.Fatal(err) + } + errOut, err := io.ReadAll(errR) + if err != nil { + t.Fatal(err) + } + + // The carriage return survives: nothing between the engine and the + // supervisor's stdio touched the bytes. + if !strings.Contains(string(out), "raw \r bytes\n") { + t.Errorf("the forwarding path altered the engine's stdout: %q", out) + } + // And the engine's own answer to the colour question is untouched: + // the forwarding path told the engine nothing, because on a terminal + // the engine's colour is wanted. + if !strings.Contains(string(out), "no_color=unset\n") { + t.Errorf("the forwarding path changed the engine's environment: %q", out) + } + if !strings.Contains(string(errOut), "stderr as written\n") { + t.Errorf("the forwarding path altered the engine's stderr: %q", errOut) + } +} diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/.openspec.yaml b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/.openspec.yaml new file mode 100644 index 00000000..abd7c5ae --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-09-25 diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/design.md b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/design.md new file mode 100644 index 00000000..83dd9cd0 --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/design.md @@ -0,0 +1,209 @@ +## Context + +The supervisor (`internal/daemon.Supervisor.Start`) is the one place an +engine's output is captured: it points the engine's stdout and stderr at the +engine log file (daemon, and the serve view), or at its own stdio (a +`serve --api` run off a terminal). The engine log is a record — append-only, +read by `ReadLog` for the control API's `/v1/logs`, the serve view's log +section, the fleet dashboard and `fleet logs` — and `ReadLog` speaks whole +lines plus a byte cursor. + +llama.cpp's download `ProgressBar` (`common/download.cpp`) prints nothing +when `isatty(stdout)` is false, so under the capture a model download is +silent. The server's HTTP model-status API (newer llama.cpp reports +`downloading` on `/v1/models`) cannot be scraped here: in this flow the +download happens in-process before the HTTP listener comes up. + +## Goals / Non-Goals + +**Goals:** + +- A captured engine (daemon; serve under the view) gets its terminal-only + stdout output — the model download's progress among them — into the engine + log. +- The log stays a record of clean lines: no escape sequences, a redrawing + line (a progress bar) recorded as a legible progression with a bounded + line count, first and final state always present. +- Every consumer of the log benefits with no contract change: the serve + view, `/v1/logs`, the fleet dashboard, `fleet logs`. + +**Non-Goals:** + +- No change to off-terminal `serve` (piped runs forward stdio untouched) or + to `serve --api` off a terminal (stdio forwarding) — the engine there has + whatever terminal, if any, the user gave it, exactly as before. +- No live in-place progress bar in the view: the log is a record and the + view tails it. The progression is a series of recorded states, refreshed on + the view's own poll cadence. +- No change to what the daemon runs, how it is driven, or the control API's + contract. + +## Decisions + +### 1. The fix lives in `Supervisor.Start`, on the capture path only + +`Start` already branches on `LogPath`: empty forwards to stdio, set writes to +the file. The pseudo-terminal attach happens in the file branch, so the +daemon and the serve view — the only two captured paths — share one +implementation, and the forwarding paths keep their exact current behaviour. +An engine's TTY-ness is a property of where its output goes, so the rule +follows the capture rather than the command. + +Alternative considered: fixing it in each command (`runServeView`, +`runDaemonCommand`). Rejected — two call sites of the same capture drifting +is exactly how this class of bug appears. + +### 2. Only stdout goes to the pseudo-terminal; stderr keeps its file + +The engine's stderr writes straight to the log file as today. Two reasons: +stderr is the engine's log lines (llama.cpp's `common_log` routes them to +stderr), and — more importantly — a file write blocks the engine only on a +full disk, while a pseudo-terminal blocks a writer that outpaces its reader. +The pump drains continuously, but liveness should not depend on a reader +being fast: stderr keeps the engine's only truly unblocked output path. + +Because the engine's stdout is now a terminal, the engine is told +`NO_COLOR=1` in its environment. An engine that colours by terminal +presence — and colours stderr by whether *stdout* is a terminal, which is +llama.cpp's rule — would otherwise write escapes to the log through the +stderr path, the one the normaliser never sees. A download bar draws no +colour, so nothing is lost; and the forwarding path (no log file) sets +nothing, so a foreground engine on a real terminal keeps its colour. + +### 3. `creack/pty`, build-tagged, with a direct-file fallback + +The pseudo-terminal is a small, well-worn dependency (pure Go over +`x/sys`, no cgo — the release builds run `CGO_ENABLED=0`). It is imported +only from a `//go:build !windows` file, with a Windows file returning +"unavailable": GoReleaser builds Windows, and there the capture falls back +to today's direct file write — the status quo, no worse. A PTY allocation +failure at runtime (a restricted environment) takes the same fallback, so +the engine always starts. + +Alternative considered: raw `x/sys/unix.Openpty` to avoid a new dependency. +Rejected — the dependency buys the edge cases (winsize, fd handoff, the +master-read end-of-stream behaviour per platform) for less code; `x/sys` is +already in the module. + +### 4. The normaliser: a column of lines, and the states of the ones redrawn + +A small state machine turns the pseudo-terminal stream into log lines. It +keeps the terminal's lines as a column, top down, the way the screen holds +them; it is a line model, not a screen emulator: + +- The terminal's CRLF becomes the log's LF; a newline (CRLF or bare) commits + the line the drawing is on — a plain line as written, a redrawing line as + its final state — and moves the drawing to the line below. A committed + line stays in the column: a cursor move may come back to it, and a line + touched after its commit is recorded again, as the terminal shows it. +- A carriage return that is not a line ending starts a **redraw** of the + line the engine is drawing: what follows is a new state of that line, + replacing the state, not appending to it. A state is complete when the + engine moves on — a new state, a newline, an erase, or the end of the + stream — so it is never recorded half-drawn. +- Cursor moves do not end a line: up, down and home move the drawing between + the column's lines. That is how the engines redraw a bar in place — + llama.cpp's `ProgressBar` parks its cursor on an anchor line and, for + every update, moves up to the bar's line, draws the state, and moves back + down — + so a bar's line is redrawn in place, and a multi-file download's several + bars sit on separate lines, each recording its own states. A move lands + the drawing on the line it arrives at: whatever the engine writes there + next begins a new state of the line — the terminal's rewrite, not an + append — so a home or an up onto a committed line corrects the line + rather than extending its content. Committing on a cursor move was the + first design, and the first real engine run showed why it is wrong: the + engine's up-down dance is part of each redraw, so a commit per move + records every state as a "final" one and resets the + dedup — the whole download, state for state, in the log. +- Erase sequences shape the state the way they shape the terminal's line: a + whole-line erase (2K, J) ends the state drawn on the line and clears what + it holds; an erase to the end of the line (a bare K) erases from the + cursor, which sits at the end of the state, and changes nothing. +- A redrawing line is recorded as its state under a frequency rule: the + first state is always recorded, the final state always, and a further + distinct state at most once per fixed interval (2 s). Identical states are + never repeated. A 2-second interval bounds a chatty bar — 1,000 updates a + download makes — to a legible run of lines, and sits under the view's own + 3 s poll so the pane sees fresh states as they land. +- Because a final state can arrive and then no byte ever follow (the + download finishes and the engine goes quiet on stdout while it loads, the + cursor on its anchor), the tick at the interval's half-rate records a + pending state whose time has come on every line of the column; dedup makes + the tick a no-op once nothing is pending. End of stream commits the whole + column, each line's final state unthrottled. +- Every other escape sequence is dropped, and one that is not part of the + redraw's own unit — the erase and the cursor moves — ends the state drawn + before it. No escape ever reaches the log. + +The rule is engine-agnostic — it reads line states, never their content — so +it serves whatever bar an engine draws, now or later. + +### 5. The pump owns the drain and the shutdown order + +A goroutine reads the pseudo-terminal's master, feeds the normaliser, and +writes the normaliser's lines to the log file. It always drains — the +throttle delays log *writes*, never reads — so the engine can never wedge on +a full terminal buffer. On exit the ordering in `Start`'s wait goroutine is: +wait for the engine, close the master (which ends the read, draining any +bytes that ride with the end-of-stream error), wait for the pump to finish +its final record, and only then close the log file. The file is closed after +the pump's last write, never under it. + +The pseudo-terminal opens at a fixed 80×50 window: wide enough that an +engine sizes its output for a normal terminal, narrow enough that recorded +lines stay compact for the pane and for log consumers. + +### 6. Tests: a fake clock and a fake engine + +- The normaliser is a plain function over a byte stream with an injected + clock: unit tests feed it captured-terminal bytes — a progress run, the + bar the engines actually draw (the cursor up-down around the anchor), + interleaved bars, a cursor move onto a committed line, the escape + sequences the engines may send, an erase, CRLF, a pending final state at + end of stream — + and assert the exact recorded lines and the frequency rule's boundaries. + The pump's end-of-stream drain is tested with the error arriving with, + and before, the last bytes. +- The supervisor test uses a shell one-liner as the engine: it prints a plain + line, prints a line only when `[ -t 1 ]` holds, and redraws a progress + line with raw `\r` bytes. The assertions read the log file: the TTY-gated + line is present (the pseudo-terminal worked), the redraws recorded as + states without escapes, the plain line untouched, and the engine carried + `NO_COLOR` (the forwarding test asserts the opposite: the engine it + forwards was told nothing). +- With the pseudo-terminal's opening stood in for with a failure, the + fallback test asserts the spec's no-pseudo-terminal scenario: the + engine's stdout in the log as written, and the engine told its output is + going to a file the same way. + +## Risks / Trade-offs + +- [The platform or environment refuses a pseudo-terminal] → the direct-file + fallback is the pre-change behaviour; the engine runs and is supervised + exactly as before, and the failure is recorded at debug level. +- [An engine misbehaves on a terminal it was not asked to be one] → the + engine's stdin stays `/dev/null` as today, so nothing it reads from stdin + gets a surprise; its window is a fixed 80×50. +- [A download with many bars (a split model) records interleaved states] → + each recorded line is a self-contained statement ("file, position, + percent"), so the interleaving reads as a log rather than a broken bar. +- [The very last bytes of the final state could be lost where the platform + signals end of stream abruptly (Linux's EIO)] → the read loop drains the + bytes that arrive with the error before stopping, and the throttled + records mean the final state is almost always already in the log by then. +- [The log gains lines it did not have before] → bounded by the frequency + rule (a long download adds a couple of hundred lines, each legible), and + the remote instance's size-based rotation already bounds the file. + +## Migration Plan + +No data or protocol migration: the engine log's path, format contract and +every consumer are unchanged; the file gains clean progress lines and no +escape sequences. Rollback is reverting the change — capture returns to the +direct file write. + +## Open Questions + +None — the platform fallback's exact wording in the debug record and the +winsize value are implementation details the spec does not pin. diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/proposal.md b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/proposal.md new file mode 100644 index 00000000..bd632be8 --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/proposal.md @@ -0,0 +1,57 @@ +## Why + +When an engine's output is captured to the engine log file — `spinloop daemon` +always, `spinloop serve` on a terminal — the engine's stdout is a file, not a +terminal. Engines that gate their terminal-only output on stdout being a +terminal therefore produce none of it: most notably llama.cpp prints its model +download progress bar only when `isatty(stdout)` holds, so a `spinloop serve` +run that fetches a model shows the server coming up and then silence while +several gigabytes are fetched. The model is downloading, but the user has no +way to know. The engine's HTTP API cannot fill the gap either, because the +download happens before the server starts listening. + +## What Changes + +- When the engine's output is captured to the engine log file, the engine's + stdout is connected to a pseudo-terminal instead of the log file, so an + engine that gates terminal output on a terminal — a download progress bar + among them — produces it. +- The captured terminal output is normalised into log lines: terminal escapes + and in-place line editing never reach the log file, and a line the engine + redraws in place (a progress bar) is recorded as its state — the first + state, the final state, and each further distinct state at most once per + fixed interval — so a long download leaves a legible progression rather than + thousands of duplicate lines or a bar frozen at its first frame. +- The engine's stderr keeps going to the log file directly, exactly as before. +- Where a pseudo-terminal cannot be allocated (no platform support), capture + falls back to today's direct file write — no worse than the status quo. +- Off the terminal, nothing changes: a `spinloop serve` run whose stdout is + not a terminal still forwards the engine's stdio untouched, and `serve --api` + off a terminal still forwards as it does. + +## Capabilities + +### New Capabilities + +(none — the capture behaviour already has homes in two existing capabilities) + +### Modified Capabilities + +- `serve-daemon`: the "Engine log capture" requirement — the engine's stdout is + presented to the engine as a pseudo-terminal and the captured output is + normalised to clean log lines, redrawing lines recorded as their state. +- `local-serving`: the "Engine output capture under the serve view" requirement + — the same capture rule for the serve view's engine log, so the view's log + section shows a download's progress while it runs. + +## Impact + +- `internal/daemon` — the supervisor gains the pseudo-terminal attach for a + captured engine's stdout and the normaliser that turns the terminal stream + into log lines; both sit beside the existing capture in `Start`. +- New dependency: a pseudo-terminal package (Unix only), imported from a + build-tagged file so the Windows build compiles and runs on the fallback. +- Engine log files gain progress lines and carry no escape sequences; every + consumer of the log (the serve view, the control API's `/v1/logs`, the fleet + dashboard and `fleet logs`) sees the normalised lines with no contract + change. diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/local-serving/spec.md b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/local-serving/spec.md new file mode 100644 index 00000000..9b1fd01d --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/local-serving/spec.md @@ -0,0 +1,47 @@ +## MODIFIED Requirements + +### Requirement: Engine output capture under the serve view + +When serve runs the view, the engine's stdout and stderr SHALL be captured to +the daemon's state-dir engine log — the same file `spinloop daemon` writes — +rather than forwarded to serve's stdio. The capture SHALL hold the engine's +whole output from its first line, so the log the view tails is complete, and +the log's path SHALL be the one the control API's status reports. With +`--api`, the API's log endpoint SHALL serve the captured file rather than +reporting the log missing. + +The engine's stdout SHALL be presented to the engine as a pseudo-terminal, +and the captured terminal output SHALL be normalised into log lines the same +way the daemon's engine log capture does: terminal escape sequences SHALL NOT +reach the log file, a line the engine redraws in place — a download progress +bar among them — SHALL be recorded as its state, the first and final state +always and any further distinct state at most once per fixed interval, and +the engine's stderr SHALL be written to the log file directly. A model +download's progress SHALL therefore appear in the view's log section while +the download runs, rather than the log showing the engine come up and then +silence. + +#### Scenario: The engine's output lands in the log + +- **WHEN** the engine writes to stdout or stderr while the view is open +- **THEN** the output is appended to the engine log file named in the + daemon's status, and appears in the view's log section + +#### Scenario: A model download's progress is shown + +- **WHEN** the engine downloads a model while the view is open, printing its + progress to stdout only because stdout is a terminal +- **THEN** the view's log section shows the download's progress as it runs, + not silence + +#### Scenario: serve --api's log endpoint serves the capture + +- **WHEN** `spinloop serve --api` runs under the view and a client asks its + log endpoint for the engine log +- **THEN** the reply carries the engine's output, not the missing-log answer + +#### Scenario: Off the terminal nothing is captured + +- **WHEN** `spinloop serve` runs with its output not on a terminal +- **THEN** the engine's output is forwarded to serve's stdio and the run + writes no engine log file diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/serve-daemon/spec.md b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/serve-daemon/spec.md new file mode 100644 index 00000000..9e937835 --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/specs/serve-daemon/spec.md @@ -0,0 +1,53 @@ +## MODIFIED Requirements + +### Requirement: Engine log capture + +The daemon SHALL write the supervised engine's stdout and stderr to a log +file rather than the daemon's own stdio, and SHALL report the log file's path +in its status so the user can find it. + +The engine's stdout SHALL be presented to the engine as a pseudo-terminal +rather than the log file itself: an engine that gates terminal-only output on +stdout being a terminal — a model download's progress among them — SHALL +produce that output while supervised. The captured terminal output SHALL be +normalised into log lines: terminal escape sequences SHALL NOT reach the log +file, and a line the engine redraws in place — a download progress bar among +them — SHALL be recorded as its state, the first state and the final state +always and any further distinct state at most once per fixed interval, so a +long download leaves a legible progression rather than an unbounded run of +duplicates. The engine's stderr SHALL be written to the log file directly, +as before the pseudo-terminal existed. Where a pseudo-terminal cannot be +allocated, the engine's stdout SHALL be written to the log file directly +instead, no worse than the capture did before. + +#### Scenario: Engine output lands in the log file + +- **WHEN** a supervised engine writes to stdout or stderr +- **THEN** the output is appended to the engine log file named in the daemon's + status + +#### Scenario: Terminal-only output is captured + +- **WHEN** a supervised engine writes to stdout only when stdout is a + terminal, as a model download's progress does +- **THEN** that output appears in the engine log file + +#### Scenario: A redrawing line is recorded as its state + +- **WHEN** the engine redraws a line in place, as a download progress bar + does +- **THEN** the log carries the line's first state, its final state, and each + further distinct state at most once per the fixed interval, with no + terminal escape sequences in any of the recorded states + +#### Scenario: stderr is captured directly + +- **WHEN** a supervised engine writes to stderr +- **THEN** the output is appended to the engine log file unaltered, as before + the pseudo-terminal existed + +#### Scenario: No pseudo-terminal available + +- **WHEN** the platform cannot allocate a pseudo-terminal for the engine +- **THEN** the engine's stdout is written to the log file directly, and the + engine runs and is supervised exactly as before diff --git a/openspec/changes/archive/2026-09-25-engine-pty-log-capture/tasks.md b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/tasks.md new file mode 100644 index 00000000..1f22f559 --- /dev/null +++ b/openspec/changes/archive/2026-09-25-engine-pty-log-capture/tasks.md @@ -0,0 +1,28 @@ +## 1. Pseudo-terminal attach + +- [x] 1.1 Add the `creack/pty` dependency (go.mod/go.sum) +- [x] 1.2 `internal/daemon/pty_unix.go` (`//go:build !windows`): open a pseudo-terminal at the fixed window size for a captured engine's stdout, returning the master to read and the close/handoff the supervisor needs +- [x] 1.3 `internal/daemon/pty_windows.go` (`//go:build windows`): report a pseudo-terminal as unavailable so the supervisor falls back +- [x] 1.4 Wire the attach into `Supervisor.Start`'s capture branch: stdout to the pseudo-terminal, stderr to the log file as today, direct file write for stdout where the attach is unavailable, with a debug record when the fallback is taken + +## 2. The normaliser + +- [x] 2.1 `internal/daemon`: the line-state normaliser over the pseudo-terminal stream — CRLF to LF, plain lines committed on newline, `\r` redraws, erase and cursor-move handling, all other escapes dropped +- [x] 2.2 The frequency rule: first and final state of a redrawing line always recorded, a further distinct state at most once per the fixed interval, identical states never repeated, an injected clock +- [x] 2.3 The pending-state tick (records a final state after the stream goes quiet) and the end-of-stream final record + +## 3. The pump and shutdown + +- [x] 3.1 The pump goroutine: read the master, feed the normaliser, write its lines to the log file, always draining; end-of-stream handling per platform including draining bytes that ride with the error +- [x] 3.2 Shutdown order in `Start`'s wait goroutine: wait for the engine, end the pump's read, wait for the pump's final record, then close the log file +- [x] 3.3 Verify the forwarding path (empty `LogPath`) is byte-for-byte unchanged + +## 4. Tests + +- [x] 4.1 Normaliser unit tests: a progress run, an erase, a cursor move, CRLF, a pending final state at end of stream, and the frequency rule's boundaries, against exact recorded output +- [x] 4.2 Supervisor test with a shell-script engine: a TTY-gated line (`[ -t 1 ]`) appears in the log, a `\r`-redrawn line records as states without escapes, a plain line is untouched +- [x] 4.3 Full suite green with `-race -cover`, coverage at or above the 80% bar + +## 5. Docs + +- [x] 5.1 Maintainer internals: why the capture presents stdout as a pseudo-terminal and how the normaliser records redrawing lines, so the next reader does not "simplify" the fallback away diff --git a/openspec/specs/local-serving/spec.md b/openspec/specs/local-serving/spec.md index f4d16c7b..44247cb2 100644 --- a/openspec/specs/local-serving/spec.md +++ b/openspec/specs/local-serving/spec.md @@ -517,12 +517,30 @@ the log's path SHALL be the one the control API's status reports. With `--api`, the API's log endpoint SHALL serve the captured file rather than reporting the log missing. +The engine's stdout SHALL be presented to the engine as a pseudo-terminal, +and the captured terminal output SHALL be normalised into log lines the same +way the daemon's engine log capture does: terminal escape sequences SHALL NOT +reach the log file, a line the engine redraws in place — a download progress +bar among them — SHALL be recorded as its state, the first and final state +always and any further distinct state at most once per fixed interval, and +the engine's stderr SHALL be written to the log file directly. A model +download's progress SHALL therefore appear in the view's log section while +the download runs, rather than the log showing the engine come up and then +silence. + #### Scenario: The engine's output lands in the log - **WHEN** the engine writes to stdout or stderr while the view is open - **THEN** the output is appended to the engine log file named in the daemon's status, and appears in the view's log section +#### Scenario: A model download's progress is shown + +- **WHEN** the engine downloads a model while the view is open, printing its + progress to stdout only because stdout is a terminal +- **THEN** the view's log section shows the download's progress as it runs, + not silence + #### Scenario: serve --api's log endpoint serves the capture - **WHEN** `spinloop serve --api` runs under the view and a client asks its diff --git a/openspec/specs/serve-daemon/spec.md b/openspec/specs/serve-daemon/spec.md index 0a2bad30..54b7e0d8 100644 --- a/openspec/specs/serve-daemon/spec.md +++ b/openspec/specs/serve-daemon/spec.md @@ -99,12 +99,52 @@ The daemon SHALL write the supervised engine's stdout and stderr to a log file rather than the daemon's own stdio, and SHALL report the log file's path in its status so the user can find it. +The engine's stdout SHALL be presented to the engine as a pseudo-terminal +rather than the log file itself: an engine that gates terminal-only output on +stdout being a terminal — a model download's progress among them — SHALL +produce that output while supervised. The captured terminal output SHALL be +normalised into log lines: terminal escape sequences SHALL NOT reach the log +file, and a line the engine redraws in place — a download progress bar among +them — SHALL be recorded as its state, the first state and the final state +always and any further distinct state at most once per fixed interval, so a +long download leaves a legible progression rather than an unbounded run of +duplicates. The engine's stderr SHALL be written to the log file directly, +as before the pseudo-terminal existed. Where a pseudo-terminal cannot be +allocated, the engine's stdout SHALL be written to the log file directly +instead, no worse than the capture did before. + #### Scenario: Engine output lands in the log file - **WHEN** a supervised engine writes to stdout or stderr - **THEN** the output is appended to the engine log file named in the daemon's status +#### Scenario: Terminal-only output is captured + +- **WHEN** a supervised engine writes to stdout only when stdout is a + terminal, as a model download's progress does +- **THEN** that output appears in the engine log file + +#### Scenario: A redrawing line is recorded as its state + +- **WHEN** the engine redraws a line in place, as a download progress bar + does +- **THEN** the log carries the line's first state, its final state, and each + further distinct state at most once per the fixed interval, with no + terminal escape sequences in any of the recorded states + +#### Scenario: stderr is captured directly + +- **WHEN** a supervised engine writes to stderr +- **THEN** the output is appended to the engine log file unaltered, as before + the pseudo-terminal existed + +#### Scenario: No pseudo-terminal available + +- **WHEN** the platform cannot allocate a pseudo-terminal for the engine +- **THEN** the engine's stdout is written to the log file directly, and the + engine runs and is supervised exactly as before + ### Requirement: What the daemon runs When starting an engine, the daemon SHALL determine what to serve in this