~bigbes/sr-ht-ecore

ref: c627d4eefcef916daf44b9c48f400c138f403666 sr-ht-ecore/logging/logging.go -rw-r--r-- 15.6 KiB
c627d4ee — Eugene Blikh internalauth: both ends of the Internal authorization 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
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
// Package logging is the log policy of a self-hosted SourceHut instance: the
// verbosity, the source positions, the colour decision, and — the part that is
// not presentation — the set of attribute keys that must never reach a log
// file.
//
// It exists because the rest of sr-ht-ecore already depends on the answer.
// [sourcecraft.dev/bigbes/sr-ht-ecore/middleware.RecoverPanics] reports a
// recovered panic through slog's *default* logger, because a middleware living
// in another module has no constructor
// through which the service could hand it one. A service that never calls
// slog.SetDefault still logs those reports — through Go's plain stderr handler,
// unlevelled, unmasked, and in a different format from every other line in the
// same journal. Until now ecore needed that and could not say so.
//
// The second half is policy rather than taste. Six services of this instance
// (compare, spec, dolt, cover, bench, tokens) each grew the same forty lines in
// their main.go: the same level parser, the same os.Stderr.Stat colour probe,
// and six separately maintained copies of the credential mask list. The copies
// had already drifted — three different key sets and three different patterns,
// with one service masking a DSN that the other five did not know was a
// credential and another masking the private keys that the rest did not. What
// is being redacted (the instance's unified-login cookie, tokens.sr.ht's
// working tokens, the Authorization header they travel in) is a fact about the
// instance, not about any one service, so it is maintained once here.
//
// # The handler stays with the caller
//
// Every service on this instance installs auxilia's scribe.TintHandler, and
// this package deliberately does not build it. ecore is a small SourceHut-
// specific library, auxilia is a large general one, and linking scribe into
// every consumer of chrome, csrf and middleware in order to share a list of
// masked keys would be the wrong trade — a service that wants a JSON handler
// for a log shipper should not have to link a tinting one. So the policy is
// resolved here and the handler is constructed there:
//
//	opts := logging.Defaults(conf, "dolt.sr.ht")
//	logging.Install(scribe.NewTintHandler(
//		scribe.WithWriter(os.Stderr),
//		scribe.WithLevel(opts.Level),
//		scribe.WithSource(opts.AddSource),
//		scribe.WithTimeFormat(opts.TimeFormat),
//		scribe.WithNoColor(!opts.Color),
//		scribe.WithMaskKeys(opts.MaskKeys...),
//		scribe.WithMask(opts.MaskPattern, opts.MaskReplacement),
//	))
//
// The masking is not scribe's to own either: [Options.ReplaceAttr] applies the
// same rules through stdlib slog alone, so a service on a JSON handler gets the
// instance's redaction without importing anything.
//
//	logging.Install(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
//		Level:       opts.Level,
//		AddSource:   opts.AddSource,
//		ReplaceAttr: opts.ReplaceAttr(),
//	}))
//
// [Install] belongs in main and nowhere else: slog's default logger is
// process-global state, so a package that set it would be deciding for
// everything else that was linked alongside it.
package logging

import (
	"log/slog"
	"os"
	"regexp"
	"slices"
	"strings"
	"time"

	"github.com/vaughan0/go-ini"

	"sourcecraft.dev/bigbes/sr-ht-core/config"
)

const (
	// LevelEnv is the environment variable that names the verbosity for one
	// run. It is what an operator reaches for from a shell or a systemd
	// Environment= line, and it overrides [LevelKey].
	LevelEnv = "LOG_LEVEL"

	// LevelKey is the config.ini key holding the instance's persistent
	// verbosity, read from the service's own section: `log-level=info`. It is
	// the setting an operator writes down; [LevelEnv] and -d are the ones they
	// pass for a single run.
	LevelKey = "log-level"

	// TimeFormat is the timestamp every service prints. The sortable form
	// rather than RFC 3339: under systemd the journal stamps its own arrival
	// time beside this one, and two RFC 3339 stamps per line is a line nobody
	// reads to the end.
	TimeFormat = time.DateTime

	// MaskReplacement is what a masked value is printed as.
	MaskReplacement = "***"

	// MaskPattern matches the attribute key *path* of a value that must not be
	// logged — "token", "user.password", "req.headers.authorization". It is the
	// union of the patterns the six services had each arrived at separately,
	// and it is a pattern rather than a list because the credential that leaks
	// is the attribute somebody adds next year under a name nobody thought to
	// add to a list.
	//
	// It matches the key and never the message, so prose that happens to
	// contain the word "token" costs nothing and cannot be used to defeat it.
	//
	// Note that this masks `token_id` as well, which tokens.sr.ht's local copy
	// deliberately did not — a row id is what correlates two lines about one
	// credential. The instance-wide default errs the other way, because the
	// failure it is guarding against is a live credential in a log file and the
	// failure it causes is an id that has to be logged under a key not
	// containing "token" (`id` is the better name for it anyway).
	MaskPattern = `(?i)(secret|token|api_?key|password|pubkey|credential|dsn|authorization|cookie)`

	// PartialMaskPattern and PartialMaskKeep are tokens.sr.ht's correlation
	// exception and are NOT part of [Defaults]: a key that is or ends in
	// "token" or "secret" keeps its first six characters instead of being
	// replaced whole, which is enough to line two log lines up against each
	// other and useless to anybody who wants to present the credential.
	//
	// It is opt-in because it is strictly weaker than the default — six
	// characters of a live working token is still six characters of a live
	// working token, and only a service whose whole subject is credentials has
	// enough to gain from it to pay that. Such a service installs it *before*
	// the rules of [Defaults], because the first matching rule wins and the
	// blanket rule would otherwise swallow the prefix this exists to keep:
	//
	//	scribe.WithMaskPartial(logging.PartialMaskPattern, logging.PartialMaskKeep),
	//	scribe.WithMaskKeys(opts.MaskKeys...),
	//	scribe.WithMask(opts.MaskPattern, opts.MaskReplacement),
	PartialMaskPattern = `(?i)(^|[._-])(token|secret)$`
	PartialMaskKeep    = 6
)

