From cfbc39fb7f4b683c73cd1c00c3272722bf0ed8c5 Mon Sep 17 00:00:00 2001 From: Deluan Date: Sun, 2 May 2021 16:39:25 -0400 Subject: [PATCH] Add log redacting, controlled by the new `EnableLogRedacting` config option (default `true`) Imported redacting code from https://github.com/whuang8/redactrus (thanks William Huang) Didn't use it as a dependency as it was too small and we want to keep dependencies at a minimum --- conf/configuration.go | 7 ++- go.mod | 1 + log/log.go | 22 +++++++ log/redactrus.go | 70 +++++++++++++++++++++ log/redactrus_test.go | 141 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 238 insertions(+), 3 deletions(-) create mode 100755 log/redactrus.go create mode 100755 log/redactrus_test.go diff --git a/conf/configuration.go b/conf/configuration.go index 92bf51962..730e7f543 100644 --- a/conf/configuration.go +++ b/conf/configuration.go @@ -44,6 +44,7 @@ type configOptions struct { EnableStarRating bool DefaultTheme string GATrackingID string + EnableLogRedacting bool AuthRequestLimit int AuthWindowLength time.Duration @@ -105,9 +106,8 @@ func Load() { log.SetLevelString(Server.LogLevel) log.SetLogSourceLine(Server.DevLogSourceLine) - if log.CurrentLevel() >= log.LevelDebug { - pretty.Printf("Loaded configuration from '%s': %# v\n", Server.ConfigFile, Server) - } + log.SetRedacting(Server.EnableLogRedacting) + log.Debug(pretty.Sprintf("Loaded configuration from '%s': %# v\n", Server.ConfigFile, Server)) // Call init hooks for _, hook := range hooks { @@ -150,6 +150,7 @@ func init() { viper.SetDefault("enablestarrating", true) viper.SetDefault("defaulttheme", "Dark") viper.SetDefault("gatrackingid", "") + viper.SetDefault("EnableLogRedacting", true) viper.SetDefault("authrequestlimit", 5) viper.SetDefault("authwindowlength", 20*time.Second) diff --git a/go.mod b/go.mod index 694d2db56..f4e0c8bfd 100644 --- a/go.mod +++ b/go.mod @@ -40,6 +40,7 @@ require ( github.com/spf13/cobra v1.1.3 github.com/spf13/jwalterweatherman v1.1.0 // indirect github.com/spf13/viper v1.7.1 + github.com/stretchr/testify v1.7.0 github.com/unrolled/secure v1.0.8 github.com/xrash/smetrics v0.0.0-20200730060457-89a2a8a1fb0b github.com/ziutek/mymysql v1.5.4 // indirect diff --git a/log/log.go b/log/log.go index 795f8312e..9fd89d7f6 100644 --- a/log/log.go +++ b/log/log.go @@ -16,6 +16,22 @@ type Level uint8 type LevelFunc = func(ctx interface{}, msg interface{}, keyValuePairs ...interface{}) +var redacted = &Hook{ + AcceptedLevels: logrus.AllLevels, + RedactionList: []string{ + // Keys from the config + "(ApiKey:\")[\\w]*", + "(Secret:\")[\\w]*", + "(Spotify.*ID:\")[\\w]*", + + // Subsonic query params + "([^\\w]t=)[\\w]+", + "([^\\w]s=)[\\w]+", + "([^\\w]p=)[\\w]+", + "([^\\w]jwt=)[\\w]+", + }, +} + const ( LevelCritical = Level(logrus.FatalLevel) LevelError = Level(logrus.ErrorLevel) @@ -65,6 +81,12 @@ func SetLogSourceLine(enabled bool) { logSourceLine = enabled } +func SetRedacting(enabled bool) { + if enabled { + defaultLogger.AddHook(redacted) + } +} + func NewContext(ctx context.Context, keyValuePairs ...interface{}) context.Context { if ctx == nil { ctx = context.Background() diff --git a/log/redactrus.go b/log/redactrus.go new file mode 100755 index 000000000..ba82da202 --- /dev/null +++ b/log/redactrus.go @@ -0,0 +1,70 @@ +package log + +// Copied from https://github.com/whuang8/redactrus (MIT License) +// Copyright (c) 2018 William Huang + +import ( + "reflect" + "regexp" + + "github.com/sirupsen/logrus" +) + +// Hook is a logrus hook for redacting information from logs +type Hook struct { + // Messages with a log level not contained in this array + // will not be dispatched. If empty, all messages will be dispatched. + AcceptedLevels []logrus.Level + RedactionList []string +} + +// Levels returns the user defined AcceptedLevels +// If AcceptedLevels is empty, all logrus levels are returned +func (h *Hook) Levels() []logrus.Level { + if len(h.AcceptedLevels) == 0 { + return logrus.AllLevels + } + return h.AcceptedLevels +} + +// LevelThreshold returns a []logrus.Level including all levels +// above and including the level given. If the provided level does not exit, +// an empty slice is returned. +func LevelThreshold(l logrus.Level) []logrus.Level { + //nolint + if l < 0 || int(l) > len(logrus.AllLevels) { + return []logrus.Level{} + } + return logrus.AllLevels[:l+1] +} + +// Fire redacts values in an log Entry that match +// with keys defined in the RedactionList +func (h *Hook) Fire(e *logrus.Entry) error { + for _, redactionKey := range h.RedactionList { + re, err := regexp.Compile(redactionKey) + if err != nil { + return err + } + + // Redact based on key matching in Data fields + for k, v := range e.Data { + if re.MatchString(k) { + e.Data[k] = "[REDACTED]" + continue + } + + // Redact based on value matching in Data fields + switch reflect.TypeOf(v).Kind() { + case reflect.String: + e.Data[k] = re.ReplaceAllString(v.(string), "$1[REDACTED]$2") + continue + } + } + + // Redact based on text matching in the Message field + e.Message = re.ReplaceAllString(e.Message, "$1[REDACTED]$2") + } + + return nil +} diff --git a/log/redactrus_test.go b/log/redactrus_test.go new file mode 100755 index 000000000..8fcc2e8e1 --- /dev/null +++ b/log/redactrus_test.go @@ -0,0 +1,141 @@ +package log + +import ( + "testing" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" +) + +var h = &Hook{} + +type levelsTest struct { + name string + acceptedLevels []logrus.Level + expected []logrus.Level + description string +} + +func TestLevels(t *testing.T) { + tests := []levelsTest{ + { + name: "undefinedAcceptedLevels", + acceptedLevels: []logrus.Level{}, + expected: logrus.AllLevels, + description: "All logrus levels expected, but did not receive them", + }, + { + name: "definedAcceptedLevels", + acceptedLevels: []logrus.Level{logrus.InfoLevel}, + expected: []logrus.Level{logrus.InfoLevel}, + description: "Logrus Info level expected, but did not receive that.", + }, + } + + for _, test := range tests { + fn := func(t *testing.T) { + h.AcceptedLevels = test.acceptedLevels + levels := h.Levels() + assert.Equal(t, test.expected, levels, test.description) + } + + t.Run(test.name, fn) + } +} + +type levelThresholdTest struct { + name string + level logrus.Level + expected []logrus.Level + description string +} + +func TestLevelThreshold(t *testing.T) { + tests := []levelThresholdTest{ + { + name: "unknownLogLevel", + level: logrus.Level(100), + expected: []logrus.Level{}, + description: "An empty Level slice was expected but was not returned", + }, + { + name: "errorLogLevel", + level: logrus.ErrorLevel, + expected: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel}, + description: "The panic, fatal, and error levels were expected but were not returned", + }, + } + + for _, test := range tests { + fn := func(t *testing.T) { + levels := LevelThreshold(test.level) + assert.Equal(t, test.expected, levels, test.description) + } + + t.Run(test.name, fn) + } +} + +func TestInvalidRegex(t *testing.T) { + e := &logrus.Entry{} + h = &Hook{RedactionList: []string{"\\"}} + err := h.Fire(e) + + assert.NotNil(t, err) +} + +type EntryDataValuesTest struct { + name string + redactionList []string + logFields logrus.Fields + expected logrus.Fields + description string //nolint +} + +// Test that any occurrence of a redaction pattern +// in the values of the entry's data fields is redacted. +func TestEntryDataValues(t *testing.T) { + tests := []EntryDataValuesTest{ + { + name: "match on key", + redactionList: []string{"Password"}, + logFields: logrus.Fields{"Password": "password123!"}, + expected: logrus.Fields{"Password": "[REDACTED]"}, + description: "Password value should have been redacted, but was not.", + }, + { + name: "string value", + redactionList: []string{"William"}, + logFields: logrus.Fields{"Description": "His name is William"}, + expected: logrus.Fields{"Description": "His name is [REDACTED]"}, + description: "William should have been redacted, but was not.", + }, + } + + for _, test := range tests { + fn := func(t *testing.T) { + logEntry := &logrus.Entry{ + Data: test.logFields, + } + h = &Hook{RedactionList: test.redactionList} + err := h.Fire(logEntry) + + assert.Nil(t, err) + assert.Equal(t, test.expected, logEntry.Data) + } + t.Run(test.name, fn) + } +} + +// Test that any occurrence of a redaction pattern +// in the entry's Message field is redacted. +func TestEntryMessage(t *testing.T) { + logEntry := &logrus.Entry{ + Message: "Secret Password: password123!", + } + h = &Hook{RedactionList: []string{`(Password: ).*`}} + err := h.Fire(logEntry) + + assert.Nil(t, err) + assert.Equal(t, "Secret Password: [REDACTED]", logEntry.Message) +}