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. fx's own SlogLogger takes one level for everything that is not a failure, so the small FxLogger in internal/logger holds one at each level and picks by event. fx moves from v1.20.1, which has no SlogLogger, to v1.24.0, its current release. The README's logging passage now names only the Go runtime, whose output cannot be redirected.

Model: opus-5-5

README.md

@@ -543,8 +543,8 @@ If it is lost, run `webhooker resetpw admin` on a stopped deployment.
 ```
 
 It is a banner rather than a log line because that is the only time it
-is ever shown: as one `INFO` record it sat among the roughly 45 fx
+is ever shown: as one `INFO` record it would sit among the records fx
-`PROVIDE`/`RUN`/`HOOK` lines a boot writes, and under `docker run -d`
+writes as each start hook runs, and under `docker run -d`
 it is one line in a log subject to rotation. The database stores only
 its Argon2id hash. There is no second account and no forgot-password
 flow, so the banner and the reset command below are the only two ways
@@ -614,7 +614,8 @@ Changing a password you still know needs none of this — use
 
 `DEBUG=true` lowers the log level to `DEBUG`, which turns on every
 statement GORM runs, the two by-design lookup misses on the
-unauthenticated routes, and the rate limiter's own rejections. It is
+unauthenticated routes, the rate limiter's own rejections, and fx's
+records of building the dependency graph at startup. It is
 meant to be safe to turn on while diagnosing a live service and safe to
 paste the output of into a bug report.
 
@@ -2599,16 +2600,15 @@ read as more than it is:
   that type on a specific webhook, and each line it writes is bounded
   per event by the 1 MB receiver body cap. Adding one is a decision to
   spend log volume on that webhook's payloads.
-- **Two writers that do not go through `internal/logger` at all**, both
+- **The Go runtime**, the one writer that does not go through
-  on standard error. `fx` prints the dependency graph and the lifecycle
+  `internal/logger`. The runtime writes an unrecovered panic or a fatal
-  hooks through its default console logger at startup and shutdown —
+  error itself, as plain text on standard error, and that output cannot
-  nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
+  be redirected. A panic in a background worker rather than in a request
-  `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a
+  handler is the case that reaches it, since nothing recovers those. It
-  panic in a background worker rather than in a request handler is the
+  carries no client-chosen value at a client-chosen length: the
-  case that reaches it, since nothing recovers those. Neither carries a
+  service's own `panic` calls are invariant guards over constants and
-  client-chosen value at a client-chosen length: the five `panic` calls
+  over `crypto/rand`, apart from the one that hands
-  in this service are invariant guards over constants and over
+  `http.ErrAbortHandler` back to `net/http`, described below.
-  `crypto/rand`.
 - **`net/http`'s own faults**, which are _not_ a separate writer.
   `internal/server/http.go` builds its server with a nil `ErrorLog`, so
   `net/http` falls back to the `log` package's default logger — and
@@ -2958,7 +2958,7 @@ webhooker/
 │   ├── lifecycle/
 │   │   └── lifecycle.go       # Shared stop-hook waiter, bounded by the stop context
 │   ├── logger/
