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