diff --git a/docs/maintainer/internals.md b/docs/maintainer/internals.md index c244f9a5..982722bf 100644 --- a/docs/maintainer/internals.md +++ b/docs/maintainer/internals.md @@ -43,7 +43,7 @@ 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. +**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. The master is not closed when the engine exits: closing it discards bytes the engine wrote just before exiting that the pump has not read yet (on Linux the read returns `EIO` once every slave fd is closed, and an early close loses the tail — the cause of the `TestSupervisorPTYCapture` flake on CI). The supervisor waits for the pump to reach end of stream, and closes the master itself only after `ptyDrainTimeout`, which covers a child of the engine that keeps the slave open. **Calling `prog.Send` from inside `Update` deadlocks the program.** The event loop reads its own channel on the goroutine that calls `Update`, so a command that hands a message back through `prog.Send` while `Update` is on the stack waits for a reader that is waiting for it. The board hung on exactly this: pressing Enter on the form's last field, or `a`/`x` on a card, and the whole TUI went still — no spinner, no keystrokes, Ctrl-C ignored. Every message from work that starts inside `Update` must *return* through the loop instead: `tea.Batch(workCmd, spinCmd)` delivers each command's messages normally, and a repaint chain re-arms through its own returned `tea.Tick`. The tests guard this by landing commands through the real program loop, not by calling `Update` and discarding the command. ## Dashboard (`fleet_dashboard.go` and friends) diff --git a/internal/daemon/supervisor.go b/internal/daemon/supervisor.go index 0573b06d..18462d26 100644 --- a/internal/daemon/supervisor.go +++ b/internal/daemon/supervisor.go @@ -33,6 +33,11 @@ const ( // DefaultGrace is how long Stop waits after the polite signal before killing. const DefaultGrace = 10 * time.Second +// ptyDrainTimeout is how long, after the engine exits, the capture waits for +// the pseudo-terminal to report end of stream before closing it. It is a +// variable so a test can shorten it. +var ptyDrainTimeout = 2 * time.Second + // Supervisor runs at most one engine process: started detached into its own // process group, its output captured, its exit recorded rather than acted on. type Supervisor struct { @@ -160,12 +165,21 @@ 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. + // The engine is gone. The pump is left to read the master until it + // reports end of stream, so output the engine wrote just before + // exiting is not discarded by closing the master early. If the + // stream has not ended within ptyDrainTimeout — a child of the + // engine can hold the slave open — the master is closed to end the + // read. The log the pump wrote to is closed only after its final + // record. if ptyMaster != nil { + select { + case <-ptyDone: + case <-time.After(ptyDrainTimeout): + ptyMaster.Close() + <-ptyDone + } ptyMaster.Close() - <-ptyDone } if logFile != nil { logFile.Close() diff --git a/internal/daemon/supervisor_pty_test.go b/internal/daemon/supervisor_pty_test.go index 1c60a4d8..bad02c92 100644 --- a/internal/daemon/supervisor_pty_test.go +++ b/internal/daemon/supervisor_pty_test.go @@ -9,6 +9,7 @@ import ( "path/filepath" "strings" "testing" + "time" ) // TestSupervisorPTYCapture is the end of the chain the unit tests cover in @@ -68,6 +69,35 @@ echo 'a stderr line' 1>&2`) } } +// TestSupervisorPTYCaptureEndsWithALingeringChild covers the bound on the +// drain after the engine exits: a child that outlives the engine keeps the +// slave open, so the master never reports end of stream, and the capture +// closes it once ptyDrainTimeout has passed. The output written before the +// exit is still in the log. +func TestSupervisorPTYCaptureEndsWithALingeringChild(t *testing.T) { + previous := ptyDrainTimeout + ptyDrainTimeout = 200 * time.Millisecond + t.Cleanup(func() { ptyDrainTimeout = previous }) + + logPath := filepath.Join(t.TempDir(), "engine.log") + s := NewSupervisor(logPath) + engine := stubEngine(t, `echo 'before the exit' +sleep 3 & +exit 0`) + 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) + } + if !strings.Contains(string(data), "before the exit\n") { + t.Errorf("the log is missing the output written before the exit:\n%s", data) + } +} + // 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