Cody Rose
8d144c2ba3
Counterintuitively, a new sink added to an existing logger will not inherit the existing logger's key-value pairs. This has only caused a problem in practice with respect to a small number of known key-value pairs, so this PR creates a way to add specific key-value pairs to new sinks. This supersedes #4579.
415 lines
11 KiB
Go
415 lines
11 KiB
Go
package log
|
|
|
|
import (
|
|
"bytes"
|
|
"encoding/json"
|
|
"io"
|
|
"strings"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/getsentry/sentry-go"
|
|
"github.com/stretchr/testify/assert"
|
|
"github.com/stretchr/testify/require"
|
|
"go.uber.org/zap"
|
|
)
|
|
|
|
func TestNew(t *testing.T) {
|
|
var jsonBuffer, consoleBuffer bytes.Buffer
|
|
logger, flush := New("service-name",
|
|
WithJSONSink(&jsonBuffer, WithGlobalRedaction()),
|
|
WithConsoleSink(&consoleBuffer, WithGlobalRedaction()),
|
|
)
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
var parsedJSON map[string]any
|
|
assert.Nil(t, json.Unmarshal(jsonBuffer.Bytes(), &parsedJSON))
|
|
assert.NotEmpty(t, parsedJSON["ts"])
|
|
delete(parsedJSON, "ts")
|
|
assert.Equal(t,
|
|
map[string]any{
|
|
"level": "info-0",
|
|
"logger": "service-name",
|
|
"msg": "yay",
|
|
},
|
|
parsedJSON,
|
|
)
|
|
assert.Equal(t,
|
|
[]string{"info-0\tservice-name\tyay"},
|
|
splitLines(consoleBuffer.String()),
|
|
)
|
|
}
|
|
|
|
func TestSetLevel(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
defer SetLevel(0)
|
|
logger, _ := New("service-name", WithConsoleSink(&buffer))
|
|
|
|
assert.Equal(t, true, logger.GetSink().Enabled(0))
|
|
assert.Equal(t, false, logger.GetSink().Enabled(1))
|
|
assert.Equal(t, false, logger.GetSink().Enabled(2))
|
|
|
|
SetLevel(1)
|
|
assert.Equal(t, true, logger.GetSink().Enabled(0))
|
|
assert.Equal(t, true, logger.GetSink().Enabled(1))
|
|
assert.Equal(t, false, logger.GetSink().Enabled(2))
|
|
|
|
SetLevel(2)
|
|
assert.Equal(t, true, logger.GetSink().Enabled(0))
|
|
assert.Equal(t, true, logger.GetSink().Enabled(1))
|
|
assert.Equal(t, true, logger.GetSink().Enabled(2))
|
|
}
|
|
|
|
func TestWithSentryFailure(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
logger, flush := New("service-name",
|
|
WithSentry(sentry.ClientOptions{Dsn: "fail"}, nil),
|
|
WithConsoleSink(&buffer),
|
|
)
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
assert.Contains(t, buffer.String(), "error configuring logger")
|
|
assert.Contains(t, buffer.String(), "yay")
|
|
}
|
|
|
|
func TestAddSentryFailure(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
logger, flush := New("service-name", WithConsoleSink(&buffer))
|
|
logger, _, err := AddSentry(logger, sentry.ClientOptions{Dsn: "fail"}, nil)
|
|
assert.NotNil(t, err)
|
|
assert.NotContains(t, err.Error(), "unsupported")
|
|
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
assert.Contains(t, buffer.String(), "yay")
|
|
}
|
|
|
|
func TestAddSentry(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
var sentryMessage string
|
|
logger, _ := New("service-name", WithConsoleSink(&buffer))
|
|
logger, flush, err := AddSentry(logger, sentry.ClientOptions{
|
|
BeforeSend: func(event *sentry.Event, hint *sentry.EventHint) *sentry.Event {
|
|
sentryMessage = event.Message
|
|
return nil
|
|
},
|
|
}, nil)
|
|
assert.Nil(t, err)
|
|
|
|
logger.Error(nil, "oops")
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
assert.Contains(t, buffer.String(), "oops")
|
|
assert.Contains(t, buffer.String(), "yay")
|
|
assert.Equal(t, "oops", sentryMessage)
|
|
}
|
|
|
|
func TestWithSentry(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
var sentryMessage string
|
|
logger, flush := New("service-name",
|
|
WithConsoleSink(&buffer),
|
|
WithSentry(sentry.ClientOptions{
|
|
BeforeSend: func(event *sentry.Event, hint *sentry.EventHint) *sentry.Event {
|
|
sentryMessage = event.Message
|
|
return nil
|
|
},
|
|
}, nil),
|
|
)
|
|
logger.Info("yay")
|
|
logger.Error(nil, "oops")
|
|
assert.Nil(t, flush())
|
|
|
|
assert.Contains(t, buffer.String(), "yay")
|
|
assert.Contains(t, buffer.String(), "oops")
|
|
assert.Equal(t, "oops", sentryMessage)
|
|
}
|
|
|
|
func TestHumanReadableTimestamp(t *testing.T) {
|
|
var buffer bytes.Buffer
|
|
logger, flush := New("service-name",
|
|
WithConsoleSink(&buffer),
|
|
)
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
ts := strings.Split(buffer.String(), "\t")[0]
|
|
assert.NotContains(t, ts, "e+09")
|
|
|
|
parsedTime, err := time.Parse(time.RFC3339, ts)
|
|
assert.Nil(t, err)
|
|
assert.Less(t, time.Since(parsedTime), 5*time.Second)
|
|
}
|
|
|
|
func TestAddSink(t *testing.T) {
|
|
var buf1, buf2 bytes.Buffer
|
|
logger, _ := New("service-name",
|
|
WithConsoleSink(&buf1),
|
|
)
|
|
logger.Info("line 1")
|
|
logger, flush, err := AddSink(logger, WithConsoleSink(&buf2))
|
|
assert.Nil(t, err)
|
|
logger.Info("line 2")
|
|
assert.Nil(t, flush())
|
|
|
|
assert.Contains(t, buf1.String(), "line 1")
|
|
assert.Contains(t, buf1.String(), "line 2")
|
|
// buf2 should only have "line 2"
|
|
assert.NotContains(t, buf2.String(), "line 1")
|
|
assert.Contains(t, buf2.String(), "line 2")
|
|
}
|
|
|
|
func TestAddSink_WithKeyValuePairs(t *testing.T) {
|
|
// Arrange: Create a logger with a key-value pair
|
|
var buf1 bytes.Buffer
|
|
logger, cleanup := New("service-name", WithConsoleSink(&buf1))
|
|
t.Cleanup(func() { _ = cleanup })
|
|
logger = logger.WithValues("sink 1 key", "sink 1 value")
|
|
|
|
// Arrange: Add a second sink with a new key-value pair
|
|
var buf2 bytes.Buffer
|
|
logger, flush, err := AddSink(logger, WithConsoleSink(&buf2), "sink 2 key", "sink 2 value")
|
|
require.NoError(t, err)
|
|
|
|
// Act
|
|
logger.Info("something")
|
|
require.NoError(t, flush())
|
|
|
|
// Assert: Confirm that each sink received only its own key-value pair
|
|
assert.Contains(t, buf1.String(), "sink 1")
|
|
assert.NotContains(t, buf1.String(), "sink 2")
|
|
assert.Contains(t, buf2.String(), "sink 2")
|
|
assert.NotContains(t, buf2.String(), "sink 1")
|
|
}
|
|
|
|
func TestStaticLevelSink(t *testing.T) {
|
|
var buf1, buf2 bytes.Buffer
|
|
l1 := zap.NewAtomicLevel()
|
|
logger, flush := New(
|
|
"service-name",
|
|
WithConsoleSink(&buf1, WithLeveler(l1)),
|
|
WithConsoleSink(&buf2, WithLevel(0)),
|
|
)
|
|
|
|
logger.Info("line 1")
|
|
SetLevelForControl(l1, 1)
|
|
logger.V(1).Info("line 2")
|
|
assert.Nil(t, flush())
|
|
|
|
// buf1 should have both lines
|
|
assert.Contains(t, buf1.String(), "line 1")
|
|
assert.Contains(t, buf1.String(), "line 2")
|
|
|
|
// buf2 should only have "line 1"
|
|
assert.Contains(t, buf2.String(), "line 1")
|
|
assert.NotContains(t, buf2.String(), "line 2")
|
|
}
|
|
|
|
func TestWithLeveler(t *testing.T) {
|
|
var buf1, buf2 bytes.Buffer
|
|
l1, l2 := zap.NewAtomicLevel(), zap.NewAtomicLevel()
|
|
logger, flush := New(
|
|
"service-name",
|
|
WithConsoleSink(&buf1, WithLeveler(l1)),
|
|
WithConsoleSink(&buf2, WithLeveler(l2)),
|
|
)
|
|
|
|
SetLevelForControl(l1, 1)
|
|
SetLevelForControl(l2, 2)
|
|
|
|
logger.V(0).Info("line 1")
|
|
logger.V(1).Info("line 2")
|
|
logger.V(2).Info("line 3")
|
|
assert.Nil(t, flush())
|
|
|
|
// buf1 should have lines 1 and 2
|
|
assert.Contains(t, buf1.String(), "line 1")
|
|
assert.Contains(t, buf1.String(), "line 2")
|
|
assert.NotContains(t, buf1.String(), "line 3")
|
|
|
|
// buf2 should have all lines
|
|
assert.Contains(t, buf2.String(), "line 1")
|
|
assert.Contains(t, buf2.String(), "line 2")
|
|
assert.Contains(t, buf2.String(), "line 3")
|
|
}
|
|
|
|
func splitLines(s string) []string {
|
|
lines := strings.Split(strings.TrimSpace(s), "\n")
|
|
logLines := make([]string, len(lines))
|
|
for i, logLine := range lines {
|
|
// remove timestamp
|
|
logLines[i] = strings.TrimSpace(logLine[strings.Index(logLine, "\t")+1:])
|
|
}
|
|
return logLines
|
|
}
|
|
|
|
func TestGlobalRedaction_Console(t *testing.T) {
|
|
oldState := globalRedactor
|
|
globalRedactor = &dynamicRedactor{
|
|
denySet: make(map[string]struct{}),
|
|
}
|
|
defer func() { globalRedactor = oldState }()
|
|
|
|
var buf bytes.Buffer
|
|
logger, flush := New("console-redaction-test",
|
|
WithConsoleSink(&buf, WithGlobalRedaction()),
|
|
)
|
|
RedactGlobally("foo")
|
|
RedactGlobally("bar")
|
|
|
|
logger.Info("this foo is :bar",
|
|
"foo", "bar",
|
|
"array", []string{"foo", "bar", "baz"},
|
|
"object", map[string]string{"foo": "bar"})
|
|
require.NoError(t, flush())
|
|
|
|
gotParts := strings.Split(buf.String(), "\t")[1:] // The first item is the timestamp
|
|
wantParts := []string{
|
|
"info-0",
|
|
"console-redaction-test",
|
|
"this ***** is :*****",
|
|
"{\"foo\": \"*****\", \"array\": [\"foo\", \"bar\", \"baz\"], \"object\": {\"foo\":\"bar\"}}\n",
|
|
}
|
|
assert.Equal(t, wantParts, gotParts)
|
|
}
|
|
|
|
func TestGlobalRedaction_JSON(t *testing.T) {
|
|
oldState := globalRedactor
|
|
globalRedactor = &dynamicRedactor{
|
|
denySet: make(map[string]struct{}),
|
|
}
|
|
defer func() { globalRedactor = oldState }()
|
|
|
|
var jsonBuffer bytes.Buffer
|
|
logger, flush := New("json-redaction-test",
|
|
WithJSONSink(&jsonBuffer, WithGlobalRedaction()),
|
|
)
|
|
RedactGlobally("foo")
|
|
RedactGlobally("bar")
|
|
logger.Info("this foo is :bar",
|
|
"foo", "bar",
|
|
"array", []string{"foo", "bar", "baz"},
|
|
"object", map[string]string{"foo": "bar"})
|
|
require.NoError(t, flush())
|
|
|
|
var parsedJSON map[string]any
|
|
require.NoError(t, json.Unmarshal(jsonBuffer.Bytes(), &parsedJSON))
|
|
assert.NotEmpty(t, parsedJSON["ts"])
|
|
delete(parsedJSON, "ts")
|
|
assert.Equal(t,
|
|
map[string]any{
|
|
"level": "info-0",
|
|
"logger": "json-redaction-test",
|
|
"msg": "this ***** is :*****",
|
|
"foo": "*****",
|
|
"array": []any{"foo", "bar", "baz"},
|
|
"object": map[string]interface{}{"foo": "bar"},
|
|
},
|
|
parsedJSON,
|
|
)
|
|
}
|
|
|
|
func TestToLogger(t *testing.T) {
|
|
var jsonBuffer bytes.Buffer
|
|
l, flush := New("service-name",
|
|
WithJSONSink(&jsonBuffer),
|
|
)
|
|
logger := ToLogger(l)
|
|
logger.Println("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
var parsedJSON map[string]any
|
|
assert.Nil(t, json.Unmarshal(jsonBuffer.Bytes(), &parsedJSON))
|
|
assert.NotEmpty(t, parsedJSON["ts"])
|
|
delete(parsedJSON, "ts")
|
|
delete(parsedJSON, "caller") // log.Logger adds a "caller" field
|
|
assert.Equal(t,
|
|
map[string]any{
|
|
"level": "info-0",
|
|
"logger": "service-name",
|
|
"msg": "yay",
|
|
},
|
|
parsedJSON,
|
|
)
|
|
}
|
|
|
|
func TestToSlogger(t *testing.T) {
|
|
var jsonBuffer bytes.Buffer
|
|
l, flush := New("service-name", WithJSONSink(&jsonBuffer))
|
|
logger := ToSlogger(l)
|
|
logger.Info("yay")
|
|
assert.Nil(t, flush())
|
|
|
|
var parsedJSON map[string]any
|
|
assert.Nil(t, json.Unmarshal(jsonBuffer.Bytes(), &parsedJSON))
|
|
assert.NotEmpty(t, parsedJSON["ts"])
|
|
delete(parsedJSON, "ts")
|
|
delete(parsedJSON, "caller") // slog.Logger adds a "caller" field
|
|
assert.Equal(t,
|
|
map[string]any{
|
|
"level": "info-0",
|
|
"logger": "service-name",
|
|
"msg": "yay",
|
|
},
|
|
parsedJSON,
|
|
)
|
|
}
|
|
|
|
func BenchmarkLoggerRedact(b *testing.B) {
|
|
msg := "this is a message with 'foo' in it"
|
|
logKvps := []any{"key", "value", "foo", "bar", "bar", "baz", "longval", "84hblnqwp97ewilbgoab8fhqlngahs6dl3i269haa"}
|
|
redactor := &dynamicRedactor{denySet: make(map[string]struct{})}
|
|
redactor.replacer.CompareAndSwap(nil, strings.NewReplacer())
|
|
|
|
b.Run("no redaction", func(b *testing.B) {
|
|
logger, flush := New("redaction-benchmark", WithJSONSink(
|
|
io.Discard,
|
|
func(conf *sinkConfig) { conf.redactor = redactor },
|
|
))
|
|
for i := 0; i < b.N; i++ {
|
|
logger.Info(msg, logKvps...)
|
|
}
|
|
require.NoError(b, flush())
|
|
})
|
|
b.Run("1 redaction", func(b *testing.B) {
|
|
logger, flush := New("redaction-benchmark", WithJSONSink(
|
|
io.Discard,
|
|
func(conf *sinkConfig) { conf.redactor = redactor },
|
|
))
|
|
redactor.configureForRedaction("84hblnqwp97ewilbgoab8fhqlngahs6dl3i269haa")
|
|
for i := 0; i < b.N; i++ {
|
|
logger.Info(msg, logKvps...)
|
|
}
|
|
require.NoError(b, flush())
|
|
})
|
|
b.Run("2 redactions", func(b *testing.B) {
|
|
logger, flush := New("redaction-benchmark", WithJSONSink(
|
|
io.Discard,
|
|
func(conf *sinkConfig) { conf.redactor = redactor },
|
|
))
|
|
redactor.configureForRedaction("84hblnqwp97ewilbgoab8fhqlngahs6dl3i269haa")
|
|
redactor.configureForRedaction("foo")
|
|
for i := 0; i < b.N; i++ {
|
|
logger.Info(msg, logKvps...)
|
|
}
|
|
require.NoError(b, flush())
|
|
})
|
|
b.Run("3 redactions", func(b *testing.B) {
|
|
logger, flush := New("redaction-benchmark", WithJSONSink(
|
|
io.Discard,
|
|
func(conf *sinkConfig) { conf.redactor = redactor },
|
|
))
|
|
redactor.configureForRedaction("84hblnqwp97ewilbgoab8fhqlngahs6dl3i269haa")
|
|
redactor.configureForRedaction("foo")
|
|
redactor.configureForRedaction("bar")
|
|
for i := 0; i < b.N; i++ {
|
|
logger.Info(msg, logKvps...)
|
|
}
|
|
require.NoError(b, flush())
|
|
})
|
|
}
|