#3295 - Add log redaction infrastructure (#3308)

* Add Redactor interface, UserData type, and redacted log functions

* Add global toggle for RedactUserData

* Improve benchmark for UserData Enabled/Disabled

* Remove incorrect key param in redacted log funcs

* Remove unnecessary bench ResetTimer

* Add ToUD helper method

* Use log redaction in auth package

* Expand redacted args slice

* Add unit test for redacted log function outputs

* Reassign global logger back to original

* Disable RedactUserData by default

* Add redaction to missed warn

* Move log redaction into log package

* revert auth

* Move log redaction back into base

* Moved RedactionLevel into redactor file, made Redact function private again, added test for RedactionLevel

base/logging.go

@@ -211,10 +211,11 @@ type LogAppenderConfig struct {
 	// Filename is the file to write logs to.  Backup log files will be retained
 	// in the same directory.  It uses <processname>-lumberjack.log in
 	// os.TempDir() if empty.
-	LogFilePath *string            `json:",omitempty"`
-	LogKeys     []string           `json:",omitempty"` // Log keywords to enable
-	LogLevel    Level              `json:",omitempty"`
-	Rotation    *LogRotationConfig `json:",omitempty"`
+	LogFilePath    *string            `json:",omitempty"`
+	LogKeys        []string           `json:",omitempty"` // Log keywords to enable
+	LogLevel       Level              `json:",omitempty"`
+	Rotation       *LogRotationConfig `json:",omitempty"`
+	RedactionLevel RedactionLevel     `json:",omitempty"`
 }
 
 type LoggingConfigMap map[string]*LogAppenderConfig
@@ -437,6 +438,11 @@ func LogTo(key string, format string, args ...interface{}) {
 	}
 }
 
+// LogToR redacts any arguments implementing the Redactor interface before calling LogTo
+func LogToR(key, format string, args ...interface{}) {
+	LogTo(key, format, redact(args)...)
+}
+
 func EnableLogKey(key string) {
 	logLock.Lock()
 	defer logLock.Unlock()
@@ -483,6 +489,11 @@ func Logf(format string, args ...interface{}) {
 	}
 }
 
+// LogfR redacts any arguments implementing the Redactor interface before calling Logf
+func LogfR(format string, args ...interface{}) {
+	Logf(format, redact(args)...)
+}
+
 // If the error is not nil, logs its description and the name of the calling function.
 // Returns the input error for easy chaining.
 func LogError(err error) error {
@@ -509,6 +520,11 @@ func Warn(format string, args ...interface{}) {
 	}
 }
 
+// WarnR redacts any arguments implementing the Redactor interface before calling Warn
+func WarnR(format string, args ...interface{}) {
+	Warn(format, redact(args)...)
+}
+
 // Logs a highlighted message prefixed with "TEMP". This function is intended for
 // temporary logging calls added during development and not to be checked in, hence its
 // distinctive name (which is visible and easy to search for before committing.)
@@ -522,12 +538,22 @@ func LogPanic(format string, args ...interface{}) {
 	panic(fmt.Sprintf(format, args...))
 }
 
+// LogPanicR redacts any arguments implementing the Redactor interface before calling LogPanic
+func LogPanicR(format string, args ...interface{}) {
+	LogPanic(format, redact(args)...)
+}
+
 // Logs a warning to the console, then exits the process.
 func LogFatal(format string, args ...interface{}) {
 	logWithCaller(fgRed, "FATAL", format, args...)
 	os.Exit(1)
 }
 
