From 851a374e53f38bdbddb5989c05c691ec23e757ff Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Wed, 11 Nov 2026 22:26:52 +0100 Subject: [PATCH] Test that pixad writes only its own errors to stderr (closes #359) Both tests run pixad as a child process. They fail against this code: every start writes the dependency-injection library's event log to stderr, and a startup error is printed twice inside its frames. Model: opus-5-5 --- go.mod | 2 +- internal/app/app.go | 45 +++++++- internal/app/app_internal_test.go | 65 +++++++++++ internal/app/app_test.go | 177 ++++++++++++++++++++++++++++++ 4 files changed, 286 insertions(+), 3 deletions(-) create mode 100644 internal/app/app_internal_test.go create mode 100644 internal/app/app_test.go diff --git a/go.mod b/go.mod index 618e2e9..2707998 100644 --- a/go.mod +++ b/go.mod @@ -17,6 +17,7 @@ require ( github.com/prometheus/client_golang v1.23.2 github.com/slok/go-http-metrics v0.13.0 github.com/spf13/cobra v1.10.2 + go.uber.org/dig v1.19.0 go.uber.org/fx v1.24.0 golang.org/x/crypto v0.41.0 golang.org/x/sync v0.19.0 @@ -126,7 +127,6 @@ require ( go.opentelemetry.io/otel v1.36.0 // indirect go.opentelemetry.io/otel/metric v1.36.0 // indirect go.opentelemetry.io/otel/trace v1.36.0 // indirect - go.uber.org/dig v1.19.0 // indirect go.uber.org/multierr v1.11.0 // indirect go.uber.org/zap v1.27.0 // indirect go.yaml.in/yaml/v2 v2.4.2 // indirect diff --git a/internal/app/app.go b/internal/app/app.go index 0d9daf9..1481ef7 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -2,13 +2,16 @@ package app import ( + "context" "fmt" + "io" "os" "os/signal" "syscall" "github.com/prometheus/client_golang/prometheus" "github.com/spf13/cobra" + "go.uber.org/dig" "go.uber.org/fx" "sneak.berlin/go/pixa/internal/config" "sneak.berlin/go/pixa/internal/database" @@ -53,7 +56,10 @@ func run(_ *cobra.Command, _ []string) { // A write to a closed stdout or stderr must not end the process. signal.Ignore(syscall.SIGPIPE) - fx.New( + app := fx.New( + // pixad logs with slog only; runApp prints a startup or shutdown + // error itself. + fx.NopLogger, fx.Provide( config.New, database.New, @@ -71,5 +77,40 @@ func run(_ *cobra.Command, _ []string) { func(log *logger.Logger) { log.Identify() }, func(*server.Server) {}, ), - ).Run() + ) + + exitCode := runApp(app, os.Stderr) + if exitCode != 0 { + os.Exit(exitCode) + } +} + +// runApp starts app, waits for a signal or a shutdown request, stops app, +// and returns the status pixad exits with, as fx.App.Run does. It prints +// a start or stop error to stderr, once, as the error that caused it: +// dig.RootCause drops the frames fx and dig wrap around it. +func runApp(app *fx.App, stderr io.Writer) int { + startCtx, cancelStart := context.WithTimeout(context.Background(), app.StartTimeout()) + defer cancelStart() + + err := app.Start(startCtx) + if err != nil { + _, _ = fmt.Fprintln(stderr, dig.RootCause(err)) + + return 1 + } + + shutdown := <-app.Wait() + + stopCtx, cancelStop := context.WithTimeout(context.Background(), app.StopTimeout()) + defer cancelStop() + + err = app.Stop(stopCtx) + if err != nil { + _, _ = fmt.Fprintln(stderr, dig.RootCause(err)) + + return 1 + } + + return shutdown.ExitCode } diff --git a/internal/app/app_internal_test.go b/internal/app/app_internal_test.go new file mode 100644 index 0000000..d59b25d --- /dev/null +++ b/internal/app/app_internal_test.go @@ -0,0 +1,65 @@ +package app + +import ( + "bytes" + "context" + "errors" + "io" + "testing" + + "go.uber.org/fx" +) + +var errTestStopFailed = errors.New("test stop hook failed") + +// TestRunAppPrintsStopErrorOnce checks that when a stop hook fails, runApp +// prints the hook's error once and returns exit status 1. +func TestRunAppPrintsStopErrorOnce(t *testing.T) { + t.Parallel() + + app := fx.New( + fx.NopLogger, + fx.Invoke(func(lifecycle fx.Lifecycle, shutdowner fx.Shutdowner) { + lifecycle.Append(fx.Hook{ + // Ask to shut down as soon as the app has started, so + // that runApp goes on to stop it. + OnStart: func(context.Context) error { return shutdowner.Shutdown() }, + OnStop: func(context.Context) error { return errTestStopFailed }, + }) + }), + ) + + var stderr bytes.Buffer + + exitCode := runApp(app, &stderr) + if exitCode != 1 { + t.Errorf("runApp() = %d, want 1", exitCode) + } + + want := errTestStopFailed.Error() + "\n" + if stderr.String() != want { + t.Errorf("stderr = %q, want %q", stderr.String(), want) + } +} + +// TestRunAppReturnsShutdownExitCode checks that runApp returns the exit +// code a shutdown request names. +func TestRunAppReturnsShutdownExitCode(t *testing.T) { + t.Parallel() + + app := fx.New( + fx.NopLogger, + fx.Invoke(func(lifecycle fx.Lifecycle, shutdowner fx.Shutdowner) { + lifecycle.Append(fx.Hook{ + OnStart: func(context.Context) error { + return shutdowner.Shutdown(fx.ExitCode(3)) + }, + }) + }), + ) + + exitCode := runApp(app, io.Discard) + if exitCode != 3 { + t.Errorf("runApp() = %d, want 3", exitCode) + } +} diff --git a/internal/app/app_test.go b/internal/app/app_test.go new file mode 100644 index 0000000..a6d94bf --- /dev/null +++ b/internal/app/app_test.go @@ -0,0 +1,177 @@ +package app_test + +import ( + "bytes" + "errors" + "fmt" + "net" + "net/http" + "os" + "os/exec" + "strconv" + "syscall" + "testing" + "time" + + "sneak.berlin/go/pixa/internal/app" +) + +// These tests run pixad in a child process: the test binary itself, +// started again with runPixadInChildEnvVar set, which makes TestMain run +// pixad instead of the tests. +const runPixadInChildEnvVar = "TEST_RUN_PIXAD_IN_CHILD" + +const validTestSigningKey = "test-signing-key-for-app-tests-0123456789" + +func TestMain(m *testing.M) { + if os.Getenv(runPixadInChildEnvVar) == "1" { + os.Args = []string{"pixad"} + + app.Run("test") + os.Exit(0) + } + + os.Exit(m.Run()) +} + +// pixadCommand returns a command that runs pixad with only the given +// environment, in an empty directory with an empty HOME, so that no +// config file is found. +func pixadCommand(t *testing.T, env ...string) (*exec.Cmd, *bytes.Buffer) { + t.Helper() + + testBinary := os.Args[0] + cmd := exec.CommandContext(t.Context(), testBinary) //nolint:gosec // not tainted + cmd.Dir = t.TempDir() + // A test binary built with -cover warns on stderr at exit when + // GOCOVERDIR is not set. + cmd.Env = append([]string{ + runPixadInChildEnvVar + "=1", + "HOME=" + t.TempDir(), + "GOCOVERDIR=" + t.TempDir(), + }, env...) + + var stderr bytes.Buffer + + cmd.Stderr = &stderr + + return cmd, &stderr +} + +// TestRunPrintsStartupErrorOnce checks that an invalid setting is +// printed once, as the line that names it, and nothing else goes to +// stderr. +func TestRunPrintsStartupErrorOnce(t *testing.T) { + t.Parallel() + + cmd, stderr := pixadCommand(t, "PIXA_SIGNING_KEY=short") + + err := cmd.Run() + + var exitErr *exec.ExitError + if !errors.As(err, &exitErr) || exitErr.ExitCode() != 1 { + t.Fatalf("pixad: got %v, want exit status 1; stderr:\n%s", err, stderr) + } + + want := `config key "signing_key" (environment variable PIXA_SIGNING_KEY): ` + + "value too short: must be at least 32 characters, got 5\n" + if stderr.String() != want { + t.Errorf("stderr:\n%s\nwant:\n%s", stderr, want) + } +} + +// TestRunWritesNothingToStderrOnStartAndStop starts pixad, waits until +// it answers its health check, stops it with SIGTERM, and checks that it +// wrote nothing to stderr. +func TestRunWritesNothingToStderrOnStartAndStop(t *testing.T) { + t.Parallel() + + port := freePort(t) + cmd, stderr := pixadCommand(t, + "PORT="+strconv.Itoa(port), + "PIXA_STATE_DIR="+t.TempDir(), + "PIXA_SIGNING_KEY="+validTestSigningKey, + ) + + err := cmd.Start() + if err != nil { + t.Fatalf("starting pixad: %v", err) + } + + waitForHealthCheck(t, cmd, port, stderr) + + err = cmd.Process.Signal(syscall.SIGTERM) + if err != nil { + t.Fatalf("signalling pixad: %v", err) + } + + err = cmd.Wait() + if err != nil { + t.Fatalf("pixad: got %v, want exit status 0; stderr:\n%s", err, stderr) + } + + if stderr.Len() != 0 { + t.Errorf("stderr is not empty:\n%s", stderr) + } +} + +// freePort returns a TCP port on the loopback address that nothing +// listens on. +func freePort(t *testing.T) int { + t.Helper() + + var listenConfig net.ListenConfig + + listener, err := listenConfig.Listen(t.Context(), "tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("finding a free port: %v", err) + } + + addr, ok := listener.Addr().(*net.TCPAddr) + if !ok { + t.Fatalf("listener address %v is not a TCP address", listener.Addr()) + } + + err = listener.Close() + if err != nil { + t.Fatalf("closing listener: %v", err) + } + + return addr.Port +} + +// waitForHealthCheck waits up to 30 seconds for pixad, started as cmd, to +// answer its health check on port. If it does not, it stops pixad and +// fails the test with what pixad wrote to stderr. +func waitForHealthCheck(t *testing.T, cmd *exec.Cmd, port int, stderr *bytes.Buffer) { + t.Helper() + + url := fmt.Sprintf("http://127.0.0.1:%d/.well-known/healthcheck.json", port) + deadline := time.Now().Add(30 * time.Second) + + for time.Now().Before(deadline) { + req, err := http.NewRequestWithContext(t.Context(), http.MethodGet, url, nil) + if err != nil { + t.Fatalf("health check request: %v", err) + } + + resp, err := http.DefaultClient.Do(req) + if err == nil { + _ = resp.Body.Close() + + if resp.StatusCode == http.StatusOK { + return + } + } + + time.Sleep(100 * time.Millisecond) + } + + // Stop pixad first: stderr is complete, and safe to read, only once + // cmd.Wait has returned. + _ = cmd.Process.Kill() + _ = cmd.Wait() + + t.Fatalf("pixad did not answer its health check on port %d; stderr:\n%s", + port, stderr) +}