From 4d178626e1f2d04330127c394e0684a78a2d7102 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Sat, 8 Aug 2026 23:13:23 +0300 Subject: [PATCH] log: bridge dolt's remotesrv logger into slog MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit remotesrv takes a *logrus.Entry and nothing else, so passing nil left it writing through logrus' standard logger: its own format, its own stream, and no mask between a field named token and the journal. It is the half of this process that serves clones and pushes — the likeliest place for a credential to reach a log field, and the one that was logging around everything the previous commit configured. internal/logrusbridge hands it an entry whose only exit is a logrus.Hook: output to io.Discard, a formatter that produces nothing, and the logrus level left wide open so the slog handler does the filtering from the one setting in config.ini. Fields cross as attributes rather than a formatted blob, which is what lets a mask keyed on the attribute path fire at all. Verified against logrus v1.9.3 rather than assumed: Entry.log fires hooks before it writes, before Logger.Exit and before the panic, so a Fatal or Panic record reaches slog before the process ends. Both arms are tested. The package takes nothing from this service and belongs beside scribe in auxilia; it is here because it was needed here first. --- cmd/doltsrht/main.go | 6 + internal/logrusbridge/logrusbridge.go | 252 +++++++++++++++++++++ internal/logrusbridge/logrusbridge_test.go | 220 ++++++++++++++++++ remoteapi/server.go | 16 +- 4 files changed, 490 insertions(+), 4 deletions(-) create mode 100644 internal/logrusbridge/logrusbridge.go create mode 100644 internal/logrusbridge/logrusbridge_test.go diff --git a/cmd/doltsrht/main.go b/cmd/doltsrht/main.go index 610f30c2ae816e6cad3856766505701330a08db0..4315c704f2d5b0ec86945f998844794b43bc43cf 100644 --- a/cmd/doltsrht/main.go +++ b/cmd/doltsrht/main.go @@ -38,6 +38,7 @@ import ( "sourcecraft.dev/bigbes/sr-ht-core/server" "sourcecraft.dev/bigbes/sr-ht-dolt/authn" + "sourcecraft.dev/bigbes/sr-ht-dolt/internal/logrusbridge" "sourcecraft.dev/bigbes/sr-ht-dolt/remoteapi" "sourcecraft.dev/bigbes/sr-ht-dolt/storage" "sourcecraft.dev/bigbes/sr-ht-dolt/web" @@ -175,6 +176,11 @@ func main() { ListenAddr: cfg.remotesapiAddr, CredsListenAddr: cfg.credsapiAddr, HttpHost: cfg.httpHost, + // dolt's remotesrv takes a *logrus.Entry and nothing else. Bridged, so + // that the half of this process serving clones and pushes reports + // through the same handler, at the same level and behind the same masks + // as the half we wrote. + DoltLogger: logrusbridge.Entry(), } rsrv, err := remoteapi.New(rapiConf) if err != nil { diff --git a/internal/logrusbridge/logrusbridge.go b/internal/logrusbridge/logrusbridge.go new file mode 100644 index 0000000000000000000000000000000000000000..a8440f9e6968c18cad6f2313ebd467a7fdc76b94 --- /dev/null +++ b/internal/logrusbridge/logrusbridge.go @@ -0,0 +1,252 @@ +// Package logrusbridge routes a logrus logger's records into log/slog. +// +// It exists for a shape of dependency that keeps recurring and has no good +// answer at the call site: a third-party library logs, and the only way it will +// accept a logger is as a *logrus.Entry. dolt's remotesrv is this service's +// example — its ServerArgs.Logger field is typed *logrus.Entry and nothing +// else — but the shape is not dolt's and not SourceHut's, which is why this is +// a general adapter rather than a line in the daemon's wiring. +// +// The reason to bridge rather than to leave the library logging on its own is +// not tidiness of format. A process that has configured one handler — a level, +// a destination, and above all a set of masks over the fields that may carry a +// credential — has configured it for the records it emits itself. Every record +// the third-party library writes goes around all of that: its own format, its +// own stream, its own idea of what is worth printing, and no mask between a +// field named "token" and the operator's journal. In a library that serves +// remote requests, the paths most likely to put a credential in a log line are +// exactly the ones this process did not write. Routing them through the same +// handler is what makes a masking rule a property of the process instead of a +// property of the code that remembered to use it. +// +// The bridge is a logrus.Hook, which is the seam logrus ships for precisely +// this, plus two settings that make the hook the *only* exit: the output goes +// to io.Discard and the formatter produces nothing, so no record is formatted +// on its way to being thrown away. +// +// The logrus logger is left at its most permissive level and the slog handler +// does the filtering. That is deliberate: it puts both halves of the process's +// output under one level, so raising the service's log level to debug reveals +// the bridged library's debug records too, from the same config key, instead of +// requiring a second knob nobody remembers exists. +// +// # Candidate for auxilia +// +// This belongs beside scribe in go.bigb.es/auxilia rather than in a service: it +// depends on nothing but logrus and the standard library, and any Go program +// with a logrus-shaped dependency wants it. It is here because it was needed +// here first. It does not belong in sr-ht-ecore — that is a SourceHut library, +// and this has nothing to do with SourceHut. +package logrusbridge + +import ( + "context" + "fmt" + "io" + "log/slog" + "os" + "slices" + "sync" + + "github.com/sirupsen/logrus" +) + +// An Option configures Entry and Hook. +type Option func(*config) + +type config struct { + target *slog.Logger +} + +// WithLogger sends the bridged records to l instead of to slog's default +// logger. +// +// The default is resolved at the moment a record is fired, not when the bridge +// is built, so a bridge constructed before slog.SetDefault still lands in the +// handler the process ends up with. Pass this only when the destination is not +// the process default — a test capturing records is the usual reason. +func WithLogger(l *slog.Logger) Option { + return func(c *config) { c.target = l } +} + +// Hook returns a logrus.Hook that forwards every record it is given to slog. +// +// Use it when the caller already holds a *logrus.Logger it wants redirected. +// Adding the hook does not stop that logger writing through its own formatter +// and output as well; silencing those is the caller's to do, and Entry is the +// version that has done it. +func Hook(opts ...Option) logrus.Hook { + var cfg config + for _, opt := range opts { + opt(&cfg) + } + return &hook{cfg: cfg} +} + +// Entry returns a *logrus.Entry whose every record goes to slog and nowhere +// else — the value to hand to a library that will accept nothing but one. +// +// The logger behind it is fresh rather than logrus' standard one: redirecting +// the standard logger would capture every other user of it in the process, +// which is a decision for that process and not for the library being handed +// this entry. +func Entry(opts ...Option) *logrus.Entry { + l := logrus.New() + // The two halves of "the hook is the only exit". Discarding the output + // alone would still pay for formatting every record on its way to nowhere, + // and the formatter is the expensive half. + l.SetOutput(io.Discard) + l.SetFormatter(noopFormatter{}) + // Everything reaches the hook; the slog handler decides what survives. + l.SetLevel(logrus.TraceLevel) + // Off, and worth saying why: logrus computes the caller by walking the + // stack on every record, and a library handed this entry may log per + // request. See hook.Fire for what happens if a caller turns it on anyway. + l.SetReportCaller(false) + l.AddHook(Hook(opts...)) + return logrus.NewEntry(l) +} + +// noopFormatter formats a record into nothing. A nil slice is a valid return: +// logrus writes it to the output, and io.Discard accepts it. +type noopFormatter struct{} + +func (noopFormatter) Format(*logrus.Entry) ([]byte, error) { return nil, nil } + +type hook struct { + cfg config + + // reported bounds the complaint about a panicking destination handler to + // one line for the life of the process. + reported sync.Once +} + +// Levels asks for every record. The filtering belongs to the slog handler, for +// the reason given in the package comment. +func (h *hook) Levels() []logrus.Level { return logrus.AllLevels } + +// Fire hands one logrus record to slog. +// +// It always returns nil. A non-nil error makes logrus print "Failed to fire +// hook" to os.Stderr, which is the one destination this bridge exists to keep +// records away from, and there is nothing a logging call can usefully do about +// its own failure anyway. +// +// It also never panics. This runs inside the logging path of a library that +// may be serving a request, so a panicking destination handler would otherwise +// take the request with it; losing a log line is the better of the two, and the +// once-only notice on stderr keeps a permanently broken handler from being +// silent forever. +func (h *hook) Fire(e *logrus.Entry) (err error) { + defer func() { + if r := recover(); r != nil { + h.reported.Do(func() { + fmt.Fprintf(os.Stderr, + "logrusbridge: the destination slog handler panicked, dropping bridged records: %v\n", r) + }) + } + err = nil + }() + + logger := h.cfg.target + if logger == nil { + logger = slog.Default() + } + + ctx := e.Context + if ctx == nil { + ctx = context.Background() + } + + level := Level(e.Level) + if !logger.Enabled(ctx, level) { + // Checked before the record is built rather than left to the handler: + // the logrus side is wide open, so a library's per-chunk debug line + // reaches here on every chunk and must cost an interface call, not an + // allocation and a sort. + return nil + } + + // The record's time is the entry's, which logrus stamps before it fires + // hooks. Taking time.Now() here would date every bridged record to when the + // bridge got round to it. + // + // The PC is zero, so a handler with source locations enabled prints none + // for a bridged record. That is the honest answer: the only PC this + // function could name is its own, inside logrus, which tells the reader + // nothing about where the line came from. When the caller has enabled + // ReportCaller the real frame is attached below as attributes instead — a + // runtime.Frame's PC is not the return address slog.Record expects, and a + // source location that is quietly one line off is worse than none. + rec := slog.NewRecord(e.Time, level, e.Message, 0) + + // Fields become attributes rather than a formatted blob. That is the whole + // point of routing through a structured handler: a mask keyed on the + // attribute path can only fire if the field is still an attribute when it + // gets there. + // + // Sorted, because a logrus.Fields is a map and its iteration order is + // random: unsorted, one library's records would shuffle their columns from + // line to line. + if len(e.Data) > 0 { + keys := make([]string, 0, len(e.Data)) + for k := range e.Data { + keys = append(keys, k) + } + slices.Sort(keys) + attrs := make([]slog.Attr, 0, len(keys)) + for _, k := range keys { + attrs = append(attrs, slog.Any(k, e.Data[k])) + } + rec.AddAttrs(attrs...) + } + + if e.Caller != nil { + rec.AddAttrs(slog.Group("source", + slog.String("file", e.Caller.File), + slog.Int("line", e.Caller.Line), + slog.String("function", e.Caller.Function), + )) + } + + // Handed to the handler rather than to logger.Log: the Logger methods build + // their own record, stamping it with the current time and with a PC walked + // out of this function's stack — the two things this bridge is carrying + // from somewhere else. Attributes and groups the caller put on the logger + // are on the handler it returns, so nothing is lost by going round it. + // + //nolint:errcheck // Handle's error has no reader; see the doc comment. + _ = logger.Handler().Handle(ctx, rec) + return nil +} + +// Level maps a logrus level onto the slog level that means the same thing. +// +// logrus has three levels above Error and slog has none: Fatal and Panic +// describe what logrus does *after* the record — exit, or panic — rather than +// how bad the record is, and both arrive here as errors because that is what +// they are. Trace and Debug both land on Debug for the same reason in reverse: +// slog draws no line there, and inventing one with a negative custom level +// would make "debug" in a config file mean different things on the two sides of +// the bridge. +// +// Both are delivered. logrus fires its hooks before it writes, before +// Logger.Exit and before the panic (verified against logrus v1.9.3, +// Entry.log), so a record that ends the process still reaches slog first. +func Level(l logrus.Level) slog.Level { + switch l { + case logrus.TraceLevel, logrus.DebugLevel: + return slog.LevelDebug + case logrus.InfoLevel: + return slog.LevelInfo + case logrus.WarnLevel: + return slog.LevelWarn + case logrus.ErrorLevel, logrus.FatalLevel, logrus.PanicLevel: + return slog.LevelError + default: + // logrus defines no other level. An unknown one is treated as the most + // serious rather than the least, so a level added upstream shows up + // instead of disappearing. + return slog.LevelError + } +} diff --git a/internal/logrusbridge/logrusbridge_test.go b/internal/logrusbridge/logrusbridge_test.go new file mode 100644 index 0000000000000000000000000000000000000000..34d14f6a2995785bcb890ebe67cdfe24b6289cb4 --- /dev/null +++ b/internal/logrusbridge/logrusbridge_test.go @@ -0,0 +1,220 @@ +package logrusbridge + +import ( + "bytes" + "context" + "log/slog" + "sync" + "testing" + "time" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "go.bigb.es/auxilia/scribe" +) + +// capture is a slog.Handler that keeps the records it is given, so a test can +// assert on the record itself — its time above all — rather than on a +// handler's rendering of it. +type capture struct { + mu sync.Mutex + level slog.Level + records []slog.Record +} + +func (c *capture) Enabled(_ context.Context, l slog.Level) bool { return l >= c.level } + +func (c *capture) Handle(_ context.Context, r slog.Record) error { + c.mu.Lock() + defer c.mu.Unlock() + c.records = append(c.records, r.Clone()) + return nil +} + +func (c *capture) WithAttrs([]slog.Attr) slog.Handler { return c } +func (c *capture) WithGroup(string) slog.Handler { return c } + +func (c *capture) only(t *testing.T) slog.Record { + t.Helper() + c.mu.Lock() + defer c.mu.Unlock() + require.Len(t, c.records, 1, "expected exactly one bridged record") + return c.records[0] +} + +// attrs flattens a record's attributes into a map for assertions. +func attrs(r slog.Record) map[string]any { + m := make(map[string]any, r.NumAttrs()) + r.Attrs(func(a slog.Attr) bool { + m[a.Key] = a.Value.Any() + return true + }) + return m +} + +// The record that comes out the slog side is the one that went in the logrus +// side: same level, same message, same fields as attributes, and the time the +// record was made rather than the time the bridge got to it. +func TestBridgedRecordKeepsLevelMessageFieldsAndTime(t *testing.T) { + c := &capture{level: slog.LevelDebug} + e := Entry(WithLogger(slog.New(c))) + + made := time.Date(2026, 8, 8, 12, 0, 0, 0, time.UTC) + e.WithTime(made). + WithFields(logrus.Fields{"repo": "~alice/widgets", "chunks": 3}). + Warn("chunk transfer stalled") + + rec := c.only(t) + assert.Equal(t, slog.LevelWarn, rec.Level) + assert.Equal(t, "chunk transfer stalled", rec.Message) + assert.True(t, rec.Time.Equal(made), "record time %s, want %s", rec.Time, made) + + got := attrs(rec) + assert.Equal(t, "~alice/widgets", got["repo"]) + assert.EqualValues(t, 3, got["chunks"]) + assert.Len(t, got, 2, "fields must arrive as attributes and nothing else") +} + +// A field is an attribute by the time it reaches the handler, which is the only +// reason a mask can fire on it. This is the property the bridge exists for: a +// credential in a third-party library's log field is masked by the process's +// own rules rather than printed around them. +func TestASensitiveFieldIsMaskedByTheDestinationHandler(t *testing.T) { + var buf bytes.Buffer + dest := slog.New(scribe.NewTintHandler( + scribe.WithWriter(&buf), + scribe.WithLevel(slog.LevelDebug), + scribe.WithNoColor(true), + scribe.WithMaskKeys("token", "authorization"), + )) + + e := Entry(WithLogger(dest)) + e.WithFields(logrus.Fields{ + "token": "s3cret-working-token", + "authorization": "Bearer s3cret-jwt", + "repo": "~alice/widgets", + }).Error("upload refused") + + out := buf.String() + assert.NotContains(t, out, "s3cret-working-token") + assert.NotContains(t, out, "s3cret-jwt") + assert.Contains(t, out, "***") + assert.Contains(t, out, "~alice/widgets", "an unmasked field must still be readable") +} + +func TestLevelMapping(t *testing.T) { + for _, tc := range []struct { + in logrus.Level + want slog.Level + }{ + {logrus.TraceLevel, slog.LevelDebug}, + {logrus.DebugLevel, slog.LevelDebug}, + {logrus.InfoLevel, slog.LevelInfo}, + {logrus.WarnLevel, slog.LevelWarn}, + {logrus.ErrorLevel, slog.LevelError}, + {logrus.FatalLevel, slog.LevelError}, + {logrus.PanicLevel, slog.LevelError}, + } { + assert.Equal(t, tc.want, Level(tc.in), "logrus %s", tc.in) + } +} + +// The logrus side is left wide open so that the slog handler decides what +// survives: raising the service's log level must reveal the bridged library's +// debug records too, from the same setting. +func TestTheSlogHandlerDoesTheFiltering(t *testing.T) { + quiet := &capture{level: slog.LevelWarn} + e := Entry(WithLogger(slog.New(quiet))) + + e.Debug("per-chunk noise") + e.Info("also below the bar") + quiet.mu.Lock() + assert.Empty(t, quiet.records, "the destination's level must gate bridged records") + quiet.mu.Unlock() + + e.Warn("this one counts") + assert.Equal(t, "this one counts", quiet.only(t).Message) + + // And the logrus logger itself must not be the one filtering, or the two + // halves of the process would need two settings. + assert.Equal(t, logrus.TraceLevel, e.Logger.GetLevel()) +} + +// The hook is the only exit: nothing is formatted and nothing is written the +// logrus way, so the destination handler is the whole of the output. +func TestNothingLeavesThroughLogrus(t *testing.T) { + c := &capture{level: slog.LevelDebug} + e := Entry(WithLogger(slog.New(c))) + + var buf bytes.Buffer + e.Logger.SetOutput(&buf) // stand in for io.Discard so we can look at it + + e.Info("hello") + + assert.Empty(t, buf.String(), "the formatter must produce nothing") + assert.Equal(t, "hello", c.only(t).Message) +} + +// logrus fires its hooks before it writes, before Logger.Exit and before the +// panic, so a record that ends the process still reaches slog first. Verified +// here rather than trusted, because it is the arm nobody would notice missing +// until they were reading a crash without its last line. +func TestFatalAndPanicRecordsReachTheHook(t *testing.T) { + t.Run("fatal", func(t *testing.T) { + c := &capture{level: slog.LevelDebug} + e := Entry(WithLogger(slog.New(c))) + exited := false + e.Logger.ExitFunc = func(int) { exited = true } + + e.Fatal("cannot serve") + + assert.True(t, exited, "logrus must still exit after the hook") + rec := c.only(t) + assert.Equal(t, slog.LevelError, rec.Level) + assert.Equal(t, "cannot serve", rec.Message) + }) + + t.Run("panic", func(t *testing.T) { + c := &capture{level: slog.LevelDebug} + e := Entry(WithLogger(slog.New(c))) + + assert.Panics(t, func() { e.Panic("unrecoverable") }) + + rec := c.only(t) + assert.Equal(t, slog.LevelError, rec.Level) + assert.Equal(t, "unrecoverable", rec.Message) + }) +} + +// The default logger is resolved when the record fires and not when the bridge +// is built, so a bridge handed to a library during startup still lands in the +// handler the process installs. +func TestTheDefaultLoggerIsResolvedWhenTheRecordFires(t *testing.T) { + previous := slog.Default() + t.Cleanup(func() { slog.SetDefault(previous) }) + + e := Entry() // built before the default is installed + + c := &capture{level: slog.LevelDebug} + slog.SetDefault(slog.New(c)) + + e.Info("late binding") + assert.Equal(t, "late binding", c.only(t).Message) +} + +// A destination that panics costs a log line and not the request it was logging. +func TestAPanickingDestinationDoesNotEscape(t *testing.T) { + e := Entry(WithLogger(slog.New(panicHandler{}))) + assert.NotPanics(t, func() { e.Info("into the void") }) +} + +type panicHandler struct{} + +func (panicHandler) Enabled(context.Context, slog.Level) bool { return true } +func (panicHandler) Handle(context.Context, slog.Record) error { + panic("the handler is broken") +} +func (panicHandler) WithAttrs([]slog.Attr) slog.Handler { return panicHandler{} } +func (panicHandler) WithGroup(string) slog.Handler { return panicHandler{} } diff --git a/remoteapi/server.go b/remoteapi/server.go index 15b7ffc1cc5e63502698b4b0fa3a68e56b9233d6..b293d5ba3deb71b84fb92fd8dfcb459b7c54308d 100644 --- a/remoteapi/server.go +++ b/remoteapi/server.go @@ -51,10 +51,18 @@ type Config struct { // chunk URLs (auth then cannot be host-checked; used only by tests without a // stable host). HttpHost string - // DoltLogger is the logger dolt's own remotesrv writes through. It exists - // only because that API takes a *logrus.Entry and nothing else; everything - // this package logs itself goes through slog's default. nil lets remotesrv - // install logrus' standard logger, which is what it did before. + // DoltLogger is the logger dolt's own remotesrv writes through. It is a + // *logrus.Entry because that API takes nothing else; everything this + // package logs itself goes through slog's default. + // + // The daemon passes logrusbridge.Entry(), which routes remotesrv's records + // into the same slog handler as ours. That is not cosmetic: remotesrv is + // the code serving remote clone and push traffic, so it is the likeliest + // place in this process for a credential to reach a log field, and a + // logger of its own would put those records past the masks. A nil entry + // lets remotesrv install logrus' standard logger and log around + // everything — acceptable in a test that only wants it quiet, not in the + // daemon. DoltLogger *logrus.Entry }