// maskKeys is the exact-key half of the policy: the credentials this instance's
// services are known to handle today, named as they are named in the code.
//
// Both halves are installed because they fail differently — the list covers
// what is named now and cannot be worked around by an unlucky regexp, and
// [MaskPattern] covers what gets named later. Every entry here was in at least
// one of the six services' lists, and no service had all of them.
var maskKeys = []string{
	// The unified-login session cookie and the header it arrives in, which
	// every service of this instance reads (SPEC ch. 6).
	"cookie",
	"authorization",

	// tokens.sr.ht working tokens and the generic credential names services
	// pass them under.
	"token",
	"api_key",
	"apikey",
	"password",

	// Keys out of config.ini that a startup line is likely to echo.
	"network-key",
	"private-key",

	// The connection string of a migration binary, which carries a password.
	"dsn",
	"data_source_name",
}

// MaskKeys returns the instance's masked attribute keys, ready to be handed to
// a handler in one line:
//
//	scribe.WithMaskKeys(logging.MaskKeys()...)
//
// It is a function returning a fresh slice rather than an exported variable
// because a mask set that any linked package can append to or truncate is not a
// policy.
func MaskKeys() []string {
	return slices.Clone(maskKeys)
}

// Options is everything about logging that the services of one instance decide
// identically. [Defaults] resolves it; the caller spends it on the handler of
// its choice.
type Options struct {
	// Level is the resolved verbosity — see [Defaults] for where it comes from.
	Level slog.Level

	// AddSource asks for file:line on every record. It is on by default: what
	// reaches these logs is mostly a failure nobody can reproduce, and "which
	// of the six render sites said this" is the first question about each one.
	AddSource bool

	// Color reports whether escape sequences are wanted, resolved from NO_COLOR
	// and from whether stderr is a terminal. Handlers usually ask the inverse
	// question, hence scribe.WithNoColor(!opts.Color).
	Color bool

	// TimeFormat is the timestamp layout, [TimeFormat] by default.
	TimeFormat string

	// MaskKeys, MaskPattern and MaskReplacement are the redaction policy, in
	// the order a handler should install them. Both matchers run against the
	// attribute's key path, never against its value or the message.
	MaskKeys        []string
	MaskPattern     string
	MaskReplacement string
}

// Defaults resolves the instance's logging policy, reading the service's own
// section of config.ini for [LevelKey].
//
// The verbosity has three sources, strongest first:
//
//   - `-d` in the argument vector, which every SourceHut daemon takes as its
//     debug flag;
//   - $LOG_LEVEL, for one run;
//   - [section]log-level in config.ini, the instance's persistent setting.
//
// A value none of them can read — including the empty string of an unset
// variable — falls through to the next source, and info if there is none. It is
// operator input: a typo in a logging preference must never be the reason a
// service will not boot.
//
// -d is read straight out of os.Args rather than taken as a parameter because
// of when this is called. core-go's server.New parses the argument vector, but
// it runs after config loading and validation, and a daemon that becomes
// verbose only once it has finished starting is silent for exactly the window
// an operator passes -d to watch. A service that installs its logger before
// loading config calls Defaults(nil, "") — -d and $LOG_LEVEL still resolve, and
// the config file has nothing to say yet.
func Defaults(conf ini.File, section string) Options {
	return Options{
		Level:           resolveLevel(conf, section),
		AddSource:       true,
		Color:           ColorEnabled(os.Stderr),
		TimeFormat:      TimeFormat,
		MaskKeys:        MaskKeys(),
		MaskPattern:     MaskPattern,
		MaskReplacement: MaskReplacement,
	}
}

// resolveLevel walks the three sources of verbosity in order of authority.
func resolveLevel(conf ini.File, section string) slog.Level {
	if DebugRequested(os.Args[1:]) {
		return slog.LevelDebug
	}
	if level, ok := ParseLevel(os.Getenv(LevelEnv)); ok {
		return level
	}
	if section != "" {
		if level, ok := ParseLevel(config.GetString(conf, section, LevelKey, "")); ok {
			return level
		}
	}
	return slog.LevelInfo
}

