// 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 }