~bigbes/sr-ht-dolt

4d178626e1f2d04330127c394e0684a78a2d7102 — Eugene Blikh 9 days ago 6af5859
log: bridge dolt's remotesrv logger into slog

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.
M cmd/doltsrht/main.go => cmd/doltsrht/main.go +6 -0
@@ 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 {

A internal/logrusbridge/logrusbridge.go => internal/logrusbridge/logrusbridge.go +252 -0
@@ 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
	}
}

A internal/logrusbridge/logrusbridge_test.go => internal/logrusbridge/logrusbridge_test.go +220 -0
@@ 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{} }

M remoteapi/server.go => remoteapi/server.go +12 -4
@@ 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
}