Log fx through slog, snake_case health check keys (closes #27)

fx wrote its own steps of starting and stopping as plain text to
stderr. It now logs them with its own slog event logger through the
backend's logger, so off a terminal every line from start to stop is
JSON. A config file that is found but cannot be read now makes
config.New return the error instead of panicking. A test runs the
server as a child process and checks that all it writes is JSON, on a
normal start and stop and with such a config file. The backend logs
its name, version and architecture once at start.

The health check's uptime keys are now uptime_seconds and
uptime_human, and its type and method take the names
GO_HTTP_SERVER_CONVENTIONS.md gives. Its path, content type, status
and code are unchanged.

Model: opus-5-5

backend/cmd/netwatch-server/main.go

@@ -16,6 +16,7 @@ import (
 	"sneak.berlin/go/netwatch/internal/server"
 
 	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 )
 
 //nolint:gochecknoglobals // set via ldflags at build time
@@ -62,6 +63,12 @@ func main() {
 	globals.Version = Version
 
 	fx.New(
+		// fx logs each step of starting and stopping through the
+		// server's own logger, so off a terminal those lines are
+		// JSON like every other line.
+		fx.WithLogger(func(log *logger.Logger) fxevent.Logger {
+			return &fxevent.SlogLogger{Logger: log.Get()}
+		}),
 		fx.Provide(
 			config.New,
 			globals.New,
@@ -72,6 +79,11 @@ func main() {
 			reportbuf.New,
 			server.New,
 		),
-		fx.Invoke(func(*server.Server) {}),
+		fx.Invoke(
+			// First, so the name and version are logged even when
+			// a setting stops the start.
+			func(log *logger.Logger) { log.Identify() },
+			func(*server.Server) {},
+		),
 	).Run()
 }

backend/cmd/netwatch-server/main_test.go

@@ -0,0 +1,203 @@
+package main
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"net"
+	"net/http"
+	"os"
+	"os/exec"
+	"path/filepath"
+	"strings"
+	"syscall"
+	"testing"
+	"time"
+)
+
+// The tests run main() in a child process, this test binary started
+// again with runMainEnv set, because main() can exit its process and
+// takes its settings from the environment.
+const runMainEnv = "NETWATCH_SERVER_RUN_MAIN"
+
+// childTimeout bounds each child's whole run; it is killed after it.
+const childTimeout = 10 * time.Second
+
+func TestMain(m *testing.M) {
+	if os.Getenv(runMainEnv) != "" {
+		main()
+
+		return
+	}
+
+	os.Exit(m.Run())
+}
+
+// TestOutputIsJSON: off a terminal, every line the server writes from
+// start to stop is JSON, fx's own lines included.
+func TestOutputIsJSON(t *testing.T) {
+	t.Parallel()
+
+	ctx, cancel := context.WithTimeout(t.Context(), childTimeout)
+	defer cancel()
+
+	port := freePort(ctx, t)
+	child, stdout, stderr := startServer(ctx, t, t.TempDir(), port)
+
+	waitForHealthcheck(ctx, t, port)
+
+	err := child.Process.Signal(syscall.SIGTERM)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	err = child.Wait()
+	if err != nil {
+		t.Fatalf("server exit = %v, want success", err)
+	}
+
+	requireJSONLines(t, stdout, stderr)
+
+	if !strings.Contains(stdout.String(), `"msg":"starting"`) {
+		t.Fatalf("no startup line in stdout:\n%s", stdout)
+	}
+}
+
+// TestMalformedConfigFileStopsTheStart: a config file the server finds
+// but cannot read stops the start, and the error is logged as JSON.
+func TestMalformedConfigFileStopsTheStart(t *testing.T) {
+	t.Parallel()
+
+	ctx, cancel := context.WithTimeout(t.Context(), childTimeout)
+	defer cancel()
+
+	home := t.TempDir()
+	dir := filepath.Join(home, ".config", "netwatch-server")
+
+	err := os.MkdirAll(dir, 0o750)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	err = os.WriteFile(filepath.Join(dir, "netwatch-server.yaml"),
+		[]byte("PORT: [8080\n"), 0o600)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	child, stdout, stderr := startServer(ctx, t, home, freePort(ctx, t))
+
+	err = child.Wait()
+	if child.ProcessState.ExitCode() != 1 {
+		t.Fatalf("server exit = %v, want exit status 1", err)
+	}
+
+	requireJSONLines(t, stdout, stderr)
+
+	if !strings.Contains(stdout.String(), "netwatch-server.yaml") {
+		t.Fatalf("no error naming the config file in stdout:\n%s", stdout)
+	}
+}
+
+// startServer runs main() in a child process listening on
+// 127.0.0.1:port, with home as its HOME and working directory and its
+// data directory in home, so it touches nothing outside home. Its
+// stdout and stderr go to the two buffers returned, which hold all of
+// it once child.Wait returns. The child is killed when ctx ends.
+func startServer(
+	ctx context.Context,
+	t *testing.T,
+	home, port string,
+) (*exec.Cmd, *bytes.Buffer, *bytes.Buffer) {
+	t.Helper()
+
+	self, err := os.Executable()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	var stdout, stderr bytes.Buffer
+
+	child := exec.CommandContext(ctx, self) //nolint:gosec // this test binary
+	child.Dir = home
+	child.Env = append(os.Environ(),
+		runMainEnv+"=1",
+		"HOME="+home,
+		"DATA_DIR="+filepath.Join(home, "data"),
+		"BIND_ADDRESS=127.0.0.1",
+		"PORT="+port,
+	)
+	child.Stdout = &stdout
+	child.Stderr = &stderr
+
+	err = child.Start()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	return child, &stdout, &stderr
+}
+
+// freePort returns a TCP port on 127.0.0.1 that was free a moment ago.
+func freePort(ctx context.Context, t *testing.T) string {
+	t.Helper()
+
+	var lc net.ListenConfig
+
+	l, err := lc.Listen(ctx, "tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	_ = l.Close()
+
+	_, port, err := net.SplitHostPort(l.Addr().String())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	return port
+}
+
+// waitForHealthcheck returns once the health check on port answers 200.
+func waitForHealthcheck(ctx context.Context, t *testing.T, port string) {
+	t.Helper()
+
+	url := "http://127.0.0.1:" + port + "/.well-known/healthcheck"
+
+	for {
+		req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		resp, err := http.DefaultClient.Do(req)
+		if err == nil {
+			_ = resp.Body.Close()
+
+			if resp.StatusCode == http.StatusOK {
+				return
+			}
+		}
+
+		select {
+		case <-ctx.Done():
+			t.Fatalf("health check never answered: %v", err)
+		case <-time.After(50 * time.Millisecond):
+		}
+	}
+}
+
+// requireJSONLines fails the test on each line of outs that is not
+// JSON.
+func requireJSONLines(t *testing.T, outs ...*bytes.Buffer) {
+	t.Helper()
+
+	for _, out := range outs {
+		for line := range strings.Lines(out.String()) {
+			if !json.Valid([]byte(line)) {
+				t.Errorf("line is not JSON: %s", line)
+			}
+		}
+	}
+}