diff --git a/README.md b/README.md index 00de84b..dc5c6aa 100644 --- a/README.md +++ b/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 -`PROVIDE`/`RUN`/`HOOK` lines a boot writes, and under `docker run -d` +is ever shown: as one `INFO` record it would sit among the records fx +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 - on standard error. `fx` prints the dependency graph and the lifecycle - hooks through its default console logger at startup and shutdown — - nothing calls `fx.WithLogger`, and `fx.New` builds that logger over - `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a - panic in a background worker rather than in a request handler is the - case that reaches it, since nothing recovers those. Neither carries a - client-chosen value at a client-chosen length: the five `panic` calls - in this service are invariant guards over constants and over - `crypto/rand`. +- **The Go runtime**, the one writer that does not go through + `internal/logger`. The runtime writes an unrecovered panic or a fatal + error itself, as plain text on standard error, and that output cannot + be redirected. A panic in a background worker rather than in a request + handler is the case that reaches it, since nothing recovers those. It + carries no client-chosen value at a client-chosen length: the + service's own `panic` calls are invariant guards over constants and + over `crypto/rand`, apart from the one that hands + `http.ErrAbortHandler` back to `net/http`, described below. - **`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/ diff --git a/cmd/webhooker/main.go b/cmd/webhooker/main.go index 4ae11c1..fc84aba 100644 --- a/cmd/webhooker/main.go +++ b/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, diff --git a/go.mod b/go.mod index ba81406..4666c65 100644 --- a/go.mod +++ b/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.17.0 // indirect - go.uber.org/multierr v1.9.0 // indirect - go.uber.org/zap v1.23.0 // indirect + go.uber.org/dig v1.19.0 // indirect + go.uber.org/multierr v1.10.0 // indirect + go.uber.org/zap v1.26.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 diff --git a/go.sum b/go.sum index d2d615e..64bf4d3 100644 --- a/go.sum +++ b/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/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= -go.uber.org/dig v1.17.0 h1:5Chju+tUvcC+N7N6EV08BJz41UZuO3BmHcN4A287ZLI= -go.uber.org/dig v1.17.0/go.mod h1:rTxpf7l5I0eBTlE6/9RL+lDybC7WFwY2QH55ZSjy1mU= -go.uber.org/fx v1.20.1 h1:zVwVQGS8zYvhh9Xxcu4w1M6ESyeMzebzj2NbSayZ4Mk= -go.uber.org/fx v1.20.1/go.mod h1:iSYNbHf2y55acNCwCXKx7LbWb5WG1Bnue5RDXz1OREg= -go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI= -go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= -go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI= -go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ= -go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY= -go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY= +go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4= +go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE= +go.uber.org/fx v1.24.0 h1:wE8mruvpg2kiiL1Vqd0CC+tr0/24XIB10Iwp2lLWzkg= +go.uber.org/fx v1.24.0/go.mod h1:AmDeGyS+ZARGKM4tlH4FY2Jr63VjbEDJHtqXTGP5hbo= +go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk= +go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo= +go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ= +go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= +go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo= +go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so= 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= diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 63d5625..52692b0 100644 --- a/internal/logger/logger.go +++ b/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) + } +} diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go index ba47479..229dde7 100644 --- a/internal/logger/logger_test.go +++ b/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"]) +}