-│   │   └── logger.go          # slog setup with TTY detection
+│   │   └── logger.go          # slog setup with TTY detection; fx's event logger
 │   ├── metrics/
 │   │   └── metrics.go         # Delivery Prometheus collectors, labelled by target type
 │   ├── middleware/

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,11 @@ 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.WithLogger(func(l *logger.Logger) fxevent.Logger {
+			return logger.NewFxLogger(l.Get())
+		}),
 		fx.Provide(
 			globals.New,
 			logger.New,

go.mod

@@ -18,7 +18,7 @@ require (
 	github.com/prometheus/client_model v0.5.0
 	github.com/slok/go-http-metrics v0.11.0
 	github.com/stretchr/testify v1.11.1
-	go.uber.org/fx v1.20.1
+	go.uber.org/fx v1.24.0
 	golang.org/x/crypto v0.38.0
 	gopkg.in/yaml.v3 v3.0.1
 	gorm.io/driver/sqlite v1.5.4
@@ -35,7 +35,6 @@ require (
 	github.com/jinzhu/now v1.1.5 // indirect
 	github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect
 	github.com/klauspost/cpuid/v2 v2.2.10 // indirect
-	github.com/kr/text v0.2.0 // indirect
 	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/mattn/go-sqlite3 v1.14.17 // indirect
 	github.com/matttproud/golang_protobuf_extensions/v2 v2.0.0 // indirect
@@ -44,10 +43,9 @@ require (
 	github.com/prometheus/procfs v0.12.0 // indirect
 	github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect
 	github.com/zeebo/xxh3 v1.0.2 // indirect
-	go.uber.org/atomic v1.9.0 // indirect
+	go.uber.org/dig v1.19.0 // indirect
-	go.uber.org/dig v1.17.0 // indirect
+	go.uber.org/multierr v1.10.0 // indirect
-	go.uber.org/multierr v1.9.0 // indirect
+	go.uber.org/zap v1.26.0 // indirect
-	go.uber.org/zap v1.23.0 // indirect
 	golang.org/x/mod v0.17.0 // indirect
 	golang.org/x/sync v0.14.0 // indirect
 	golang.org/x/sys v0.37.0 // indirect

go.sum

@@ -1,14 +1,9 @@
 github.com/99designs/basicauth-go v0.0.0-20230316000542-bf6f9cbbf0f8 h1:nMpu1t4amK3vJWBibQ5X/Nv0aXL+b69TQf2uK5PH7Go=
 github.com/99designs/basicauth-go v0.0.0-20230316000542-bf6f9cbbf0f8/go.mod h1:3cARGAK9CfW3HoxCy1a0G4TKrdiKke8ftOMEOHyySYs=
-github.com/benbjohnson/clock v1.3.0 h1:ip6w0uFQkncKQ979AypyG0ER7mqUSBdKLOgAle/AT8A=
-github.com/benbjohnson/clock v1.3.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
 github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj44=
 github.com/cespare/xxhash/v2 v2.2.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
-github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
-github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
-github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc h1:U9qPSI2PIWSS1VwoXQT9A3Wy9MM3WgvqSxFWenqJduM=
 github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/dustin/go-humanize v1.0.1 h1:GzkhY7T5VNhEkwH0PVJgjz+fX1rhBrR7pRT3mDkpeCY=
@@ -65,7 +60,6 @@ github.com/pingcap/errors v0.11.4 h1:lFuQV/oaUMGcD2tqt+01ROSmJs75VG1ToEOkZIZ4nE4
 github.com/pingcap/errors v0.11.4/go.mod h1:Oi8TUi2kEtXXLMJk9l1cGmz20kV3TaQ0usTwv5KuLY8=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
-github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_golang v1.18.0 h1:HzFfmkOzH5Q8L8G+kSJKUx5dtG87sewO+FoDDqP5Tbk=
@@ -82,28 +76,24 @@ github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjR
 github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog=
 github.com/slok/go-http-metrics v0.11.0 h1:ABJUpekCZSkQT1wQrFvS4kGbhea/w6ndFJaWJeh3zL0=
 github.com/slok/go-http-metrics v0.11.0/go.mod h1:ZGKeYG1ET6TEJpQx18BqAJAvxw9jBAZXCHU7bWQqqAc=
-github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.5.2 h1:xuMeJ0Sdp5ZMRXx/aWO6RZxdr3beISkG5/G/aIRr3pY=
 github.com/stretchr/objx v0.5.2/go.mod h1:FRsXN1f5AsAjCGJKqEizvkpNtU+EGNCLh3NxZ/8L+MA=
-github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U=
 github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U=
 github.com/zeebo/assert v1.3.0 h1:g7C04CbJuIDKNPFHmsk4hwZDO5O+kntRxzaUoNXj+IQ=
 github.com/zeebo/assert v1.3.0/go.mod h1:Pq9JiuJQpG8JLJdtkwrJESF0Foym2/D9XMU5ciN/wJ0=
 github.com/zeebo/xxh3 v1.0.2 h1:xZmwmqxHZA8AI603jOQ0tMqmBr9lPeFwGg6d+xy9DC0=
 github.com/zeebo/xxh3 v1.0.2/go.mod h1:5NWz9Sef7zIDm2JHfFlcQvNekmcEl9ekUZQQKCYaDcA=
-go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE=
+go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
-go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
-go.uber.org/dig v1.17.0 h1:5Chju+tUvcC+N7N6EV08BJz41UZuO3BmHcN4A287ZLI=
+go.uber.org/fx v1.24.0 h1:wE8mruvpg2kiiL1Vqd0CC+tr0/24XIB10Iwp2lLWzkg=
-go.uber.org/dig v1.17.0/go.mod h1:rTxpf7l5I0eBTlE6/9RL+lDybC7WFwY2QH55ZSjy1mU=
+go.uber.org/fx v1.24.0/go.mod h1:AmDeGyS+ZARGKM4tlH4FY2Jr63VjbEDJHtqXTGP5hbo=
-go.uber.org/fx v1.20.1 h1:zVwVQGS8zYvhh9Xxcu4w1M6ESyeMzebzj2NbSayZ4Mk=
+go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
-go.uber.org/fx v1.20.1/go.mod h1:iSYNbHf2y55acNCwCXKx7LbWb5WG1Bnue5RDXz1OREg=
+go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
-go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
+go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=
-go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
+go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
-go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
+go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo=
-go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
+go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so=
-go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
-go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
 golang.org/x/crypto v0.38.0 h1:jt+WWG8IZlBnVbomuhg2Mdq0+BBQaHbtqHEFEigjUV8=
 golang.org/x/crypto v0.38.0/go.mod h1:MvrbAqul58NNYPKnOra203SB9vpuZW0e+RRZV+Ggqjw=
 golang.org/x/mod v0.17.0 h1:zY54UmvipHiNd+pm+m0x9KhZ9hl1/7QNMyxXbc6ICqA=

internal/logger/logger.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"sneak.berlin/go/webhooker/internal/globals"
 )
 
@@ -106,3 +107,40 @@ func (l *Logger) Identify() {
 func (l *Logger) Writer() io.Writer {
 	return os.Stdout
 }
+
+// FxLogger writes fx's own events through a slog logger: how the
+// dependency graph was built at DEBUG, since it repeats on every
+// start; the start and stop hooks, the start itself and the signal
+// that stops the service at INFO; every failure at ERROR.
+//
+// The formatting is fx's own fxevent.SlogLogger. That logger takes a
+// single level for every event that is not a failure, so FxLogger
+// holds one at each level and picks between them.
+type FxLogger struct {
+	graph     *fxevent.SlogLogger
+	lifecycle *fxevent.SlogLogger
+}
+
+// NewFxLogger returns an FxLogger that writes through log.
+func NewFxLogger(log *slog.Logger) *FxLogger {
+	graph := &fxevent.SlogLogger{Logger: log}
+	graph.UseLogLevel(slog.LevelDebug)
+
+	lifecycle := &fxevent.SlogLogger{Logger: log}
+	lifecycle.UseLogLevel(slog.LevelInfo)
+
+	return &FxLogger{graph: graph, lifecycle: lifecycle}
+}
+
+// LogEvent implements fxevent.Logger.
+func (f *FxLogger) LogEvent(event fxevent.Event) {
+	switch event.(type) {
+	case *fxevent.Supplied, *fxevent.Provided, *fxevent.Replaced,
+		*fxevent.Decorated, *fxevent.BeforeRun, *fxevent.Run,
+		*fxevent.Invoking, *fxevent.Invoked,
+		*fxevent.LoggerInitialized:
+		f.graph.LogEvent(event)
+	default:
+		f.lifecycle.LogEvent(event)
+	}
+}

internal/logger/logger_test.go

@@ -1,13 +1,23 @@
 package logger_test
 
 import (
+	"bytes"
+	"encoding/json"
+	"errors"
+	"log/slog"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"go.uber.org/fx/fxtest"
 	"sneak.berlin/go/webhooker/internal/globals"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
+var errStopHook = errors.New("stop hook failed on purpose")
+
 func testGlobals() *globals.Globals {
 	return &globals.Globals{
 		Appname: "test-app",
@@ -57,3 +67,47 @@ func TestEnableDebugLogging(t *testing.T) {
 	// Test debug logging
 	l.Get().Debug("debug message", "test", true)
 }
+
+// TestFxLogger_Levels starts and stops an fx app that reports its own
+// events through NewFxLogger, as cmd/webhooker does, and reads back
+// what reached the handler: the graph at DEBUG, the start at INFO and
+// a failed stop hook at ERROR, each as a structured record.
+func TestFxLogger_Levels(t *testing.T) {
+	t.Parallel()
+
+	var out bytes.Buffer
+
+	log := slog.New(slog.NewJSONHandler(
+		&out, &slog.HandlerOptions{Level: slog.LevelDebug},
+	))
+
+	app := fx.New(
+		fx.WithLogger(func() fxevent.Logger {
+			return logger.NewFxLogger(log)
+		}),
+		fx.Invoke(func(lc fx.Lifecycle) {
+			lc.Append(fx.StopHook(func() error { return errStopHook }))
+		}),
+	)
+
+	require.NoError(t, app.Start(t.Context()))
+	require.ErrorIs(t, app.Stop(t.Context()), errStopHook)
+
+	levels := map[string]string{}
+
+	decoder := json.NewDecoder(&out)
+	for decoder.More() {
+		var record struct {
+			Level string `json:"level"`
+			Msg   string `json:"msg"`
+		}
+
+		require.NoError(t, decoder.Decode(&record))
+
+		levels[record.Msg] = record.Level
+	}
+
+	assert.Equal(t, "DEBUG", levels["provided"])
+	assert.Equal(t, "INFO", levels["started"])
+	assert.Equal(t, "ERROR", levels["OnStop hook failed"])
+}