diff --git a/base/logging.go b/base/logging.go index 077e13d529..c7a6be23f6 100644 --- a/base/logging.go +++ b/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 -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 diff --git a/base/logging_test.go b/base/logging_test.go index 549dc12fa3..079b0deea1 100644 --- a/base/logging_test.go +++ b/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: alice", func() { LogToR("TEST", "%s", username) }) + + assertLogContains(t, "WARNING: alice", func() { Warn("%s", username) }) + assertLogContains(t, "WARNING: alice", func() { WarnR("%s", username) }) +} + func Benchmark_LoggingPerformance(b *testing.B) { var logKeys = map[string]bool{ diff --git a/base/redactor.go b/base/redactor.go new file mode 100644 index 0000000000..2a0fd4af38 --- /dev/null +++ b/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 +} diff --git a/base/redactor_test.go b/base/redactor_test.go new file mode 100644 index 0000000000..256383cef2 --- /dev/null +++ b/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) + } +} diff --git a/base/redactor_userdata.go b/base/redactor_userdata.go new file mode 100644 index 0000000000..abedd56ed9 --- /dev/null +++ b/base/redactor_userdata.go @@ -0,0 +1,46 @@ +package base + +import "fmt" + +const ( + userDataPrefix = "" + userDataSuffix = "" +) + +// 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)) + } +} diff --git a/base/redactor_userdata_test.go b/base/redactor_userdata_test.go new file mode 100644 index 0000000000..36090993ce --- /dev/null +++ b/base/redactor_userdata_test.go @@ -0,0 +1,58 @@ +package base + +import ( + "math/big" + "testing" + + assert "github.com/couchbaselabs/go.assert" +) + +func TestUserDataRedact(t *testing.T) { + username := "alice" + userdata := UserData(username) + + // This is intentionally brittle (hardcoded redaction tags) + // We'd probably want to know if this changed by accident... + RedactUserData = true + assert.Equals(t, userdata.Redact(), ""+username+"") + + RedactUserData = false + assert.Equals(t, userdata.Redact(), username) +} + +func TestUD(t *testing.T) { + RedactUserData = true + defer func() { RedactUserData = false }() + + // Straight-forward string test. + ud := UD("hello world") + assert.Equals(t, ud.Redact(), userDataPrefix+"hello world"+userDataSuffix) + + // big.Int fulfils the Stringer interface, so we should get sensible values. + ud = UD(big.NewInt(1234)) + assert.Equals(t, ud.Redact(), userDataPrefix+"1234"+userDataSuffix) + + // Even plain structs could be redactable. + ud = UD(struct{}{}) + assert.Equals(t, ud.Redact(), userDataPrefix+"{}"+userDataSuffix) +} + +func BenchmarkUserDataRedact(b *testing.B) { + username := UserData("alice") + + // We'd expect a minor performance hit when redaction is enabled. + b.Run("Enabled", func(bn *testing.B) { + RedactUserData = true + for i := 0; i < bn.N; i++ { + username.Redact() + } + }) + + // When redaction is disabled, we should see no performance hit. + b.Run("Disabled", func(bn *testing.B) { + RedactUserData = false + for i := 0; i < bn.N; i++ { + username.Redact() + } + }) +}