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 slog event logger through the
backend's logger, so off a terminal every line the backend's own
logger and fx write is JSON. A malformed config file 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; its type and method take the names
GO_HTTP_SERVER_CONVENTIONS.md gives.
Rules suppressed: revive and tagliatelle on HealthcheckResponse, whose name and keys come from the conventions; gosec where the test starts its own binary.

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,227 @@
+package main
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"net"
+	"net/http"
+	"os"
+	"os/exec"
+	"os/signal"
+	"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) != "" {
+		// A SIGTERM that comes before fx catches it is dropped, not fatal.
+		signal.Notify(make(chan os.Signal, 1), syscall.SIGTERM)
+		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)
+
+	// The child drops a SIGTERM that comes before fx catches it (see
+	// TestMain), so send one every 100ms until the test ends. ctx
+	// bounds the wait: when it ends, the child is killed.
+	stop := make(chan struct{})
+	defer close(stop)
+
+	go func() {
+		for {
+			_ = child.Process.Signal(syscall.SIGTERM)
+
+			select {
+			case <-stop:
+				return
+			case <-time.After(100 * time.Millisecond):
+			}
+		}
+	}()
+
+	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, and
+// killed and reaped when the test ends if nothing waited for it.
+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)
+	}
+
+	t.Cleanup(func() {
+		if child.ProcessState == nil {
+			_ = child.Process.Kill()
+			_ = child.Wait()
+		}
+	})
+
+	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)
+			}
+		}
+	}
+}

backend/internal/config/config.go

@@ -73,7 +73,8 @@ type Config struct {
 
 // New loads configuration from env, .env files, and config
 // files, returning a fully resolved Config. It fails, with an error
-// naming the setting, on a value the server cannot use.
+// naming the setting, on a value the server cannot use, and on a
+// config file it finds but cannot read.
 func New(
 	_ fx.Lifecycle,
 	params Params,
@@ -106,8 +107,8 @@ func New(
 	if err != nil {
 		var notFound viper.ConfigFileNotFoundError
 		if !errors.As(err, &notFound) {
-			log.Error("config file malformed", "error", err)
-			panic(err)
+			return nil, fmt.Errorf("config file %s: %w",
+				viper.ConfigFileUsed(), err)
 		}
 	}
 

backend/internal/handlers/healthcheck.go

@@ -6,6 +6,6 @@ import "net/http"
 // endpoint.
 func (s *Handlers) HandleHealthCheck() http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
-		s.respondJSON(w, r, s.hc.Check(), http.StatusOK)
+		s.respondJSON(w, r, s.hc.Healthcheck(), http.StatusOK)
 	}
 }

backend/internal/handlers/healthcheck_test.go

@@ -50,8 +50,8 @@ func newStartedHandlers(t *testing.T, g *globals.Globals) *handlers.Handlers {
 
 // TestHandleHealthCheck checks the health check's answer: 200, a JSON
 // content type, and a JSON object with exactly the fields of
-// healthcheck.Response, carrying this server's name and version and
-// an uptime counted from its start.
+// healthcheck.HealthcheckResponse, carrying this server's name and
+// version and an uptime counted from its start.
 func TestHandleHealthCheck(t *testing.T) {
 	t.Parallel()
 
@@ -82,7 +82,7 @@ func TestHandleHealthCheck(t *testing.T) {
 	}
 
 	fields := []string{
-		"appname", "now", "status", "uptimeHuman", "uptimeSeconds", "version",
+		"appname", "now", "status", "uptime_human", "uptime_seconds", "version",
 	}
 	if got := slices.Sorted(maps.Keys(body)); !slices.Equal(got, fields) {
 		t.Fatalf("fields = %v, want %v", got, fields)
@@ -104,17 +104,17 @@ func TestHandleHealthCheck(t *testing.T) {
 	}
 
 	// Started just now, so the uptime is well under a minute.
-	human, _ := body["uptimeHuman"].(string)
+	human, _ := body["uptime_human"].(string)
 
 	uptime, err := time.ParseDuration(human)
 	if err != nil || uptime > time.Minute {
-		t.Errorf("uptimeHuman = %q, want a duration under a minute (%v)",
+		t.Errorf("uptime_human = %q, want a duration under a minute (%v)",
 			human, err)
 	}
 
-	seconds, ok := body["uptimeSeconds"].(float64)
+	seconds, ok := body["uptime_seconds"].(float64)
 	if !ok || seconds < 0 || seconds > time.Minute.Seconds() {
-		t.Errorf("uptimeSeconds = %v, want a number of seconds under a minute",
-			body["uptimeSeconds"])
+		t.Errorf("uptime_seconds = %v, want a number of seconds under a minute",
+			body["uptime_seconds"])
 	}
 }

backend/internal/healthcheck/healthcheck.go

@@ -30,14 +30,17 @@ type Healthcheck struct {
 	params      *Params
 }
 
-// Response is the JSON payload returned by the health check
-// endpoint.
-type Response struct {
+// HealthcheckResponse is the JSON payload returned by the health
+// check endpoint. Its name and its snake_case keys are the ones
+// GO_HTTP_SERVER_CONVENTIONS.md gives.
+//
+//nolint:revive,tagliatelle // name and keys from the conventions
+type HealthcheckResponse struct {
 	Appname       string `json:"appname"`
 	Now           string `json:"now"`
 	Status        string `json:"status"`
-	UptimeHuman   string `json:"uptimeHuman"`
-	UptimeSeconds int64  `json:"uptimeSeconds"`
+	UptimeHuman   string `json:"uptime_human"`
+	UptimeSeconds int64  `json:"uptime_seconds"`
 	Version       string `json:"version"`
 }
 
@@ -65,9 +68,9 @@ func New(
 	return s, nil
 }
 
-// Check returns the current health status of the application.
-func (s *Healthcheck) Check() *Response {
-	return &Response{
+// Healthcheck returns the current health status of the application.
+func (s *Healthcheck) Healthcheck() *HealthcheckResponse {
+	return &HealthcheckResponse{
 		Appname:       s.params.Globals.Appname,
 		Now:           time.Now().UTC().Format(time.RFC3339Nano),
 		Status:        "ok",