coverage — ~bigbes/sr-ht-ecore — 9a4d2ed9 — logging/logging.go

Coverage
94.9% 56/59 statements
Δ
+0.0
Blob
f8c7309
Uncovered L375-L376L382-L383L406
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. Most entries here came from the
140 // six donor services, each of which had some of them and none of which had them
141 // all; the rest were added afterwards, one per credential seen in a log file,
142 // and each of those says where it leaked.
143 //
144 // The entries the pattern half already matches are kept anyway. They cost one
145 // regexp each and they are what survives somebody narrowing that pattern:
146 // dropping a name from a list is a decision, while a name quietly falling out
147 // of an alternation is an edit.
148 var maskKeys = []string{
149 // The unified-login session cookie and the header it arrives in, which
150 // every service of this instance reads (SPEC ch. 6).
151 "cookie",
152 "authorization",
153
154 // tokens.sr.ht working tokens and the generic credential names services
155 // pass them under.
156 "token",
157 "api_key",
158 "apikey",
159 "password",
160
161 // Keys out of config.ini that a startup line is likely to echo.
162 "network-key",
163 "private-key",
164
165 // The connection string of a migration binary, which carries a password.
166 //
167 // "datasource" is not a third spelling somebody might use — it is the
168 // spelling brant v0.5.1 writes (cli/cli.go, `slog.Error("failed to create
169 // provider", "datasource", a.DataSourceName, ...)`), and every migrate
170 // binary on this instance wraps brant. Neither half of the policy caught
171 // it: [MaskPattern]'s dsn arm is a substring match and "datasource" does
172 // not contain "dsn", while the key rules below are anchored to a whole path
173 // segment, so the "dsn" entry does not reach it either. Found in
174 // snip.sr.ht, where the missing-migrations-directory case — the state an
175 // installed package is in until its first migration ships — printed a
176 // production password at ERR level.
177 "dsn",
178 "data_source_name",
179 "datasource",
180 }
181
182 // MaskKeys returns the instance's masked attribute keys, ready to be handed to
183 // a handler in one line:
184 //
185 // scribe.WithMaskKeys(logging.MaskKeys()...)
186 //
187 // It is a function returning a fresh slice rather than an exported variable
188 // because a mask set that any linked package can append to or truncate is not a
189 // policy.
190 20 func MaskKeys() []string {
191 20 return slices.Clone(maskKeys)
192 20 }
193
194 // Options is everything about logging that the services of one instance decide
195 // identically. [Defaults] resolves it; the caller spends it on the handler of
196 // its choice.
197 type Options struct {
198 // Level is the resolved verbosity — see [Defaults] for where it comes from.
199 Level slog.Level
200
201 // AddSource asks for file:line on every record. It is on by default: what
202 // reaches these logs is mostly a failure nobody can reproduce, and "which
203 // of the six render sites said this" is the first question about each one.
204 AddSource bool
205
206 // Color reports whether escape sequences are wanted, resolved from NO_COLOR
207 // and from whether stderr is a terminal. Handlers usually ask the inverse
208 // question, hence scribe.WithNoColor(!opts.Color).
209 Color bool
210
211 // TimeFormat is the timestamp layout, [TimeFormat] by default.
212 TimeFormat string
213
214 // MaskKeys, MaskPattern and MaskReplacement are the redaction policy, in
215 // the order a handler should install them. Both matchers run against the
216 // attribute's key path, never against its value or the message.
217 MaskKeys []string
218 MaskPattern string
219 MaskReplacement string
220 }
221
222 // Defaults resolves the instance's logging policy, reading the service's own
223 // section of config.ini for [LevelKey].
224 //
225 // The verbosity has three sources, strongest first:
226 //
227 // - `-d` in the argument vector, which every SourceHut daemon takes as its
228 // debug flag;
229 // - $LOG_LEVEL, for one run;
230 // - [section]log-level in config.ini, the instance's persistent setting.
231 //
232 // A value none of them can read — including the empty string of an unset
233 // variable — falls through to the next source, and info if there is none. It is
234 // operator input: a typo in a logging preference must never be the reason a
235 // service will not boot.
236 //
237 // -d is read straight out of os.Args rather than taken as a parameter because
238 // of when this is called. core-go's server.New parses the argument vector, but
239 // it runs after config loading and validation, and a daemon that becomes
240 // verbose only once it has finished starting is silent for exactly the window
241 // an operator passes -d to watch. A service that installs its logger before
242 // loading config calls Defaults(nil, "") — -d and $LOG_LEVEL still resolve, and
243 // the config file has nothing to say yet.
244 11 func Defaults(conf ini.File, section string) Options {
245 11 return defaults(resolveLevel(conf, section, true))
246 11 }
247
248 // DefaultsWithoutDebugFlag is Defaults for a binary whose -d is not the
249 // daemon's.
250 //
251 // A migration CLI on this instance passes -d to brant, where it means
252 // --dialect and takes a value: `coversrht-migrate -d postgres` would otherwise
253 // arrive here as a request for debug logging, silently, because the probe sees
254 // the flag and never the value. $LOG_LEVEL and the config key still resolve —
255 // only the argument scan is dropped, which is the one source that cannot tell
256 // the two meanings apart.
257 2 func DefaultsWithoutDebugFlag(conf ini.File, section string) Options {
258 2 return defaults(resolveLevel(conf, section, false))
259 2 }
260
261 13 func defaults(level slog.Level) Options {
262 13 return Options{
263 13 Level: level,
264 13 AddSource: true,
265 13 Color: ColorEnabled(os.Stderr),
266 13 TimeFormat: TimeFormat,
267 13 MaskKeys: MaskKeys(),
268 13 MaskPattern: MaskPattern,
269 13 MaskReplacement: MaskReplacement,
270 13 }
271 13 }
272
273 // resolveLevel walks the three sources of verbosity in order of authority.
274 // debugFlag is false for a binary whose -d belongs to something else.
275 13 func resolveLevel(conf ini.File, section string, debugFlag bool) slog.Level {
276 13 if debugFlag && DebugRequested(os.Args[1:]) {
277 3 return slog.LevelDebug
278 3 }
279 10 if level, ok := ParseLevel(os.Getenv(LevelEnv)); ok {
280 2 return level
281 2 }
282 8 if section != "" {
283 3 if level, ok := ParseLevel(config.GetString(conf, section, LevelKey, "")); ok {
284 2 return level
285 2 }
286 }
287 6 return slog.LevelInfo
288 }
289
290 // ParseLevel reads a verbosity name — "debug", "info", "warn" (or "warning"),
291 // "error" — case and surrounding space insensitively. The second result reports
292 // whether the name was one of those, which is what lets a caller tell "the
293 // operator did not say" from "the operator said something unreadable" and
294 // degrade rather than refuse.
295 26 func ParseLevel(s string) (slog.Level, bool) {
296 26 switch strings.ToLower(strings.TrimSpace(s)) {
297 2 case "debug":
298 2 return slog.LevelDebug, true
299 1 case "info":
300 1 return slog.LevelInfo, true
301 6 case "warn", "warning":
302 6 return slog.LevelWarn, true
303 2 case "error":
304 2 return slog.LevelError, true
305 15 default:
306 15 return slog.LevelInfo, false
307 }
308 }
309
310 // DebugRequested reports whether the argument vector (without argv[0]) carries
311 // SourceHut's -d debug flag.
312 //
313 // Only the standalone token counts, which is what all six services did by hand;
314 // recognising a clustered "-bd" would mean reproducing core-go's getopt here,
315 // against an argument vector core-go is about to parse properly anyway. A "--"
316 // ends the scan: what follows it is an operand, not a flag.
317 19 func DebugRequested(args []string) bool {
318 19 for _, arg := range args {
319 16 if arg == "--" {
320 1 return false
321 1 }
322 15 if arg == "-d" {
323 6 return true
324 6 }
325 }
326 12 return false
327 }
328
329 // ColorEnabled reports whether escape sequences should be written to f.
330 //
331 // NO_COLOR disables them whatever it is set to, which is what the convention at
332 // no-color.org asks for: its presence is the signal and its value means
333 // nothing, so NO_COLOR=0 disables colour exactly as NO_COLOR=1 does. Otherwise
334 // the question is whether f is a character device — a terminal is, and the
335 // pipe, file or journal socket that systemd, a container and a shell redirect
336 // hand a daemon are not. One Stat answers it, which is cheaper than taking
337 // golang.org/x/term as a dependency for one bit.
338 21 func ColorEnabled(f *os.File) bool {
339 21 if _, set := os.LookupEnv("NO_COLOR"); set {
340 4 return false
341 4 }
342 17 info, err := f.Stat()
343 17 if err != nil {
344 1 return false
345 1 }
346 16 return info.Mode()&os.ModeCharDevice != 0
347 }
348
349 // ReplaceAttr compiles the masking policy into a slog.HandlerOptions.
350 // ReplaceAttr function, so that a service on a stdlib handler redacts exactly
351 // what a service on scribe's tint handler redacts:
352 //
353 // slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
354 // Level: opts.Level,
355 // AddSource: opts.AddSource,
356 // ReplaceAttr: opts.ReplaceAttr(),
357 // })
358 //
359 // The rules are compiled once, here, rather than per record; the key matching
360 // mirrors scribe's, so an attribute is redacted however deeply it is nested and
361 // whatever the caller believed it was logging. Returns nil — a valid
362 // ReplaceAttr meaning "no substitution" — when the policy is empty.
363 //
364 // An unparseable [Options.MaskPattern] panics, on this call, in main. A mask
365 // rule that silently did not compile would be a redaction that silently does
366 // not happen.
367 5 func (o Options) ReplaceAttr() func(groups []string, a slog.Attr) slog.Attr {
368 5 rules := o.maskRules()
369 5 if len(rules) == 0 {
370 1 return nil
371 1 }
372
373 3 replacement := o.MaskReplacement
374 3 if replacement == "" {
375 0 replacement = MaskReplacement
376 0 }
377
378 35 return func(groups []string, a slog.Attr) slog.Attr {
379 35 // A group's own attribute carries no value to mask; its contents each
380 35 // arrive here separately, with the group name in groups.
381 35 if a.Value.Kind() == slog.KindGroup {
382 0 return a
383 0 }
384
385 35 key := a.Key
386 35 if len(groups) > 0 {
387 2 key = strings.Join(groups, ".") + "." + a.Key
388 2 }
389 156 for _, rule := range rules {
390 156 if rule.MatchString(key) {
391 20 return slog.String(a.Key, replacement)
392 20 }
393 }
394 15 return a
395 }
396 }
397
398 // maskRules compiles the key list and the pattern into one ordered rule set.
399 // The key patterns are built the way scribe builds them — anchored to a path
400 // separator on both sides, case-insensitively — so that the two handlers cannot
401 // disagree about what "cookie" matches.
402 5 func (o Options) maskRules() []*regexp.Regexp {
403 5 rules := make([]*regexp.Regexp, 0, len(o.MaskKeys)+1)
404 22 for _, key := range o.MaskKeys {
405 22 if key == "" {
406 0 continue
407 }
408 22 rules = append(rules, regexp.MustCompile(`(?i)(^|\.|\])`+regexp.QuoteMeta(key)+`($|\.|\[)`))
409 }
410 5 if o.MaskPattern != "" {
411 4 rules = append(rules, regexp.MustCompile(o.MaskPattern))
412 4 }
413 4 return rules
414 }
415
416 // Install makes h the handler of slog's default logger and returns that logger,
417 // for the callers that would rather pass a logger than reach for the global.
418 //
419 // This is the line the rest of ecore is waiting for.
420 // [sourcecraft.dev/bigbes/sr-ht-ecore/middleware.RecoverPanics] reports through
421 // the default logger and takes no logger of its own, so a
422 // binary that builds a handler and does not install it has its panic reports —
423 // and only those — come out in Go's plain format, with none of the masking
424 // below applied. slog.SetDefault also redirects the standard log package's
425 // output into h, so a dependency that still writes through "log" lands in the
426 // same stream.
427 //
428 // Call it from main, once, before anything logs.
429 2 func Install(h slog.Handler) *slog.Logger {
430 2 if h == nil {
431 1 panic("logging: Install called with a nil handler")
432 }
433 1 log := slog.New(h)
434 1 slog.SetDefault(log)
435 1 return log
436 }