From ed3a5af7c35ef37e83608e9fb214412730535ce4 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Sun, 9 Aug 2026 00:00:03 +0300 Subject: [PATCH] logging: the instance's slog policy, without the handler MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit middleware.RecoverPanics reports panics through slog's default logger, so ecore already depends on every service installing a compatible handler and had no way to say so. A service that forgets slog.SetDefault prints its panic reports in Go's plain format, unlevelled and unmasked, into a journal where everything else is tinted. Six services (compare, spec, dolt, cover, bench, tokens) had each written the same level parser, the same os.Stderr.Stat colour probe, the same -d scan of os.Args, and their own copy of the credential mask list. The copies had drifted into three key sets and four patterns: only spec masked the config private keys, only tokens-migrate knew a DSN carries a password, and only dolt masked pubkey and credential. What is redacted — the unified-login cookie, tokens.sr.ht working tokens, the Authorization header they ride in — is a fact about the instance, so it is maintained once. Defaults() resolves the policy and Install() sets the default logger; the handler stays with the caller, because ecore is a small SourceHut library and auxilia is a large general one, and a service that wants a JSON handler for a log shipper should not link a tinting one to share a mask list. Options.ReplaceAttr applies the same masking through stdlib slog alone, so the split costs a non-scribe service nothing. tokens.sr.ht's partial mask is exported but not defaulted: six characters of a live working token is still six characters of a live working token. Level: -d, then $LOG_LEVEL, then [section]log-level, then info; an unreadable value falls through to the next source rather than refusing to boot. --- logging/logging.go | 399 ++++++++++++++++++++++++++++++++++++++++ logging/logging_test.go | 359 ++++++++++++++++++++++++++++++++++++ 2 files changed, 758 insertions(+) create mode 100644 logging/logging.go create mode 100644 logging/logging_test.go diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 0000000000000000000000000000000000000000..a98249d368b820676f69df6582cd026236a3c10b --- /dev/null +++ b/logging/logging.go @@ -0,0 +1,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 +} diff --git a/logging/logging_test.go b/logging/logging_test.go new file mode 100644 index 0000000000000000000000000000000000000000..920e62c3d968c847dc8cff47cddd18609aada5b2 --- /dev/null +++ b/logging/logging_test.go @@ -0,0 +1,359 @@ +package logging + +import ( + "bytes" + "log/slog" + "os" + "path/filepath" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "github.com/vaughan0/go-ini" +) + +// withArgs replaces the argument vector for the duration of one test, which is +// what lets the -d probe be tested without a subprocess. +func withArgs(t *testing.T, args ...string) { + t.Helper() + previous := os.Args + os.Args = append([]string{"testsrht"}, args...) + t.Cleanup(func() { os.Args = previous }) +} + +// unsetenv removes a variable for the duration of one test. t.Setenv can only +// set, and "NO_COLOR is set to the empty string" is precisely not the same +// state as "NO_COLOR is unset". +func unsetenv(t *testing.T, key string) { + t.Helper() + previous, existed := os.LookupEnv(key) + require.NoError(t, os.Unsetenv(key)) + t.Cleanup(func() { + if existed { + require.NoError(t, os.Setenv(key, previous)) + } + }) +} + +func TestParseLevel(t *testing.T) { + for _, tc := range []struct { + input string + want slog.Level + }{ + {"debug", slog.LevelDebug}, + {"Debug", slog.LevelDebug}, + {"info", slog.LevelInfo}, + {"warn", slog.LevelWarn}, + {"warning", slog.LevelWarn}, + {" WARNING ", slog.LevelWarn}, + {"error", slog.LevelError}, + } { + level, ok := ParseLevel(tc.input) + assert.True(t, ok, "ParseLevel(%q) should be readable", tc.input) + assert.Equal(t, tc.want, level, "ParseLevel(%q)", tc.input) + } +} + +// TestParseLevelReportsUnreadableValues covers the distinction the second +// result exists for: an operator who said nothing and an operator who said +// something unrecognisable both get info, and neither gets a refusal to boot, +// but only the caller can tell whether to try the next source. +func TestParseLevelReportsUnreadableValues(t *testing.T) { + for _, input := range []string{"", " ", "chatty", "verbose", "DEBUG+2", "3"} { + level, ok := ParseLevel(input) + assert.False(t, ok, "ParseLevel(%q) should not be readable", input) + assert.Equal(t, slog.LevelInfo, level, "ParseLevel(%q)", input) + } +} + +// TestDefaultsLevelPrefersTheDebugFlag: -d is typed for this run, so it outranks +// both the environment and the config file. +func TestDefaultsLevelPrefersTheDebugFlag(t *testing.T) { + withArgs(t, "-b", ":5000", "-d") + t.Setenv(LevelEnv, "error") + + conf := ini.File{"dolt.sr.ht": ini.Section{LevelKey: "warn"}} + assert.Equal(t, slog.LevelDebug, Defaults(conf, "dolt.sr.ht").Level) +} + +func TestDefaultsLevelPrefersTheEnvironmentOverTheConfigFile(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "error") + + conf := ini.File{"dolt.sr.ht": ini.Section{LevelKey: "warn"}} + assert.Equal(t, slog.LevelError, Defaults(conf, "dolt.sr.ht").Level) +} + +func TestDefaultsLevelFallsBackToTheConfigFile(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "") + + conf := ini.File{"dolt.sr.ht": ini.Section{LevelKey: "warn"}} + assert.Equal(t, slog.LevelWarn, Defaults(conf, "dolt.sr.ht").Level) +} + +// TestDefaultsDegradesAnUnreadableLevel is the whole reason ParseLevel reports +// readability: a typo in a logging preference costs the preference, never the +// service. An unreadable value is skipped as though it had not been written, so +// the next source down still gets its say. +func TestDefaultsDegradesAnUnreadableLevel(t *testing.T) { + conf := ini.File{"dolt.sr.ht": ini.Section{LevelKey: "warn"}} + + t.Run("unreadable environment falls through to the config file", func(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "chatty") + assert.Equal(t, slog.LevelWarn, Defaults(conf, "dolt.sr.ht").Level) + }) + + t.Run("unreadable config value is info", func(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "") + broken := ini.File{"dolt.sr.ht": ini.Section{LevelKey: "trace"}} + assert.Equal(t, slog.LevelInfo, Defaults(broken, "dolt.sr.ht").Level) + }) +} + +// TestDefaultsWithoutAConfigFile covers the call a daemon makes before it has +// loaded config.ini — the point of which is that -d is live while config is +// being validated rather than only once the daemon has finished starting. +func TestDefaultsWithoutAConfigFile(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "") + assert.Equal(t, slog.LevelInfo, Defaults(nil, "").Level) + + withArgs(t, "-d") + assert.Equal(t, slog.LevelDebug, Defaults(nil, "").Level) +} + +// TestDefaultsCarriesTheInstancePolicy pins the decisions that must not differ +// between two services reading the same journal. +func TestDefaultsCarriesTheInstancePolicy(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "") + + opts := Defaults(nil, "") + assert.True(t, opts.AddSource, "source positions are on for every service") + assert.Equal(t, TimeFormat, opts.TimeFormat) + assert.Equal(t, MaskPattern, opts.MaskPattern) + assert.Equal(t, MaskReplacement, opts.MaskReplacement) + assert.Equal(t, MaskKeys(), opts.MaskKeys) +} + +// TestNoColorIsHonouredWhateverItSaysTo: no-color.org's convention is that the +// variable's presence is the signal and its value means nothing — "0" and +// "false" disable colour exactly as "1" does. A handler that read it as a +// boolean would give an operator who wrote NO_COLOR=0 the escape sequences they +// asked not to have. +func TestNoColorIsHonouredWhateverItSaysTo(t *testing.T) { + devNull, err := os.Open(os.DevNull) + require.NoError(t, err) + t.Cleanup(func() { _ = devNull.Close() }) + + for _, value := range []string{"", "0", "false", "1"} { + t.Setenv("NO_COLOR", value) + assert.False(t, ColorEnabled(devNull), "NO_COLOR=%q", value) + } +} + +// TestColorEnabledOnACharacterDevice: /dev/null is a character device, which is +// the same answer a terminal gives and the one a test can rely on having. +func TestColorEnabledOnACharacterDevice(t *testing.T) { + unsetenv(t, "NO_COLOR") + + devNull, err := os.Open(os.DevNull) + require.NoError(t, err) + t.Cleanup(func() { _ = devNull.Close() }) + + assert.True(t, ColorEnabled(devNull)) +} + +// TestColorDisabledWithoutATerminal is the case that matters in production: +// under systemd, in a container and behind a shell redirect, stderr is a file +// or a pipe, and escape sequences stored in a journal are noise every reader +// has to filter — and a `journalctl | grep` that stops matching what the eye +// sees. +func TestColorDisabledWithoutATerminal(t *testing.T) { + unsetenv(t, "NO_COLOR") + + regular, err := os.Create(filepath.Join(t.TempDir(), "journal")) + require.NoError(t, err) + t.Cleanup(func() { _ = regular.Close() }) + assert.False(t, ColorEnabled(regular), "a regular file is not a terminal") + + reader, writer, err := os.Pipe() + require.NoError(t, err) + t.Cleanup(func() { + _ = reader.Close() + _ = writer.Close() + }) + assert.False(t, ColorEnabled(writer), "a pipe is not a terminal") + + // A closed descriptor cannot be stated at all; the safe answer to a + // question that cannot be asked is the one that writes no escapes. + closed, err := os.Open(os.DevNull) + require.NoError(t, err) + require.NoError(t, closed.Close()) + assert.False(t, ColorEnabled(closed)) +} + +func TestDebugRequested(t *testing.T) { + for _, tc := range []struct { + name string + args []string + want bool + }{ + {"no arguments", nil, false}, + {"bare flag", []string{"-d"}, true}, + {"after other flags", []string{"-b", ":5000", "-d"}, true}, + {"before other flags", []string{"-d", "-m", ":5001"}, true}, + {"absent", []string{"-b", ":5000"}, false}, + {"not a flag value", []string{"-b", "-dev"}, false}, + {"clustered is core-go's business", []string{"-bd"}, false}, + {"after the operand separator", []string{"--", "-d"}, false}, + } { + t.Run(tc.name, func(t *testing.T) { + assert.Equal(t, tc.want, DebugRequested(tc.args)) + }) + } +} + +// TestMaskKeysAreTheDonorsUnion is the test the package exists for: the list is +// the union of what the six services had each written down separately, and no +// adoption may quietly drop an entry one of them had. Every key below was in at +// least one donor's list, and no donor had them all. +func TestMaskKeysAreTheDonorsUnion(t *testing.T) { + assert.ElementsMatch(t, []string{ + "token", // cover, dolt, compare, bench, spec + "cookie", // all six + "authorization", // all six + "network-key", // spec + "private-key", // spec + "password", // tokens (daemon and migrate) + "api_key", // tokens + "apikey", // tokens + "dsn", // tokens-migrate + "data_source_name", // tokens-migrate + }, MaskKeys()) +} + +// TestMaskKeysReturnsACopy: a mask set that a linked package can append to or +// truncate is not a policy, which is why this is a function and not a var. +func TestMaskKeysReturnsACopy(t *testing.T) { + keys := MaskKeys() + require.NotEmpty(t, keys) + keys[0] = "not-a-credential" + keys = append(keys, "another") + + assert.NotContains(t, MaskKeys(), "not-a-credential") + assert.NotContains(t, MaskKeys(), "another") + assert.Len(t, MaskKeys(), len(keys)-1) +} + +// TestMaskPatternCoversTheDonorsPatterns pins the union of the four different +// regexps the six services had arrived at, including the two entries only one +// donor each had thought of (dolt's pubkey/credential, tokens-migrate's dsn). +func TestMaskPatternCoversTheDonorsPatterns(t *testing.T) { + opts := Options{MaskPattern: MaskPattern, MaskReplacement: MaskReplacement} + replace := opts.ReplaceAttr() + require.NotNil(t, replace) + + masked := func(key string) bool { + return replace(nil, slog.String(key, "sensitive")).Value.String() == MaskReplacement + } + + for _, key := range []string{ + "secret", "client_secret", "token", "access_token", "api_key", "apikey", + "apiKey", "password", "pubkey", "credential", "dsn", "authorization", + "cookie", "Authorization", "SECRET", + } { + assert.True(t, masked(key), "%q must be masked", key) + } + + for _, key := range []string{"user", "repo", "duration", "status", "id", "path"} { + assert.False(t, masked(key), "%q must not be masked", key) + } + + // Documented consequence of taking the union: token_id is masked here, + // where tokens.sr.ht's local copy kept it readable. A service that needs + // the row id to correlate on logs it under a key without "token" in it. + assert.True(t, masked("token_id")) +} + +// TestReplaceAttrMasksThroughAStdlibHandler is what makes the split honest: a +// service that wants a JSON or text handler instead of scribe's tinting one +// still redacts exactly what the instance redacts, without importing anything +// to get it. +func TestReplaceAttrMasksThroughAStdlibHandler(t *testing.T) { + withArgs(t) + t.Setenv(LevelEnv, "") + opts := Defaults(nil, "") + + var buf bytes.Buffer + log := slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{ + Level: opts.Level, + ReplaceAttr: opts.ReplaceAttr(), + })) + + log.Info("issued a token for the caller", + slog.String("cookie", "sr.ht.unified-login=abcdef"), + slog.String("user", "~bigbes"), + slog.Int("token_bytes", 32), + slog.Group("request", + slog.String("authorization", "Bearer 0123456789abcdef"), + slog.String("method", "POST"), + ), + ) + out := buf.String() + + assert.Contains(t, out, "cookie=***") + assert.Contains(t, out, "request.authorization=***") + assert.NotContains(t, out, "abcdef", "no fragment of a credential survives") + assert.NotContains(t, out, "Bearer") + + // Masking keys is not masking prose: the rules match the attribute's key + // path and nothing else, so a message that says "token" is untouched and a + // non-credential attribute keeps its value. + assert.Contains(t, out, `msg="issued a token for the caller"`) + assert.Contains(t, out, "user=~bigbes") + assert.Contains(t, out, "request.method=POST") + + // A non-string value carrying a masked key is redacted too, rather than + // printed because it was not a string. + assert.Contains(t, out, "token_bytes=***") +} + +// TestReplaceAttrIsNilForAnEmptyPolicy: nil is slog's own "no substitution", so +// a caller with no masking configured pays nothing per record. +func TestReplaceAttrIsNilForAnEmptyPolicy(t *testing.T) { + assert.Nil(t, Options{}.ReplaceAttr()) +} + +// TestReplaceAttrRejectsAnUnparseablePattern: a mask rule that silently failed +// to compile would be a redaction that silently does not happen, so it fails on +// the call from main instead. +func TestReplaceAttrRejectsAnUnparseablePattern(t *testing.T) { + assert.Panics(t, func() { + Options{MaskPattern: `(?i)(unclosed`}.ReplaceAttr() + }) +} + +// TestInstallSetsTheDefault covers the line the shared middleware depends on: +// RecoverPanics reports through slog's default logger, so an Install that built +// a logger and did not install it would leave those reports — and only those — +// in Go's plain stderr format, unmasked. +func TestInstallSetsTheDefault(t *testing.T) { + previous := slog.Default() + t.Cleanup(func() { slog.SetDefault(previous) }) + + var buf bytes.Buffer + log := Install(slog.NewTextHandler(&buf, nil)) + require.NotNil(t, log) + assert.Same(t, log, slog.Default()) + + slog.Info("through the default logger") + assert.Contains(t, buf.String(), "through the default logger") +} + +func TestInstallRejectsANilHandler(t *testing.T) { + assert.Panics(t, func() { Install(nil) }) +}