Name the cause on the page for a refused form (closes #358)

The CSRF middleware answered a refused login or generator form with the
library's bare text, such as "Forbidden - origin invalid". It now answers
403 with a page that names the cause and what to do, and logs a warning
with the request ID and the library's reason. A page opened over plain
HTTP with debug off and a form from another host both fail the origin
check; the page tells them apart by the host in the Origin or Referer
header.

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

internal/handlers/csrf_refused_internal_test.go

@@ -8,6 +8,7 @@ import (
 	"log/slog"
 	"net/http"
 	"net/http/httptest"
+	"net/url"
 	"strings"
 	"testing"
 
@@ -84,18 +85,38 @@ func TestFormRefusedNamesCause(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			t.Parallel()
 
-			rec, logLine := postRefusedForm(t, tt.debug, tt.origin, tt.referer)
+			rec, logLine := postRefusedForm(t, tt.debug, tt.origin, tt.referer,
+				nil, "")
 			checkFormRefused(t, rec, logLine, tt.wantCause, tt.wantReason)
 		})
 	}
 }
 
-// postRefusedForm sends a POST with no CSRF token or cookie to the CSRF
-// middleware built for debug, with the given Origin and Referer headers
-// when they are not empty. It returns the response and the one JSON log
-// line the middleware wrote.
+// TestFormRefusedNamesCauseForForeignToken verifies that a form whose token
+// does not match its CSRF cookie answers 403 with a page naming
+// causeStaleToken, and logs a warning with the request ID and the
+// middleware's reason.
+func TestFormRefusedNamesCauseForForeignToken(t *testing.T) {
+	t.Parallel()
+
+	// The router and postRefusedForm derive their CSRF key from
+	// testSigningKey, so cookiesA is valid there and only tokenB is wrong.
+	_, router := newCSRFTestRouter(t)
+	cookiesA, _ := csrfCredentials(t, router, nil)
+	_, tokenB := csrfCredentials(t, router, nil)
+
+	rec, logLine := postRefusedForm(t, true, "http://example.com", "",
+		cookiesA, tokenB)
+	checkFormRefused(t, rec, logLine, causeStaleToken, csrf.ErrBadToken)
+}
+
+// postRefusedForm sends a POST with the given cookies to the CSRF
+// middleware built for debug. It adds the form token and the Origin and
+// Referer headers when they are not empty. It returns the response and the
+// one JSON log line the middleware wrote.
 func postRefusedForm(
 	t *testing.T, debug bool, origin, referer string,
+	cookies []*http.Cookie, token string,
 ) (*httptest.ResponseRecorder, map[string]any) {
 	t.Helper()
 
@@ -112,12 +133,21 @@ func postRefusedForm(
 	})
 	srv := newCSRFProtect(keys.CSRFKey, debug, log)(reached)
 
+	form := url.Values{loginKeyField: {"x"}}
+	if token != "" {
+		form.Set(csrfTokenField, token)
+	}
+
 	ctx := context.WithValue(context.Background(),
 		middleware.RequestIDKey, refusedFormRequestID)
 	req := httptest.NewRequestWithContext(ctx, http.MethodPost,
-		"http://example.com/", strings.NewReader("key=x"))
+		"http://example.com/", strings.NewReader(form.Encode()))
 	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
 
+	for _, c := range cookies {
+		req.AddCookie(c)
+	}
+
 	if origin != "" {
 		req.Header.Set("Origin", origin)
 	}