diff --git a/README.md b/README.md index 307976a..b5ece8b 100644 --- a/README.md +++ b/README.md @@ -557,8 +557,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 @@ -628,7 +628,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. @@ -2637,16 +2638,20 @@ 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**, which 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. +- **A failure before fx's logger is built**, such as an invalid + configuration value. fx's logger takes the configuration, so when + that fails fx's own console logger still prints the failure as plain + text on standard error. Its values come from the operator's + environment, not from a client. - **`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 @@ -2996,7 +3001,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..1d88d3c 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,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, diff --git a/cmd/webhooker/main_test.go b/cmd/webhooker/main_test.go index 98ca68e..851c4d8 100644 --- a/cmd/webhooker/main_test.go +++ b/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 — diff --git a/go.mod b/go.mod index 684de3d..ab6e2ef 100644 --- a/go.mod +++ b/go.mod @@ -20,7 +20,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 @@ -42,7 +42,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 @@ -51,10 +50,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.47.0 // indirect diff --git a/go.sum b/go.sum index 8c96a5e..7eb057a 100644 --- a/go.sum +++ b/go.sum @@ -1,7 +1,5 @@ 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= @@ -12,9 +10,6 @@ github.com/chromedp/chromedp v0.16.0 h1:rOO4deOm4CbZgBCa8mD9g2rDyIoNs0BkgvNrlbp5 github.com/chromedp/chromedp v0.16.0/go.mod h1:rbuGKFT1vMcFcFqKfPIO1GpX/N+2s8onm2qMxZLbU5U= github.com/chromedp/sysutil v1.1.0 h1:PUFNv5EcprjqXZD9nJb9b/c9ibAbxiYo4exNWZyipwM= github.com/chromedp/sysutil v1.1.0/go.mod h1:WiThHUdltqCNKGc4gaU50XgYjwjYIhKWoHGPTUfWTJ8= -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= @@ -83,7 +78,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= @@ -100,28 +94,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"]) +}