~bigbes/sr-ht-ecore

ref: e8a9672594733218fd773bab9e9216ae1c2db6c2 sr-ht-ecore/logging/logging_test.go -rw-r--r-- 12.6 KiB
e8a96725 — Eugene Blikh bearer: mint the internal authorization through internalauth 9 days ago
                                                                                
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
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) })
}