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

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

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

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

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

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