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