phraser: forward llama-server's output to mavend's log (V-499)

mavend scraped the child's stderr for the listen line and threw every other line away, and never piped its stdout at all. Nothing about the resident model's memory was diagnosable from a running box: no buffer sizes, no KV-cache layout, no offload lines, no prompt-cache limit. Both streams now share one pipe and every line lands in mavend's log with a `llama:` prefix. The last 12 startup lines are also kept and go into the error when the server dies before it listens, because bare "EOF" never named which allocation it choked on. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-03 23:19:03 +04:00
parent 86817d6d06
commit f229795cea
2 changed files with 165 additions and 43 deletions
@@ -1,6 +1,7 @@
 package phraser

 import (
+	"bufio"
 	"bytes"
 	"context"
 	"encoding/json"
@@ -8,6 +9,7 @@ import (
 	"io"
 	"log"
 	"net/http"
+	"os"
 	"os/exec"
 	"regexp"
 	"strings"
@@ -83,6 +85,19 @@ type Config struct {
 	NCtx       int
 	Timeout    time.Duration

+	// CacheRAMMiB bounds llama-server's prompt cache, which is what actually ate
+	// this box. Measured on homesrv 2026-08-03: the server's own default limit is
+	// 8192 MiB, it stores the full KV state of every idle slot it evicts (112 kiB
+	// per token, so 166 MiB for one 1521-token prompt), and RSS climbed by that
+	// much per distinct prompt until it hit 7.9 GB and half a gigabyte went to
+	// swap. Weights are only 1.1 GB and mmapped, and -ngl 99 costs almost no RSS
+	// because RADV keeps device memory outside the process.
+	//
+	// 0 ⇒ the flag is not passed and the server's own 8 GiB default applies. That
+	// is the escape hatch for a llama-server too old to know --cache-ram, not a
+	// recommendation. See docs/evals/2026-08-03-llama-prompt-cache.md.
+	CacheRAMMiB int
+
 	// ContextBlock renders the shared context block (who he is, how to
 	// address him, the time) fresh for each turn. See internal/persona.
 	// nil ⇒ no block, the prompts stand alone.
@@ -116,6 +131,8 @@ func DefaultConfig(modelPath string) Config {
 		Listen:     "127.0.0.1:0",
 		NGpuLayers: -1,
 		NCtx:       2048,
+		// 512 MiB caps total RSS near 1 GB and still holds several recent prompts.
+		CacheRAMMiB: 512,
 		Timeout:    30 * time.Second,
 	}
 }
@@ -225,8 +242,10 @@ func spawnLlamaServer(ctx context.Context, cfg Config) (backend, error) {
 	return p, nil
 }

-func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) {
-	p := &llamaProc{}
+// llamaArgs is the command line for one resident server. It is a function and
+// not an inline literal because kill-maven.sh's orphan sweep matches against
+// this exact line, and a test pins the two together.
+func llamaArgs(cfg Config) []string {
 	args := []string{
 		"-m", cfg.ModelPath,
 		"--host", "127.0.0.1",
@@ -235,7 +254,15 @@ func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) {
 		"-ngl", fmt.Sprintf("%d", cfg.NGpuLayers),
 		"--no-webui",
 	}
-	cmd := exec.CommandContext(ctx, cfg.BinPath, args...)
+	if cfg.CacheRAMMiB > 0 {
+		args = append(args, "--cache-ram", fmt.Sprintf("%d", cfg.CacheRAMMiB))
+	}
+	return args
+}
+
+func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) {
+	p := &llamaProc{}
+	cmd := exec.CommandContext(ctx, cfg.BinPath, llamaArgs(cfg)...)
 	// Pdeathsig: the kernel SIGKILLs llama-server the moment mavend dies — by
 	// ANY means, including SIGKILL/OOM/panic where our Close() never runs. Without
 	// it a hard-killed mavend orphans its llama-server (reparented to init, keeps
@@ -246,63 +273,104 @@ func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) {
 	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true, Pdeathsig: syscall.SIGKILL}
 	p.cmd = cmd

-	stderr, err := cmd.StderrPipe()
+	// One pipe for both streams. llama.cpp writes its buffer sizes, KV-cache
+	// layout and offload lines to stderr and its request log to stdout, and
+	// stdout used to go nowhere at all — so nothing about the model's memory was
+	// diagnosable from a running box. Both ends land in mavend's log now.
+	pr, pw, err := os.Pipe()
 	if err != nil {
-		return nil, fmt.Errorf("llm: stderr pipe: %w", err)
+		return nil, fmt.Errorf("llm: output pipe: %w", err)
 	}
+	cmd.Stdout = pw
+	cmd.Stderr = pw

 	if err := cmd.Start(); err != nil {
-		stderr.Close()
+		pr.Close()
+		pw.Close()
 		return nil, fmt.Errorf("llm: start: %w", err)
 	}
+	// The child holds the only other reference to the write end. Dropping ours
+	// is what makes the reader see EOF when the child dies.
+	pw.Close()

 	portCh := make(chan string, 1)
 	errCh := make(chan error, 1)
+	tail := &lineTail{}
 	p.wg.Add(1)
 	go func() {
 		defer p.wg.Done()
-		buf := make([]byte, 4096)
-		var leftover []byte
-		for {
-			n, err := stderr.Read(buf)
-			if n > 0 {
-				data := append(leftover, buf[:n]...)
-				lines := bytes.Split(data, []byte("\n"))
-				for _, line := range lines[:len(lines)-1] {
-					if m := listenRE.FindSubmatch(line); len(m) > 1 {
-						addr := string(m[1])
-						portCh <- addr
-						close(portCh)
-					}
+		defer pr.Close()
+		sc := bufio.NewScanner(pr)
+		// llama.cpp prints one prompt per line and a prompt can be long.
+		sc.Buffer(make([]byte, 0, 64*1024), 1024*1024)
+		listening := false
+		for sc.Scan() {
+			line := sc.Bytes()
+			log.Printf("llama: %s", line)
+			if !listening {
+				tail.add(string(line))
+				if m := listenRE.FindSubmatch(line); len(m) > 1 {
+					listening = true
+					portCh <- string(m[1])
+					close(portCh)
 				}
-				leftover = lines[len(lines)-1]
-			}
-			if err != nil {
-				errCh <- err
-				return
 			}
 		}
+		err := sc.Err()
+		if err == nil {
+			err = io.EOF
+		}
+		errCh <- err
 	}()

+	fail := func(err error) (*llamaProc, error) {
+		_ = cmd.Process.Kill()
+		_ = cmd.Wait()
+		return nil, err
+	}
 	select {
 	case addr := <-portCh:
 		p.base = addr
 		return p, nil
 	case err := <-errCh:
-		_ = cmd.Process.Kill()
-		_ = cmd.Wait()
-		return nil, fmt.Errorf("llm: server output: %w", err)
+		// The tail is the whole diagnosis when the server dies during load: bare
+		// "EOF" never said which layer or which allocation it choked on.
+		return fail(fmt.Errorf("llm: server output: %w; last output: %s", err, tail.String()))
 	case <-ctx.Done():
-		_ = cmd.Process.Kill()
-		_ = cmd.Wait()
-		return nil, ctx.Err()
+		return fail(ctx.Err())
 	case <-time.After(60 * time.Second):
-		_ = cmd.Process.Kill()
-		_ = cmd.Wait()
-		return nil, fmt.Errorf("llm: server did not start within 60s")
+		return fail(fmt.Errorf("llm: server did not start within 60s; last output: %s", tail.String()))
 	}
 }

+// lineTail keeps the last few startup lines so a server that dies before it
+// listens can say why in the error, not just "EOF". Written by the reader
+// goroutine and read by whoever gives up on startup, so it takes a lock.
+type lineTail struct {
+	mu    sync.Mutex
+	lines []string
+}
+
+const lineTailMax = 12
+
+func (t *lineTail) add(line string) {
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	t.lines = append(t.lines, line)
+	if len(t.lines) > lineTailMax {
+		t.lines = t.lines[len(t.lines)-lineTailMax:]
+	}
+}
+
+func (t *lineTail) String() string {
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	if len(t.lines) == 0 {
+		return "(no output)"
+	}
+	return strings.Join(t.lines, " | ")
+}
+
 // BaseURL is the llama-server this phraser talks to right now. It changes when
 // the model is swapped, so callers that cache it must register an observer
 // (OnSwap) rather than keeping the string forever.
@@ -1,9 +1,11 @@
 package phraser

 import (
+	"bytes"
 	"context"
 	"errors"
 	"fmt"
+	"log"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -59,6 +61,19 @@ func TestExtractPort(t *testing.T) {
 	}
 }

+// The prompt cache is what ate 6.8GB of the deployed server's RSS, so the cap
+// has to reach the command line, and the opt-out has to leave it off.
+func TestLlamaArgsCapsPromptCache(t *testing.T) {
+	cfg := DefaultConfig("/m.gguf")
+	if got := strings.Join(llamaArgs(cfg), " "); !strings.Contains(got, "--cache-ram 512") {
+		t.Errorf("default args = %q, want --cache-ram 512", got)
+	}
+	cfg.CacheRAMMiB = 0
+	if got := strings.Join(llamaArgs(cfg), " "); strings.Contains(got, "--cache-ram") {
+		t.Errorf("args with the cap off = %q, want no --cache-ram flag", got)
+	}
+}
+
 func TestStartLlamaProcScrapesPortAndReaps(t *testing.T) {
 	bin := fakeLlama(t, listensThenSleeps)
 	ctx, cancel := context.WithCancel(context.Background())
@@ -86,6 +101,48 @@ func TestStartLlamaProcScrapesPortAndReaps(t *testing.T) {
 	}
 }

+// captureLog redirects the standard logger for the duration of a test and
+// returns what was written to it.
+func captureLog(t *testing.T) *bytes.Buffer {
+	t.Helper()
+	var buf bytes.Buffer
+	old := log.Writer()
+	flags := log.Flags()
+	log.SetOutput(&buf)
+	log.SetFlags(0)
+	t.Cleanup(func() { log.SetOutput(old); log.SetFlags(flags) })
+	return &buf
+}
+
+// The child's buffer-size, KV-cache and offload lines are the only way to
+// account for its memory on a running box, and they used to be dropped: stderr
+// was scraped for the listen line and thrown away, stdout was never piped.
+func TestStartLlamaProcForwardsChildOutput(t *testing.T) {
+	buf := captureLog(t)
+	bin := fakeLlama(t, `echo "load_tensors: Vulkan0 model buffer size = 1053.34 MiB" >&2
+echo "llama_context: KV self size = 448.00 MiB"
+`+listensThenSleeps)
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	p, err := startLlamaProc(ctx, testCfg(bin))
+	if err != nil {
+		t.Fatalf("startLlamaProc: %v", err)
+	}
+	p.cancel = cancel
+	defer p.Close()
+
+	got := buf.String()
+	for _, want := range []string{
+		"llama: load_tensors: Vulkan0 model buffer size = 1053.34 MiB", // stderr
+		"llama: llama_context: KV self size = 448.00 MiB",              // stdout, previously discarded
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log missing %q\nlog was:\n%s", want, got)
+		}
+	}
+}
+
 func TestStartLlamaProcFailureArms(t *testing.T) {
 	t.Run("binary missing", func(t *testing.T) {
 		cfg := testCfg(filepath.Join(t.TempDir(), "does-not-exist"))
@@ -96,13 +153,18 @@ func TestStartLlamaProcFailureArms(t *testing.T) {
 	})

 	t.Run("server exits without listening", func(t *testing.T) {
-		// stderr closes, so the reader goroutine reports EOF on errCh.
+		// stderr closes, so the reader goroutine reports EOF on errCh. The error
+		// must carry the child's last words: bare "EOF" named no cause.
+		captureLog(t)
 		bin := fakeLlama(t, `echo "ggml_vulkan: no device" >&2
 exit 1`)
 		_, err := startLlamaProc(context.Background(), testCfg(bin))
 		if err == nil || !strings.Contains(err.Error(), "llm: server output") {
 			t.Fatalf("err = %v, want the server-output arm", err)
 		}
+		if !strings.Contains(err.Error(), "ggml_vulkan: no device") {
+			t.Errorf("err = %v, want the child's last output in it", err)
+		}
 	})

 	t.Run("context cancelled during startup", func(t *testing.T) {
@@ -241,15 +303,7 @@ func TestKillMavenScriptMatchesRealCommandLine(t *testing.T) {
 	// startLlamaProc that breaks the sweep fails here instead of on the box.
 	cfg := DefaultConfig("/opt/maven/models/llm/Qwen3-1.7B-UD-Q4_K_XL.gguf")
 	cfg.NCtx, cfg.NGpuLayers = 4096, 99
-	cmdline := strings.Join([]string{
-		cfg.BinPath,
-		"-m", cfg.ModelPath,
-		"--host", "127.0.0.1",
-		"--port", extractPort(cfg.Listen),
-		"-c", fmt.Sprintf("%d", cfg.NCtx),
-		"-ngl", fmt.Sprintf("%d", cfg.NGpuLayers),
-		"--no-webui",
-	}, " ")
+	cmdline := cfg.BinPath + " " + strings.Join(llamaArgs(cfg), " ")
 	if !pat.MatchString(cmdline) {
 		t.Fatalf("kill-maven.sh pattern %q does not match %q — orphans would leak", m[1], cmdline)
 	}