// ParseLevel reads a verbosity name — "debug", "info", "warn" (or "warning"),
// "error" — case and surrounding space insensitively. The second result reports
// whether the name was one of those, which is what lets a caller tell "the
// operator did not say" from "the operator said something unreadable" and
// degrade rather than refuse.
func ParseLevel(s string) (slog.Level, bool) {
	switch strings.ToLower(strings.TrimSpace(s)) {
	case "debug":
		return slog.LevelDebug, true
	case "info":
		return slog.LevelInfo, true
	case "warn", "warning":
		return slog.LevelWarn, true
	case "error":
		return slog.LevelError, true
	default:
		return slog.LevelInfo, false
	}
}

// DebugRequested reports whether the argument vector (without argv[0]) carries
// SourceHut's -d debug flag.
//
// Only the standalone token counts, which is what all six services did by hand;
// recognising a clustered "-bd" would mean reproducing core-go's getopt here,
// against an argument vector core-go is about to parse properly anyway. A "--"
// ends the scan: what follows it is an operand, not a flag.
func DebugRequested(args []string) bool {
	for _, arg := range args {
		if arg == "--" {
			return false
		}
		if arg == "-d" {
			return true
		}
	}
	return false
}

// ColorEnabled reports whether escape sequences should be written to f.
//
// NO_COLOR disables them whatever it is set to, which is what the convention at
// no-color.org asks for: its presence is the signal and its value means
// nothing, so NO_COLOR=0 disables colour exactly as NO_COLOR=1 does. Otherwise
// the question is whether f is a character device — a terminal is, and the
// pipe, file or journal socket that systemd, a container and a shell redirect
// hand a daemon are not. One Stat answers it, which is cheaper than taking
// golang.org/x/term as a dependency for one bit.
func ColorEnabled(f *os.File) bool {
	if _, set := os.LookupEnv("NO_COLOR"); set {
		return false
	}
	info, err := f.Stat()
	if err != nil {
		return false
	}
	return info.Mode()&os.ModeCharDevice != 0
}

// ReplaceAttr compiles the masking policy into a slog.HandlerOptions.
// ReplaceAttr function, so that a service on a stdlib handler redacts exactly
// what a service on scribe's tint handler redacts:
//
//	slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
//		Level:       opts.Level,
//		AddSource:   opts.AddSource,
//		ReplaceAttr: opts.ReplaceAttr(),
//	})
//
// The rules are compiled once, here, rather than per record; the key matching
// mirrors scribe's, so an attribute is redacted however deeply it is nested and
// whatever the caller believed it was logging. Returns nil — a valid
// ReplaceAttr meaning "no substitution" — when the policy is empty.
//
// An unparseable [Options.MaskPattern] panics, on this call, in main. A mask
// rule that silently did not compile would be a redaction that silently does
// not happen.
func (o Options) ReplaceAttr() func(groups []string, a slog.Attr) slog.Attr {
	rules := o.maskRules()
	if len(rules) == 0 {
		return nil
	}

	replacement := o.MaskReplacement
	if replacement == "" {
		replacement = MaskReplacement
	}

	return func(groups []string, a slog.Attr) slog.Attr {
		// A group's own attribute carries no value to mask; its contents each
		// arrive here separately, with the group name in groups.
		if a.Value.Kind() == slog.KindGroup {
			return a
		}

		key := a.Key
		if len(groups) > 0 {
			key = strings.Join(groups, ".") + "." + a.Key
		}
		for _, rule := range rules {
			if rule.MatchString(key) {
				return slog.String(a.Key, replacement)
			}
		}
		return a
	}
}

// maskRules compiles the key list and the pattern into one ordered rule set.
// The key patterns are built the way scribe builds them — anchored to a path
// separator on both sides, case-insensitively — so that the two handlers cannot
// disagree about what "cookie" matches.
func (o Options) maskRules() []*regexp.Regexp {
	rules := make([]*regexp.Regexp, 0, len(o.MaskKeys)+1)
	for _, key := range o.MaskKeys {
		if key == "" {
			continue
		}
		rules = append(rules, regexp.MustCompile(`(?i)(^|\.|\])`+regexp.QuoteMeta(key)+`($|\.|\[)`))
	}
	if o.MaskPattern != "" {
		rules = append(rules, regexp.MustCompile(o.MaskPattern))
	}
	return rules
}

// Install makes h the handler of slog's default logger and returns that logger,
// for the callers that would rather pass a logger than reach for the global.
//
// This is the line the rest of ecore is waiting for.
// [sourcecraft.dev/bigbes/sr-ht-ecore/middleware.RecoverPanics] reports through
// the default logger and takes no logger of its own, so a
// binary that builds a handler and does not install it has its panic reports —
// and only those — come out in Go's plain format, with none of the masking
// below applied. slog.SetDefault also redirects the standard log package's
// output into h, so a dependency that still writes through "log" lands in the
// same stream.
//
// Call it from main, once, before anything logs.
func Install(h slog.Handler) *slog.Logger {
	if h == nil {
		panic("logging: Install called with a nil handler")
	}
	log := slog.New(h)
	slog.SetDefault(log)
	return log
}