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