~bigbes/sr-ht-dolt

ref: 4d178626e1f2d04330127c394e0684a78a2d7102 sr-ht-dolt/internal/logrusbridge/logrusbridge.go -rw-r--r-- 10.0 KiB
4d178626 — Eugene Blikh log: bridge dolt's remotesrv logger into slog 9 days ago
                                                                                
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
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
	}
}