From 8aaf6dc794468a13a9e405d1ea874c74eb9f7909 Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 11 Nov 2026 20:30:59 +0000 Subject: [PATCH 1/2] 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 --- internal/app/app_test.go | 177 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 177 insertions(+) create mode 100644 internal/app/app_test.go 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) +} -- 2.54.0 From 2679139492921623efb7cce1a9083ea47caaa750 Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 11 Nov 2026 20:34:06 +0000 Subject: [PATCH 2/2] Print a startup or shutdown error once, without fx's event log (closes #359) pixad builds its fx app with fx.NopLogger and runs start, wait and stop itself, so that it can print a start or stop error to stderr once. dig.RootCause strips the frames fx and dig wrap around the error, which leaves the line that names the setting. The exit status is as before. Two tests run runApp on a small fx app. A stop hook that fails has its error printed once, with exit status 1. A shutdown request's exit code is returned. Model: opus-5-5 --- go.mod | 2 +- internal/app/app.go | 45 ++++++++++++++++++++- internal/app/app_internal_test.go | 65 +++++++++++++++++++++++++++++++ 3 files changed, 109 insertions(+), 3 deletions(-) create mode 100644 internal/app/app_internal_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) + } +} -- 2.54.0