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.

Model: opus-5-5

.gitignore

@@ -70,4 +70,3 @@ vendor/
 # Local dev configs
 config.yml
 config.yaml
-config.dev.yml

Makefile

@@ -79,12 +79,15 @@ docker-versioned:
 docker-test:
 	@script/test
 
-# Run local dev server in Docker
+# Run local dev server in Docker, with debug on and a new random signing
+# key each run. Log in to the page with the key it prints.
 devserver: docker-versioned devserver-stop
+	@key="$$(head -c 32 /dev/urandom | base64)" && \
 	docker run -d --name pixad-dev -p 8080:8080 \
-		-v $(CURDIR)/config.dev.yml:/etc/pixa/config.yml:ro \
-		pixa:latest
-	@echo "pixad running at http://localhost:8080"
+		-e PIXA_SIGNING_KEY="$$key" -e PIXA_DEBUG=true \
+		pixa:latest >/dev/null && \
+	echo "pixad running at http://localhost:8080" && \
+	echo "signing key: $$key"
 
 # Stop dev server
 devserver-stop:

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,6 +2,7 @@
 package app
 
 import (
+	"context"
 	"fmt"
 	"os"
 	"os/signal"
@@ -9,6 +10,7 @@ import (
 
 	"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 +55,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 +76,40 @@ func run(_ *cobra.Command, _ []string) {
 			func(log *logger.Logger) { log.Identify() },
 			func(*server.Server) {},
 		),
-	).Run()
+	)
+
+	exitCode := runApp(app)
+	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) int {
+	startCtx, cancelStart := context.WithTimeout(context.Background(), app.StartTimeout())
+	defer cancelStart()
+
+	err := app.Start(startCtx)
+	if err != nil {
+		fmt.Fprintln(os.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(os.Stderr, dig.RootCause(err))
+
+		return 1
+	}
+
+	return shutdown.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)
+}