Send fx's own events through the service's logger (closes #183)
check / check (push) Successful in 3m39s
check / check (push) Successful in 3m39s
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
This commit is contained in:
@@ -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/
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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=
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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"])
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user