From 9fd9780168589a6ad1d5e7a16b7136a3bdf9f0c8 Mon Sep 17 00:00:00 2001 From: spinloop-agent Date: Tue, 6 Oct 2026 12:09:56 +0100 Subject: [PATCH] test(daemon): stop reading the stub engine's argv before it is written The stub engine wrote its argv with a shell redirection, which creates and truncates the file before printf writes to it. Tests that waited only for the file to exist could read it empty and fail. The stub now writes to a sibling file and renames it, and the wait helper waits for the text each test goes on to assert on, which also covers the engine log being opened before its first line is written. --- cmd/spinloop/serve_daemon_test.go | 51 ++++++++++++++++---- cmd/spinloop/waitforfile_test.go | 80 +++++++++++++++++++++++++++++++ 2 files changed, 121 insertions(+), 10 deletions(-) create mode 100644 cmd/spinloop/waitforfile_test.go diff --git a/cmd/spinloop/serve_daemon_test.go b/cmd/spinloop/serve_daemon_test.go index 83c9df7e..2e73b121 100644 --- a/cmd/spinloop/serve_daemon_test.go +++ b/cmd/spinloop/serve_daemon_test.go @@ -26,7 +26,12 @@ import ( func stubEngineDaemon(t *testing.T, argsFile string) { t.Helper() script := filepath.Join(t.TempDir(), "llama-server") - body := "#!/bin/sh\nprintf '%s\\n' \"$@\" > " + argsFile + "\ntrap 'exit 0' TERM\nwhile true; do sleep 0.05; done\n" + // The argv is written to a sibling file and renamed into place. A plain + // redirection creates and truncates the file before printf writes to it, so + // a test polling for the file could read it empty; a rename makes it appear + // complete. + body := "#!/bin/sh\nprintf '%s\\n' \"$@\" > " + argsFile + ".tmp && mv " + argsFile + ".tmp " + argsFile + + "\ntrap 'exit 0' TERM\nwhile true; do sleep 0.05; done\n" if err := os.WriteFile(script, []byte(body), 0o755); err != nil { t.Fatal(err) } @@ -91,20 +96,45 @@ func apiDo(t *testing.T, method, url, token, body string) (int, map[string]any) return resp.StatusCode, decoded } -// waitForFile polls until the stub engine has written path. +// waitForFile polls until path holds something and returns its contents. func waitForFile(t *testing.T, path string) string { + t.Helper() + return waitForFileContaining(t, path) +} + +// waitForFileContaining polls until path holds something and every want is in +// it, and returns the contents. A file existing is not the same as its having +// been written: a shell redirection creates and truncates a file before it +// writes, and the daemon opens the engine log before its first line, so a read +// that only waits for the file can land in that gap and see it empty or +// partial. Waiting for the text the caller goes on to assert on removes the +// gap. On timeout it fails with what the file last held. +func waitForFileContaining(t *testing.T, path string, wants ...string) string { t.Helper() deadline := time.Now().Add(10 * time.Second) + last := "" for time.Now().Before(deadline) { if data, err := os.ReadFile(path); err == nil { - return string(data) + last = string(data) + if last != "" && containsAll(last, wants) { + return last + } } time.Sleep(10 * time.Millisecond) } - t.Fatalf("%s never appeared", path) + t.Fatalf("%s never held %q; it last held:\n%s", path, wants, last) return "" } +func containsAll(s string, wants []string) bool { + for _, w := range wants { + if !strings.Contains(s, w) { + return false + } + } + return true +} + // interruptSelf delivers the signal serve's daemon modes shut down on. func interruptSelf(t *testing.T) { t.Helper() @@ -375,7 +405,7 @@ func TestCmdDaemon_LifecycleFromItsAPI(t *testing.T) { } // The engine was started with its metrics endpoint on. - if args := waitForFile(t, argsFile); !strings.Contains(args, "--metrics") { + if args := waitForFileContaining(t, argsFile, "--metrics"); !strings.Contains(args, "--metrics") { t.Errorf("engine argv missing --metrics:\n%s", args) } @@ -447,8 +477,9 @@ func TestCmdDaemon_StartCarriesDeployConfig(t *testing.T) { body["model"] != "org/model" { t.Fatalf("start with body = %d %v", code, body) } - args := waitForFile(t, argsFile) - for _, want := range []string{"org/model:Q4_K_M", "friendly", "16384", "--ngl", "--metrics"} { + wantArgs := []string{"org/model:Q4_K_M", "friendly", "16384", "--ngl", "--metrics"} + args := waitForFileContaining(t, argsFile, wantArgs...) + for _, want := range wantArgs { if !strings.Contains(args, want) { t.Errorf("engine argv missing %q:\n%s", want, args) } @@ -562,13 +593,13 @@ func TestCmdServe_ViewRunCapturesEngineOutput(t *testing.T) { if err != nil { t.Fatal(err) } - log := waitForFile(t, filepath.Join(stateDir, "engine.log")) + log := waitForFileContaining(t, filepath.Join(stateDir, "engine.log"), "engine up", "engine down") for _, want := range []string{"engine up", "engine down"} { if !strings.Contains(log, want) { t.Errorf("the engine log is missing %q:\n%s", want, log) } } - args := waitForFile(t, argsFile) + args := waitForFileContaining(t, argsFile, "--metrics") if !strings.Contains(args, "--metrics") { t.Errorf("the view run must switch the metrics endpoint on:\n%s", args) } @@ -653,7 +684,7 @@ func TestCmdServe_ViewQuitStopsTheEngine(t *testing.T) { if err != nil { t.Fatal(err) } - log := waitForFile(t, filepath.Join(stateDir, "engine.log")) + log := waitForFileContaining(t, filepath.Join(stateDir, "engine.log"), "engine stopped on TERM") if !strings.Contains(log, "engine stopped on TERM") { t.Errorf("the engine must be stopped through the supervisor on q:\n%s", log) } diff --git a/cmd/spinloop/waitforfile_test.go b/cmd/spinloop/waitforfile_test.go new file mode 100644 index 00000000..0ecf0d52 --- /dev/null +++ b/cmd/spinloop/waitforfile_test.go @@ -0,0 +1,80 @@ +package main + +import ( + "os" + "os/exec" + "path/filepath" + "testing" + "time" +) + +// A file that exists has not necessarily been written. The daemon tests poll +// for the stub engine's argv and the engine log, and a read that returned as +// soon as the file existed could see it empty or partial and fail an +// assertion about its contents. These pin the two halves of the fix: the +// helper waits for content, and the stub never exposes an empty argv file. + +func TestWaitForFileContaining_SkipsAnEmptyAndAPartialFile(t *testing.T) { + path := filepath.Join(t.TempDir(), "log") + go func() { + _ = os.WriteFile(path, nil, 0o600) // created, nothing written yet + time.Sleep(60 * time.Millisecond) + _ = os.WriteFile(path, []byte("engine up\n"), 0o600) // the first line only + time.Sleep(60 * time.Millisecond) + _ = os.WriteFile(path, []byte("engine up\nengine down\n"), 0o600) + }() + + got := waitForFileContaining(t, path, "engine up", "engine down") + + if got != "engine up\nengine down\n" { + t.Errorf("returned before the wanted text was there: %q", got) + } +} + +func TestWaitForFile_DoesNotReturnAnEmptyFile(t *testing.T) { + path := filepath.Join(t.TempDir(), "args") + go func() { + _ = os.WriteFile(path, nil, 0o600) + time.Sleep(60 * time.Millisecond) + _ = os.WriteFile(path, []byte("--metrics\n"), 0o600) + }() + + if got := waitForFile(t, path); got != "--metrics\n" { + t.Errorf("got %q, want the written argv", got) + } +} + +func TestStubEngineDaemon_ArgsFileNeverAppearsEmpty(t *testing.T) { + // With a plain redirection the empty file was visible on most runs, so a + // handful of runs is enough to catch a regression; each costs a process spawn. + for i := 0; i < 10; i++ { + argsFile := filepath.Join(t.TempDir(), "args") + stubEngineDaemon(t, argsFile) + cmd := exec.Command(llamaServerBinary, "--hf-repo", "org/model:Q4_K_M", "--metrics") + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + + // Read as fast as possible from the moment the engine starts, so a file + // that is created before it is written would be caught in between. + deadline := time.Now().Add(5 * time.Second) + for { + data, err := os.ReadFile(argsFile) + if err == nil { + if len(data) == 0 { + _ = cmd.Process.Kill() + t.Fatalf("run %d: the argv file existed while empty", i) + } + break + } + if time.Now().After(deadline) { + _ = cmd.Process.Kill() + t.Fatalf("run %d: the argv file never appeared", i) + } + } + // Killed rather than asked to stop: the stub only acts on TERM between + // its sleeps, and nothing here depends on how it exits. + _ = cmd.Process.Kill() + _ = cmd.Wait() + } +}