Send fx's own events through the service's logger (closes #183)

fx printed its dependency graph and its start and stop hooks through
its console logger on standard error. fx.WithLogger now hands those
events to the service's logger: building the graph at DEBUG, the hooks,
the start and the stopping signal at INFO, failures at ERROR. The fx
logger's constructor takes the configuration, so the level DEBUG=true
sets is in force before fx replays the events it held back. fx's
SlogLogger takes one level for everything that is not a failure, so
FxLogger in internal/logger holds one at each level. fx moves from
v1.20.1, which has no SlogLogger, to v1.24.0. The README names the Go
runtime as a writer whose output cannot be redirected.

Model: opus-5-5

cmd/webhooker/main.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/datadir"
@@ -168,6 +169,17 @@ func run(stderr io.Writer) int {
 func newApp() *fx.App {
 	return fx.New(
 		fx.StopTimeout(stopTimeout),
+		// fx's own events go through the service's logger, not fx's
+		// console logger on standard error. fx holds its events back
+		// until this logger is built and then replays them, so it takes
+		// the configuration, which sets the level DEBUG=true asks for:
+		// without it the replay would run at INFO and drop every record
+		// of how the graph was built.
+		fx.WithLogger(
+			func(l *logger.Logger, _ *config.Config) fxevent.Logger {
+				return logger.NewFxLogger(l.Get())
+			},
+		),
 		fx.Provide(
 			globals.New,
 			logger.New,

cmd/webhooker/main_test.go

@@ -2,6 +2,12 @@ package main
 
 import (
 	"bytes"
+	"encoding/json"
+	"io"
+	"log/slog"
+	"net"
+	"os"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -38,6 +44,99 @@ func TestNewApp_StopTimeout(t *testing.T) {
 	require.Less(t, got, dockerStopGrace)
 }
 
+// freePort returns a loopback TCP port that was free a moment ago, by
+// taking one and releasing it.
+func freePort(t *testing.T) int {
+	t.Helper()
+
+	var listenCfg net.ListenConfig
+
+	l, err := listenCfg.Listen(t.Context(), "tcp", "127.0.0.1:0")
+	require.NoError(t, err)
+
+	addr, ok := l.Addr().(*net.TCPAddr)
+	require.True(t, ok, "listener is not TCP")
+	require.NoError(t, l.Close())
+
+	return addr.Port
+}
+
+// TestNewApp_SendsFxEventsToTheLogger starts and stops the app main
+// runs, with DEBUG=true, and reads back what reached the service's
+// logger. fx's own events must arrive there as structured records:
+// the start at INFO, and at DEBUG the records of how the graph was
+// built.
+//
+// fx holds its events back until its logger is built and then replays
+// them all at once, so the earliest of them arriving shows the replay
+// ran at DEBUG: that globals.New was provided, which fx records before
+// anything is built, and the run of logger.New, which happens before
+// the configuration sets the level.
+func TestNewApp_SendsFxEventsToTheLogger(t *testing.T) {
+	t.Setenv("DATA_DIR", t.TempDir())
+	t.Setenv("PORT", strconv.Itoa(freePort(t)))
+	t.Setenv("DEBUG", "true")
+
+	// internal/logger writes to whatever os.Stdout is when it builds
+	// its handler. A file is not a terminal, so that handler is the
+	// JSON one the service uses in production.
+	out, err := os.CreateTemp(t.TempDir(), "stdout")
+	require.NoError(t, err)
+
+	stdout := os.Stdout
+	os.Stdout = out
+
+	t.Cleanup(func() {
+		os.Stdout = stdout
+		_ = out.Close()
+	})
+
+	app := newApp()
+	require.NoError(t, app.Start(t.Context()))
+	require.NoError(t, app.Stop(t.Context()))
+
+	_, err = out.Seek(0, io.SeekStart)
+	require.NoError(t, err)
+
+	written, err := io.ReadAll(out)
+	require.NoError(t, err)
+
+	type record struct {
+		Level       string `json:"level"`
+		Msg         string `json:"msg"`
+		Name        string `json:"name"`
+		Constructor string `json:"constructor"`
+	}
+
+	var records []record
+
+	for line := range strings.Lines(string(written)) {
+		var r record
+
+		// The first-boot banner is plain text, not a record.
+		if json.Unmarshal([]byte(line), &r) == nil {
+			records = append(records, r)
+		}
+	}
+
+	const pkg = "sneak.berlin/go/webhooker/internal/"
+
+	info := slog.LevelInfo.String()
+	debug := slog.LevelDebug.String()
+
+	assert.Contains(t, records, record{Level: info, Msg: "started"})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "provided", Constructor: pkg + "globals.New()",
+	})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "run", Name: pkg + "logger.New()",
+	})
+	assert.Contains(t, records, record{Level: debug, Msg: "invoking"})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "initialized custom fxevent.Logger",
+	})
+}
+
 // TestRunRefusesLockedDataDir pins what an operator's second start
 // does. The entry point must refuse before it builds the fx graph —
 // nothing may open a database in a DATA_DIR another process holds —