coverage — ~bigbes/sr-ht-ecore — 89fa694c — logging/logging.go

Coverage
94.9% 56/59 statements
Δ
+0.0
Blob
f866996
Uncovered L356-L357L363-L364L387
1 // Package logging is the log policy of a self-hosted SourceHut instance: the
2 // verbosity, the source positions, the colour decision, and — the part that is
3 // not presentation — the set of attribute keys that must never reach a log
4 // file.
5 //
6 // It exists because the rest of sr-ht-ecore already depends on the answer.
7 // [sourcecraft.dev/bigbes/sr-ht-ecore/middleware.RecoverPanics] reports a
8 // recovered panic through slog's *default* logger, because a middleware living
9 // in another module has no constructor
10 // through which the service could hand it one. A service that never calls
11 // slog.SetDefault still logs those reports — through Go's plain stderr handler,
12 // unlevelled, unmasked, and in a different format from every other line in the
13 // same journal. Until now ecore needed that and could not say so.
14 //
15 // The second half is policy rather than taste. Six services of this instance
16 // (compare, spec, dolt, cover, bench, tokens) each grew the same forty lines in
17 // their main.go: the same level parser, the same os.Stderr.Stat colour probe,
18 // and six separately maintained copies of the credential mask list. The copies
19 // had already drifted — three different key sets and three different patterns,
20 // with one service masking a DSN that the other five did not know was a
21 // credential and another masking the private keys that the rest did not. What
22 // is being redacted (the instance's unified-login cookie, tokens.sr.ht's
23 // working tokens, the Authorization header they travel in) is a fact about the
24 // instance, not about any one service, so it is maintained once here.
25 //
26 // # The handler stays with the caller
27 //
28 // Every service on this instance installs auxilia's scribe.TintHandler, and
29 // this package deliberately does not build it. ecore is a small SourceHut-
30 // specific library, auxilia is a large general one, and linking scribe into
31 // every consumer of chrome, csrf and middleware in order to share a list of
32 // masked keys would be the wrong trade — a service that wants a JSON handler
33 // for a log shipper should not have to link a tinting one. So the policy is
34 // resolved here and the handler is constructed there:
35 //
36 // opts := logging.Defaults(conf, "dolt.sr.ht")
37 // logging.Install(scribe.NewTintHandler(
38 // scribe.WithWriter(os.Stderr),
39 // scribe.WithLevel(opts.Level),
40 // scribe.WithSource(opts.AddSource),
41 // scribe.WithTimeFormat(opts.TimeFormat),
42 // scribe.WithNoColor(!opts.Color),
43 // scribe.WithMaskKeys(opts.MaskKeys...),
44 // scribe.WithMask(opts.MaskPattern, opts.MaskReplacement),
45 // ))
46 //
47 // The masking is not scribe's to own either: [Options.ReplaceAttr] applies the
48 // same rules through stdlib slog alone, so a service on a JSON handler gets the
49 // instance's redaction without importing anything.
50 //
51 // logging.Install(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
52 // Level: opts.Level,
53 // AddSource: opts.AddSource,
54 // ReplaceAttr: opts.ReplaceAttr(),
55 // }))
56 //
57 // [Install] belongs in main and nowhere else: slog's default logger is
58 // process-global state, so a package that set it would be deciding for
59 // everything else that was linked alongside it.
60 package logging
61
62 import (
63 "log/slog"
64 "os"
65 "regexp"
66 "slices"
67 "strings"
68 "time"
69
70 "github.com/vaughan0/go-ini"
71
72 "sourcecraft.dev/bigbes/sr-ht-core/config"
73 )
74
75 const (
76 // LevelEnv is the environment variable that names the verbosity for one
77 // run. It is what an operator reaches for from a shell or a systemd
78 // Environment= line, and it overrides [LevelKey].
79 LevelEnv = "LOG_LEVEL"
80
81 // LevelKey is the config.ini key holding the instance's persistent
82 // verbosity, read from the service's own section: `log-level=info`. It is
83 // the setting an operator writes down; [LevelEnv] and -d are the ones they
84 // pass for a single run.
85 LevelKey = "log-level"
86
87 // TimeFormat is the timestamp every service prints. The sortable form
88 // rather than RFC 3339: under systemd the journal stamps its own arrival
89 // time beside this one, and two RFC 3339 stamps per line is a line nobody
90 // reads to the end.
91 TimeFormat = time.DateTime
92
93 // MaskReplacement is what a masked value is printed as.
94 MaskReplacement = "***"
95
96 // MaskPattern matches the attribute key *path* of a value that must not be
97 // logged — "token", "user.password", "req.headers.authorization". It is the
98 // union of the patterns the six services had each arrived at separately,
99 // and it is a pattern rather than a list because the credential that leaks
100 // is the attribute somebody adds next year under a name nobody thought to
101 // add to a list.
102 //
103 // It matches the key and never the message, so prose that happens to
104 // contain the word "token" costs nothing and cannot be used to defeat it.
105 //
106 // Note that this masks `token_id` as well, which tokens.sr.ht's local copy
107 // deliberately did not — a row id is what correlates two lines about one
108 // credential. The instance-wide default errs the other way, because the
109 // failure it is guarding against is a live credential in a log file and the
110 // failure it causes is an id that has to be logged under a key not
111 // containing "token" (`id` is the better name for it anyway).
112 MaskPattern = `(?i)(secret|token|api_?key|password|pubkey|credential|dsn|authorization|cookie)`
113
114 // PartialMaskPattern and PartialMaskKeep are tokens.sr.ht's correlation
115 // exception and are NOT part of [Defaults]: a key that is or ends in
116 // "token" or "secret" keeps its first six characters instead of being
117 // replaced whole, which is enough to line two log lines up against each
118 // other and useless to anybody who wants to present the credential.
119 //
120 // It is opt-in because it is strictly weaker than the default — six
121 // characters of a live working token is still six characters of a live
122 // working token, and only a service whose whole subject is credentials has
123 // enough to gain from it to pay that. Such a service installs it *before*
124 // the rules of [Defaults], because the first matching rule wins and the
125 // blanket rule would otherwise swallow the prefix this exists to keep:
126 //
127 // scribe.WithMaskPartial(logging.PartialMaskPattern, logging.PartialMaskKeep),
128 // scribe.WithMaskKeys(opts.MaskKeys...),
129 // scribe.WithMask(opts.MaskPattern, opts.MaskReplacement),
130 PartialMaskPattern = `(?i)(^|[._-])(token|secret)$`
131 PartialMaskKeep = 6
132 )
133
134 // maskKeys is the exact-key half of the policy: the credentials this instance's
135 // services are known to handle today, named as they are named in the code.
136 //
137 // Both halves are installed because they fail differently — the list covers
138 // what is named now and cannot be worked around by an unlucky regexp, and
139 // [MaskPattern] covers what gets named later. Every entry here was in at least
140 // one of the six services' lists, and no service had all of them.
141 var maskKeys = []string{
142 // The unified-login session cookie and the header it arrives in, which
143 // every service of this instance reads (SPEC ch. 6).
144 "cookie",
145 "authorization",
146
147 // tokens.sr.ht working tokens and the generic credential names services
148 // pass them under.
149 "token",
150 "api_key",
151 "apikey",
152 "password",
153
154 // Keys out of config.ini that a startup line is likely to echo.
155 "network-key",
156 "private-key",
157
158 // The connection string of a migration binary, which carries a password.
159 "dsn",
160 "data_source_name",
161 }
162
163 // MaskKeys returns the instance's masked attribute keys, ready to be handed to
164 // a handler in one line:
165 //
166 // scribe.WithMaskKeys(logging.MaskKeys()...)
167 //
168 // It is a function returning a fresh slice rather than an exported variable
169 // because a mask set that any linked package can append to or truncate is not a
170 // policy.
171 18 func MaskKeys() []string {
172 18 return slices.Clone(maskKeys)
173 18 }
174
175 // Options is everything about logging that the services of one instance decide
176 // identically. [Defaults] resolves it; the caller spends it on the handler of
177 // its choice.
178 type Options struct {
179 // Level is the resolved verbosity — see [Defaults] for where it comes from.
180 Level slog.Level
181
182 // AddSource asks for file:line on every record. It is on by default: what
183 // reaches these logs is mostly a failure nobody can reproduce, and "which
184 // of the six render sites said this" is the first question about each one.
185 AddSource bool
186
187 // Color reports whether escape sequences are wanted, resolved from NO_COLOR
188 // and from whether stderr is a terminal. Handlers usually ask the inverse
189 // question, hence scribe.WithNoColor(!opts.Color).
190 Color bool
191
192 // TimeFormat is the timestamp layout, [TimeFormat] by default.
193 TimeFormat string
194
195 // MaskKeys, MaskPattern and MaskReplacement are the redaction policy, in
196 // the order a handler should install them. Both matchers run against the
197 // attribute's key path, never against its value or the message.
198 MaskKeys []string
199 MaskPattern string
200 MaskReplacement string
201 }
202
203 // Defaults resolves the instance's logging policy, reading the service's own
204 // section of config.ini for [LevelKey].
205 //
206 // The verbosity has three sources, strongest first:
207 //
208 // - `-d` in the argument vector, which every SourceHut daemon takes as its
209 // debug flag;
210 // - $LOG_LEVEL, for one run;
211 // - [section]log-level in config.ini, the instance's persistent setting.
212 //
213 // A value none of them can read — including the empty string of an unset
214 // variable — falls through to the next source, and info if there is none. It is
215 // operator input: a typo in a logging preference must never be the reason a
216 // service will not boot.
217 //
218 // -d is read straight out of os.Args rather than taken as a parameter because
219 // of when this is called. core-go's server.New parses the argument vector, but
220 // it runs after config loading and validation, and a daemon that becomes
221 // verbose only once it has finished starting is silent for exactly the window
222 // an operator passes -d to watch. A service that installs its logger before
223 // loading config calls Defaults(nil, "") — -d and $LOG_LEVEL still resolve, and
224 // the config file has nothing to say yet.
225 10 func Defaults(conf ini.File, section string) Options {
226 10 return defaults(resolveLevel(conf, section, true))
227 10 }
228
229 // DefaultsWithoutDebugFlag is Defaults for a binary whose -d is not the
230 // daemon's.
231 //
232 // A migration CLI on this instance passes -d to brant, where it means
233 // --dialect and takes a value: `coversrht-migrate -d postgres` would otherwise
234 // arrive here as a request for debug logging, silently, because the probe sees
235 // the flag and never the value. $LOG_LEVEL and the config key still resolve —
236 // only the argument scan is dropped, which is the one source that cannot tell
237 // the two meanings apart.
238 2 func DefaultsWithoutDebugFlag(conf ini.File, section string) Options {
239 2 return defaults(resolveLevel(conf, section, false))
240 2 }
241
242 12 func defaults(level slog.Level) Options {
243 12 return Options{
244 12 Level: level,
245 12 AddSource: true,
246 12 Color: ColorEnabled(os.Stderr),
247 12 TimeFormat: TimeFormat,
248 12 MaskKeys: MaskKeys(),
249 12 MaskPattern: MaskPattern,
250 12 MaskReplacement: MaskReplacement,
251 12 }
252 12 }
253
254 // resolveLevel walks the three sources of verbosity in order of authority.
255 // debugFlag is false for a binary whose -d belongs to something else.
256 12 func resolveLevel(conf ini.File, section string, debugFlag bool) slog.Level {
257 12 if debugFlag && DebugRequested(os.Args[1:]) {
258 3 return slog.LevelDebug
259 3 }
260 9 if level, ok := ParseLevel(os.Getenv(LevelEnv)); ok {
261 2 return level
262 2 }
263 7 if section != "" {
264 3 if level, ok := ParseLevel(config.GetString(conf, section, LevelKey, "")); ok {
265 2 return level
266 2 }
267 }
268 5 return slog.LevelInfo
269 }
270
271 // ParseLevel reads a verbosity name — "debug", "info", "warn" (or "warning"),
272 // "error" — case and surrounding space insensitively. The second result reports
273 // whether the name was one of those, which is what lets a caller tell "the
274 // operator did not say" from "the operator said something unreadable" and
275 // degrade rather than refuse.
276 25 func ParseLevel(s string) (slog.Level, bool) {
277 25 switch strings.ToLower(strings.TrimSpace(s)) {
278 2 case "debug":
279 2 return slog.LevelDebug, true
280 1 case "info":
281 1 return slog.LevelInfo, true
282 6 case "warn", "warning":
283 6 return slog.LevelWarn, true
284 2 case "error":
285 2 return slog.LevelError, true
286 14 default:
287 14 return slog.LevelInfo, false
288 }
289 }
290
291 // DebugRequested reports whether the argument vector (without argv[0]) carries
292 // SourceHut's -d debug flag.
293 //
294 // Only the standalone token counts, which is what all six services did by hand;
295 // recognising a clustered "-bd" would mean reproducing core-go's getopt here,
296 // against an argument vector core-go is about to parse properly anyway. A "--"
297 // ends the scan: what follows it is an operand, not a flag.
298 18 func DebugRequested(args []string) bool {
299 18 for _, arg := range args {
300 16 if arg == "--" {
301 1 return false
302 1 }
303 15 if arg == "-d" {
304 6 return true
305 6 }
306 }
307 11 return false
308 }
309
310 // ColorEnabled reports whether escape sequences should be written to f.
311 //
312 // NO_COLOR disables them whatever it is set to, which is what the convention at
313 // no-color.org asks for: its presence is the signal and its value means
314 // nothing, so NO_COLOR=0 disables colour exactly as NO_COLOR=1 does. Otherwise
315 // the question is whether f is a character device — a terminal is, and the
316 // pipe, file or journal socket that systemd, a container and a shell redirect
317 // hand a daemon are not. One Stat answers it, which is cheaper than taking
318 // golang.org/x/term as a dependency for one bit.
319 20 func ColorEnabled(f *os.File) bool {
320 20 if _, set := os.LookupEnv("NO_COLOR"); set {
321 4 return false
322 4 }
323 16 info, err := f.Stat()
324 16 if err != nil {
325 1 return false
326 1 }
327 15 return info.Mode()&os.ModeCharDevice != 0
328 }
329
330 // ReplaceAttr compiles the masking policy into a slog.HandlerOptions.
331 // ReplaceAttr function, so that a service on a stdlib handler redacts exactly
332 // what a service on scribe's tint handler redacts:
333 //
334 // slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
335 // Level: opts.Level,
336 // AddSource: opts.AddSource,
337 // ReplaceAttr: opts.ReplaceAttr(),
338 // })
339 //
340 // The rules are compiled once, here, rather than per record; the key matching
341 // mirrors scribe's, so an attribute is redacted however deeply it is nested and
342 // whatever the caller believed it was logging. Returns nil — a valid
343 // ReplaceAttr meaning "no substitution" — when the policy is empty.
344 //
345 // An unparseable [Options.MaskPattern] panics, on this call, in main. A mask
346 // rule that silently did not compile would be a redaction that silently does
347 // not happen.
348 4 func (o Options) ReplaceAttr() func(groups []string, a slog.Attr) slog.Attr {
349 4 rules := o.maskRules()
350 4 if len(rules) == 0 {
351 1 return nil
352 1 }
353
354 2 replacement := o.MaskReplacement
355 2 if replacement == "" {
356 0 replacement = MaskReplacement
357 0 }
358
359 30 return func(groups []string, a slog.Attr) slog.Attr {
360 30 // A group's own attribute carries no value to mask; its contents each
361 30 // arrive here separately, with the group name in groups.
362 30 if a.Value.Kind() == slog.KindGroup {
363 0 return a
364 0 }
365
366 30 key := a.Key
367 30 if len(groups) > 0 {
368 2 key = strings.Join(groups, ".") + "." + a.Key
369 2 }
370 91 for _, rule := range rules {
371 91 if rule.MatchString(key) {
372 19 return slog.String(a.Key, replacement)
373 19 }
374 }
375 11 return a
376 }
377 }
378
379 // maskRules compiles the key list and the pattern into one ordered rule set.
380 // The key patterns are built the way scribe builds them — anchored to a path
381 // separator on both sides, case-insensitively — so that the two handlers cannot
382 // disagree about what "cookie" matches.
383 4 func (o Options) maskRules() []*regexp.Regexp {
384 4 rules := make([]*regexp.Regexp, 0, len(o.MaskKeys)+1)
385 10 for _, key := range o.MaskKeys {
386 10 if key == "" {
387 0 continue
388 }
389 10 rules = append(rules, regexp.MustCompile(`(?i)(^|\.|\])`+regexp.QuoteMeta(key)+`($|\.|\[)`))
390 }
391 4 if o.MaskPattern != "" {
392 3 rules = append(rules, regexp.MustCompile(o.MaskPattern))
393 3 }
394 3 return rules
395 }
396
397 // Install makes h the handler of slog's default logger and returns that logger,
398 // for the callers that would rather pass a logger than reach for the global.
399 //
400 // This is the line the rest of ecore is waiting for.
401 // [sourcecraft.dev/bigbes/sr-ht-ecore/middleware.RecoverPanics] reports through
402 // the default logger and takes no logger of its own, so a
403 // binary that builds a handler and does not install it has its panic reports —
404 // and only those — come out in Go's plain format, with none of the masking
405 // below applied. slog.SetDefault also redirects the standard log package's
406 // output into h, so a dependency that still writes through "log" lands in the
407 // same stream.
408 //
409 // Call it from main, once, before anything logs.
410 2 func Install(h slog.Handler) *slog.Logger {
411 2 if h == nil {
412 1 panic("logging: Install called with a nil handler")
413 }
414 1 log := slog.New(h)
415 1 slog.SetDefault(log)
416 1 return log
417 }