@@ 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
+}
@@ 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) })
+}