From 82bd142429c67642edf6812185c28235e16073f5 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Sun, 4 Oct 2026 03:11:43 +0200 Subject: [PATCH] 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 --- TODO.md | 12 + backend/cmd/netwatch-server/main.go | 14 +- backend/cmd/netwatch-server/main_test.go | 227 ++++++++++++++++++ backend/internal/config/config.go | 7 +- backend/internal/handlers/healthcheck.go | 2 +- backend/internal/handlers/healthcheck_test.go | 16 +- backend/internal/healthcheck/healthcheck.go | 19 +- 7 files changed, 276 insertions(+), 21 deletions(-) create mode 100644 backend/cmd/netwatch-server/main_test.go diff --git a/TODO.md b/TODO.md index 6445247..7f13ff4 100644 --- a/TODO.md +++ b/TODO.md @@ -23,6 +23,18 @@ latest run passes. # Completed Steps +- 2026-10-03: the backend's logs are one stream (issue #27): fx logs its own + steps of starting and stopping through the backend's logger, so off a terminal + every line the backend's own logger and fx write is JSON, where fx used to + write plain text to stderr. A config file that is found but cannot be read now + stops the start with its error, logged as JSON like a bad setting, where it + used to end in a Go panic. A test runs the server as a child process and + checks both. 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 path, content type, `"status":"ok"` and 200 are unchanged. + `SENTRY_DSN`, `METRICS_USERNAME` and `METRICS_PASSWORD` are still read and + still unused, and left out of `backend/README.md`, until issues #94 and #95 + wire them up - 2026-10-03: the frontend has a real linter (issue #47, and item 2 of issue #28): `eslint` with its recommended rules, set in `eslint.config.js`, runs in a new `frontend-lint` stage of `Dockerfile`, which the frontend stage waits diff --git a/backend/cmd/netwatch-server/main.go b/backend/cmd/netwatch-server/main.go index 0136dae..d9f3c17 100644 --- a/backend/cmd/netwatch-server/main.go +++ b/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() } diff --git a/backend/cmd/netwatch-server/main_test.go b/backend/cmd/netwatch-server/main_test.go new file mode 100644 index 0000000..964e867 --- /dev/null +++ b/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) + } + } + } +} diff --git a/backend/internal/config/config.go b/backend/internal/config/config.go index a258978..0abc49b 100644 --- a/backend/internal/config/config.go +++ b/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, ¬Found) { - log.Error("config file malformed", "error", err) - panic(err) + return nil, fmt.Errorf("config file %s: %w", + viper.ConfigFileUsed(), err) } } diff --git a/backend/internal/handlers/healthcheck.go b/backend/internal/handlers/healthcheck.go index d71e8bf..41cd943 100644 --- a/backend/internal/handlers/healthcheck.go +++ b/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) } } diff --git a/backend/internal/handlers/healthcheck_test.go b/backend/internal/handlers/healthcheck_test.go index dfbfa31..3348ab6 100644 --- a/backend/internal/handlers/healthcheck_test.go +++ b/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"]) } } diff --git a/backend/internal/healthcheck/healthcheck.go b/backend/internal/healthcheck/healthcheck.go index 4540abd..f4b78e1 100644 --- a/backend/internal/healthcheck/healthcheck.go +++ b/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",