+// LogFatalR redacts any arguments implementing the Redactor interface before calling LogFatal
+func LogFatalR(format string, args ...interface{}) {
+	LogFatal(format, redact(args)...)
+}
+
 func logWithCaller(color string, prefix string, format string, args ...interface{}) {
 	message := fmt.Sprintf(format, args...)
 	logLock.RLock()
@@ -625,6 +651,7 @@ func CreateRollingLogger(logConfig *LogAppenderConfig) {
 	if logConfig != nil {
 		SetLogLevel(logConfig.LogLevel.sgLevel())
 		ParseLogFlags(logConfig.LogKeys)
+		SetRedaction(logConfig.RedactionLevel)
 
 		if logConfig.LogFilePath == nil {
 			return

base/logging_test.go

@@ -10,12 +10,41 @@
 package base
 
 import (
+	"bytes"
 	"errors"
-	"github.com/couchbaselabs/go.assert"
 	"log"
 	"testing"
+
+	"github.com/couchbaselabs/go.assert"
 )
 
+// asserts that the logs produced by function f contain string s.
+func assertLogContains(t *testing.T, s string, f func()) {
+	originalLogger := logger
+	b := bytes.Buffer{}
+
+	// temporarily override logger for the function call
+	logger = log.New(&b, "", 0)
+	defer func() { logger = originalLogger }()
+
+	f()
+	assert.StringContains(t, b.String(), s)
+}
+
+func TestRedactedLogFuncs(t *testing.T) {
+	username := UD("alice")
+
+	RedactUserData = true
+	defer func() { RedactUserData = false }()
+	EnableLogKey("TEST")
+
+	assertLogContains(t, "TEST: alice", func() { LogTo("TEST", "%s", username) })
+	assertLogContains(t, "TEST: <ud>alice</ud>", func() { LogToR("TEST", "%s", username) })
+
+	assertLogContains(t, "WARNING: alice", func() { Warn("%s", username) })
+	assertLogContains(t, "WARNING: <ud>alice</ud>", func() { WarnR("%s", username) })
+}
+
 func Benchmark_LoggingPerformance(b *testing.B) {
 
 	var logKeys = map[string]bool{

base/redactor.go

@@ -0,0 +1,84 @@
+package base
+
+import (
+	"errors"
+	"fmt"
+	"strings"
+)
+
+// Redactor provides an interface for log redaction.
+type Redactor interface {
+	// Redact returns the given string in a redacted form. This may be tagged,
+	// changed, hashed, or removed completely depending on desired behaviour.
+	Redact() string
+}
+
+// redact performs an *in-place* redaction on the input slice, and returns it.
+// This should only be consumed by logging funcs. E.g. fmt.Printf(fmt, redact(args))
+func redact(args []interface{}) []interface{} {
+	for i, v := range args {
+		if r, ok := v.(Redactor); ok {
+			args[i] = r.Redact()
+		}
+	}
+	return args
+}
+
+type RedactionLevel int
+
+const (
+	RedactNone RedactionLevel = iota
+	RedactPartial
+	RedactFull
+)
+
+func SetRedaction(redactionLevel RedactionLevel) {
+	Logf("Log redaction level: %s", redactionLevel)
+	switch redactionLevel {
+	case RedactFull:
+		RedactUserData = true
+	case RedactPartial:
+		RedactUserData = true
+	case RedactNone:
+		RedactUserData = false
+	default:
+		RedactUserData = false
+	}
+}
+
+// String returns a lower-case ASCII representation of the log redaction level.
+func (l RedactionLevel) String() string {
+	switch l {
+	case RedactNone:
+		return "none"
+	case RedactPartial:
+		return "partial"
+	case RedactFull:
+		return "full"
+	default:
+		return fmt.Sprintf("RedactionLevel(%d)", l)
+	}
+}
+
+// MarshalText marshals the RedactionLevel to text.
+func (l *RedactionLevel) MarshalText() ([]byte, error) {
+	if l == nil {
+		return nil, errors.New("can't marshal a nil *RedactionLevel to text")
+	}
+	return []byte(l.String()), nil
+}
+
+// UnmarshalText unmarshals text to a RedactionLevel.
+func (l *RedactionLevel) UnmarshalText(text []byte) error {
+	switch strings.ToLower(string(text)) {
+	case "none":
+		*l = RedactNone
+	case "partial":
+		*l = RedactPartial
+	case "full":
+		*l = RedactFull
+	default:
+		return fmt.Errorf("unrecognized level: %v", string(text))
+	}
+	return nil
+}

base/redactor_test.go

@@ -0,0 +1,110 @@
+package base
+
+import (
+	"math/big"
+	"testing"
+
+	assert "github.com/couchbaselabs/go.assert"
+)
+
+func TestRedactHelper(t *testing.T) {
+	RedactUserData = true
+	defer func() { RedactUserData = false }()
+
+	ptr := UserData("hello")
+
+	var in = []interface{}{
+		UserData("alice"),
+		&ptr,
+		"bob",
+		1234,
+		big.NewInt(1234),
+		struct{}{},
+	}
+
+	out := redact(in)
+
+	// Since redact performs an in-place redaction,
+	// we'd expect the input slice to change too.
+	assert.DeepEquals(t, out, in)
+
+	// Check that ptr wasn't redacted outside of the slice... this could be dangerous!
+	assert.Equals(t, string(ptr), "hello")
+
+	// Verify that only the types implementing Redactor have changed.
+	assert.Equals(t, out[0], UserData("alice").Redact())
+	assert.Equals(t, out[1], ptr.Redact())
+	assert.Equals(t, out[2], "bob")
+	assert.Equals(t, out[3], 1234)
+	assert.Equals(t, out[4].(*big.Int).String(), big.NewInt(1234).String())
+	assert.Equals(t, out[5], struct{}{})
+}
+
+func TestSetRedaction(t *testing.T) {
+	// Hits the default case
+	SetRedaction(-1)
+	assert.Equals(t, RedactUserData, false)
+
+	SetRedaction(RedactFull)
+	assert.Equals(t, RedactUserData, true)
+
+	SetRedaction(RedactPartial)
+	assert.Equals(t, RedactUserData, true)
+
+	SetRedaction(RedactNone)
+	assert.Equals(t, RedactUserData, false)
+}
+
+func TestRedactionLevelMarshalText(t *testing.T) {
+	var level RedactionLevel
+	level = RedactNone
+	text, err := level.MarshalText()
+	assert.Equals(t, err, nil)
+	assert.Equals(t, string(text), "none")
+
+	level = RedactPartial
+	text, err = level.MarshalText()
+	assert.Equals(t, err, nil)
+	assert.Equals(t, string(text), "partial")
+
+	level = RedactFull
+	text, err = level.MarshalText()
+	assert.Equals(t, err, nil)
+	assert.Equals(t, string(text), "full")
+}
+
+func TestRedactionLevelUnmarshalText(t *testing.T) {
+	var level RedactionLevel
+	err := level.UnmarshalText([]byte("none"))
+	assert.Equals(t, err, nil)
+	assert.Equals(t, level, RedactNone)
+
+	err = level.UnmarshalText([]byte("partial"))
+	assert.Equals(t, err, nil)
+	assert.Equals(t, level, RedactPartial)
+
+	err = level.UnmarshalText([]byte("full"))
+	assert.Equals(t, err, nil)
+	assert.Equals(t, level, RedactFull)
+
+	err = level.UnmarshalText([]byte("asdf"))
+	assert.Equals(t, err.Error(), "unrecognized level: asdf")
+}
+
+func BenchmarkRedactHelper(b *testing.B) {
+	RedactUserData = true
+	defer func() { RedactUserData = false }()
+
+	var data = []interface{}{
+		UserData("alice"),
+		"bob",
+		1234,
+		big.NewInt(1234),
+		struct{}{},
+	}
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		redact(data)
+	}
+}

base/redactor_userdata.go

@@ -0,0 +1,46 @@
+package base
+
+import "fmt"
+
+const (
+	userDataPrefix = "<ud>"
+	userDataSuffix = "</ud>"
+)
+
+// RedactUserData is a global toggle for user data redaction.
+var RedactUserData = false
+
+// UserData is a type which implements the Redactor interface for logging purposes of user data.
+//
+//  User data is data that is stored into Couchbase by the application user account:
+//  - Key and value pairs in JSON documents, or the key exclusively
+//  - Application/Admin usernames that identify the human person
+//  - Query statements included in the log file collected by support that leak the document fields (Select floor_price from stock).
+//  - Names and email addresses asked during product registration and alerting
+//  - Usernames
+//  - Document xattrs
+type UserData string
+
+// Redact tags the string with UserData tags for post-processing.
+func (ud UserData) Redact() string {
+	if !RedactUserData {
+		return string(ud)
+	}
+	return userDataPrefix + string(ud) + userDataSuffix
+}
+
+// Compile-time interface check.
+var _ Redactor = UserData("")
+
+// UD returns a UserData type for any given value.
+func UD(i interface{}) UserData {
+	switch v := i.(type) {
+	case string:
+		return UserData(v)
+	case fmt.Stringer:
+		return UserData(v.String())
+	default:
+		// Fall back to a slower but safe way of getting a string from any type.
+		return UserData(fmt.Sprintf("%v", v))
+	}
+}