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

@@ -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

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
 }

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

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