// 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 defaults(resolveLevel(conf, section, true))
}
// DefaultsWithoutDebugFlag is Defaults for a binary whose -d is not the
// daemon's.
//
// A migration CLI on this instance passes -d to brant, where it means
// --dialect and takes a value: `coversrht-migrate -d postgres` would otherwise
// arrive here as a request for debug logging, silently, because the probe sees
// the flag and never the value. $LOG_LEVEL and the config key still resolve —
// only the argument scan is dropped, which is the one source that cannot tell
// the two meanings apart.
func DefaultsWithoutDebugFlag(conf ini.File, section string) Options {
return defaults(resolveLevel(conf, section, false))
}
func defaults(level slog.Level) Options {
return Options{
Level: level,
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.
// debugFlag is false for a binary whose -d belongs to something else.
func resolveLevel(conf ini.File, section string, debugFlag bool) slog.Level {
if debugFlag && 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
}