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

fx printed its dependency graph and lifecycle hooks through its own console logger on standard error, so an operator shipping the JSON log to a collector got a second shape on a second stream for every start. The production app now passes fx.WithLogger with a small FxLogger in internal/logger that writes fx's events through the service's logger: graph events at debug, lifecycle at info, failures at error. Its constructor takes the configuration, so DEBUG=true applies before fx replays the events it held back. go.uber.org/fx moves from v1.20.1 to v1.24.0. Tests keep fx.NopLogger. The README says a failure before the logger exists, and the Go runtime's own output, still go to standard error as plain text.

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,19 @@ 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. The exception is a failure
+		// before this logger is built, such as an invalid configuration
+		// value, which fx's console logger still prints there. 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 —