diff --git a/logger/context.go b/logger/context.go
index 9e5195975b6b8afe3e507222853bec3d057a2d17..244ba31b0bf1e500a2a9b45b9029e702e71e07d2 100644
--- a/logger/context.go
+++ b/logger/context.go
@@ -9,7 +9,7 @@ func GetContextLogger() Logger {
}
func LogMessageWithFields(fields map[string]interface{}, message interface{}) {
- globalLogger.WithFields(fields).log(LevelInfo, 1, fmt.Sprintf("%v", message))
+ globalLogger.withFields(fields).log(LevelInfo, 1, fmt.Sprintf("%v", message))
}
func LogMessage(format string, a ...interface{}) {
@@ -18,12 +18,12 @@ func LogMessage(format string, a ...interface{}) {
func LogError(fields map[string]interface{}, err error) {
// sendRaygunError(fields, err)
- globalLogger.WithFields(fields).log(LevelError, 1, fmt.Sprintf("%+v", err))
+ globalLogger.withFields(fields).log(LevelError, 1, fmt.Sprintf("%+v", err))
}
func LogErrorMessage(message interface{}, err error) {
if err != nil || message != nil {
- globalLogger.WithFields(map[string]interface{}{
+ globalLogger.withFields(map[string]interface{}{
"error": fmt.Sprintf("%+v", err),
}).log(LevelError, 1, fmt.Sprintf("%v", message))
}
@@ -34,11 +34,11 @@ func LogWarningMessage(format string, a ...interface{}) {
}
func LogWarning(fields map[string]interface{}, err error) {
- globalLogger.WithFields(fields).log(LevelWarn, 1, fmt.Sprintf("%+v", err))
+ globalLogger.withFields(fields).log(LevelWarn, 1, fmt.Sprintf("%+v", err))
}
func SQLDebugInfo(sql string) {
- globalLogger.WithFields(map[string]interface{}{
+ globalLogger.withFields(map[string]interface{}{
"sql": sql,
}).log(LevelInfo, 1, "SQL")
}
diff --git a/logger/global.go b/logger/global.go
index ca25a0273c19b7227d0b5d4106cb02ecad9338e1..c5f21956249cd83285663118cfdb8abbbd4b1aa0 100644
--- a/logger/global.go
+++ b/logger/global.go
@@ -36,12 +36,12 @@ func New() Logger {
//this should only be used outside of a request context
//or anywhere if you have a single threaded process
func Fatalf(format string, args ...interface{}) {
- globalLogger.WithFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprintf(format, args...))
+ globalLogger.withFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprintf(format, args...))
os.Exit(1)
}
func Fatal(args ...interface{}) {
- globalLogger.WithFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprint(args...))
+ globalLogger.withFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprint(args...))
os.Exit(1)
}
diff --git a/logger/logger.go b/logger/logger.go
index 6899dc3300b8a60bbcd33d11ccacc8c1941662de..2f65ed00f017f9c0fdd455ef2df89567e744b79a 100644
--- a/logger/logger.go
+++ b/logger/logger.go
@@ -1,8 +1,11 @@
package logger
import (
+ "bytes"
+ "encoding/json"
"fmt"
"io"
+ "regexp"
"strings"
"time"
@@ -23,17 +26,25 @@ type Logger interface {
Tracef(format string, args ...interface{})
Trace(args ...interface{})
- WithFields(data map[string]interface{}) logger
+ WithFields(data map[string]interface{}) Logger
+ WithSensitiveWord(word string) Logger
+ SensitiveWords() []string
}
type logger struct {
- level Level
- writer io.Writer
- data map[string]interface{}
+ level Level
+ writer io.Writer
+ data map[string]interface{}
+ sensitiveWords map[string]bool //map key is lowercase word
IFormatter
}
-func (l logger) WithFields(data map[string]interface{}) logger {
+func (l logger) WithFields(data map[string]interface{}) Logger {
+ l = l.withFields(data)
+ return l
+}
+
+func (l logger) withFields(data map[string]interface{}) logger {
newLogger := logger{
level: l.level,
writer: l.writer,
@@ -49,12 +60,104 @@ func (l logger) WithFields(data map[string]interface{}) logger {
return newLogger
}
+//word may only consist of alpha-numerics with delimeters inside,
+//e.g. OTP "12345" or Card number "1234-12345678-12345678-1234"
+//and the delimiters may be spaces, dashes, underscores, slashes and dots
+//and it is considered case insensitive
+const sensitiveWordPattern = `[a-z0-9]([a-z0-9\.\\\/ _-]*[a-z0-9])*`
+
+var sensitiveWordRegex = regexp.MustCompile("^" + sensitiveWordPattern + "$")
+
+func (l logger) WithSensitiveWord(word string) Logger {
+ l = l.withSensitiveWord(word)
+ return l
+}
+
+func (l logger) withSensitiveWord(word string) logger {
+ word = strings.ToLower(word)
+ if !sensitiveWordRegex.MatchString(word) {
+ l.Errorf("cannot add \"%s\" as sensitive word, expecting %s", word, sensitiveWordPattern)
+ return l
+ }
+ if l.sensitiveWords == nil {
+ l.sensitiveWords = map[string]bool{word: true}
+ } else {
+ l.sensitiveWords[word] = true
+ }
+ return l
+}
+
+func (l logger) SensitiveWords() []string {
+ words := make([]string, len(l.sensitiveWords))
+ i := 0
+ for w := range l.sensitiveWords {
+ words[i] = w
+ i++
+ }
+ return words
+}
+
+const delimiters = "()[]{}!@#$%^&*-=_+;:'\"|\\/?<>,.~` \n\r"
+
+func FilterSensitiveWordsMap(s string, wordsMap map[string]bool) (filtered string, changed bool) {
+ if len(wordsMap) == 0 {
+ return s, false
+ }
+
+ changed = false
+ f := []byte(s)
+ for word := range wordsMap {
+ //it will be inefficient to compile regex for each word in each context
+ //much quicker to just look for the word and see if it is delimited as required
+ //not to mach short words as part of longer words which may expose the word be assumption
+ //e.g. OTP "202" should not match part of a date 2021-01-02 making it ***1-01-02
+ wLen := len(word)
+ offset := 0
+ fLen := len(f)
+ for offset < fLen {
+ index := bytes.Index(f[offset:], []byte(word)) + offset
+ if index < offset {
+ break //word not found
+ }
+
+ //found the word, check delimiters before/after
+ if index > 0 && strings.IndexByte(delimiters, f[index-1]) < 0 {
+ offset = index + 1 //word match without delimiter before
+ continue
+ }
+
+ if index+wLen < fLen && strings.IndexByte(delimiters, f[index+wLen]) < 0 {
+ offset = index + 1 //word match without delimiter after
+ continue
+ }
+
+ //has delimiter after, this is a word match, replace any length match with 3 stars "***"
+ //pad length if required
+ pad := 0
+ for fLen < index+3 {
+ f = append(f, ' ')
+ fLen++
+ pad++
+ }
+ f = append(f[:index+3], f[index+wLen:fLen-pad]...)
+ f[index] = '*'
+ f[index+1] = '*'
+ f[index+2] = '*'
+ fLen = len(f)
+ changed = true
+ offset = index + 3 //for loop skipped index over word, now skip offset over delimiter
+ }
+ }
+ filtered = string(f)
+ return
+}
+
func (l logger) Fatalf(format string, args ...interface{}) {
- l.WithFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprintf(format, args...))
+ l.withFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprintf(format, args...))
}
func (l logger) Fatal(args ...interface{}) {
- l.WithFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprint(args...))
+ l.withFields(map[string]interface{}{"call_stack": errors.Stack(3)}).log(LevelFatal, 1, fmt.Sprint(args...))
}
func (l logger) Errorf(format string, args ...interface{}) {
@@ -106,6 +209,22 @@ func (l logger) log(level Level, skip int, msg string) {
Data: l.data,
Message: strings.ReplaceAll(msg, "\n", ";"),
}
+
+ //filter sensitive words out of data values and message text
+ for dataName, dataValue := range entry.Data {
+ dataString, ok := dataValue.(string)
+ if !ok {
+ jsonValue, err := json.Marshal(dataValue)
+ if err != nil {
+ continue
+ }
+ dataString = string(jsonValue)
+ }
+ if filteredString, changed := FilterSensitiveWordsMap(dataString, l.sensitiveWords); changed {
+ entry.Data[dataName] = filteredString
+ }
+ }
+ entry.Message, _ = FilterSensitiveWordsMap(entry.Message, l.sensitiveWords)
l.writer.Write(l.Format(entry))
}
}
diff --git a/logger/logger_test.go b/logger/logger_test.go
new file mode 100644
index 0000000000000000000000000000000000000000..cd3df521f392ba9d80108277be24fc8f797a71c8
--- /dev/null
+++ b/logger/logger_test.go
@@ -0,0 +1,54 @@
+package logger_test
+
+import (
+ "testing"
+
+ "gitlab.com/uafrica/go-utils/logger"
+)
+
+func TestFilter(t *testing.T) {
+ logger.SetGlobalFormat(logger.NewConsole())
+ logger.SetGlobalLevel(logger.LevelDebug)
+ tests := []test{
+ {"Your new OTP is 12345", map[string]bool{"12345": true}, "Your new OTP is ***"}, //match at end of string
+ {"Your new OTP is 12345.", map[string]bool{"12345": true}, "Your new OTP is ***."}, //match in middle
+ {"12345 is your new OTP.", map[string]bool{"12345": true}, "*** is your new OTP."}, //match at start
+ {"Your new OTP is 12345. Do not repeat 12345/123456", map[string]bool{"12345": true}, "Your new OTP is ***. Do not repeat ***/123456"}, //no match on longer word
+ {"Send 12345\n12345 is the code you should type", map[string]bool{"12345": true}, "Send ***\n*** is the code you should type"}, //match before/after newline
+ //
+ {"Your new OTP is 111-11", map[string]bool{"111-11": true}, "Your new OTP is ***"},
+ {"The secret IP is 1.2.3.4 but 11.2.3.4 and 1.2.3.44 is public", map[string]bool{"1.2.3.4": true}, "The secret IP is *** but 11.2.3.4 and 1.2.3.44 is public"}, //match with delimiters in the word
+ //
+ {"1.2.3.4.5.6.7.8", map[string]bool{"1": true}, "***.2.3.4.5.6.7.8"}, //short replace at start
+ {"1.2.3.4.5.6.7.8", map[string]bool{"4": true}, "1.2.3.***.5.6.7.8"}, //short replace in middle
+ {"1.2.3.4.5.6.7.8", map[string]bool{"8": true}, "1.2.3.4.5.6.7.***"}, //short replace at end
+ //
+ {"11.22.33.44.55.66.77.88", map[string]bool{"11": true}, "***.22.33.44.55.66.77.88"}, //short replace at start
+ {"11.22.33.44.55.66.77.88", map[string]bool{"44": true}, "11.22.33.***.55.66.77.88"}, //short replace in middle
+ {"11.22.33.44.55.66.77.88", map[string]bool{"88": true}, "11.22.33.44.55.66.77.***"}, //short replace at end
+ //
+ {"111.222.333.444.555.666.777.888", map[string]bool{"111": true}, "***.222.333.444.555.666.777.888"}, //exact replace at start
+ {"111.222.333.444.555.666.777.888", map[string]bool{"444": true}, "111.222.333.***.555.666.777.888"}, //exact replace in middle
+ {"111.222.333.444.555.666.777.888", map[string]bool{"888": true}, "111.222.333.444.555.666.777.***"}, //exact replace at end
+ //
+ {"1111.2222.3333.4444.5555.6666.7777.8888", map[string]bool{"1111": true}, "***.2222.3333.4444.5555.6666.7777.8888"}, //long replace at start
+ {"1111.2222.3333.4444.5555.6666.7777.8888", map[string]bool{"4444": true}, "1111.2222.3333.***.5555.6666.7777.8888"}, //long replace in middle
+ {"1111.2222.3333.4444.5555.6666.7777.8888", map[string]bool{"8888": true}, "1111.2222.3333.4444.5555.6666.7777.***"}, //long replace at end
+ }
+ for testNr, test := range tests {
+ filtered, changed := logger.FilterSensitiveWordsMap(test.Text, test.Words)
+ if test.Filtered != filtered {
+ t.Fatalf("test[%d]: %s --%+v--> %s != %s", testNr, test.Text, test.Words, filtered, test.Filtered)
+ }
+ if test.Text != test.Filtered && !changed {
+ t.Fatalf("test[%d]: changed=%v != %v", testNr, changed, test.Text != test.Filtered)
+ }
+ t.Logf("test[%d]: %s --%+v--> %s", testNr, test.Text, test.Words, filtered)
+ }
+}
+
+type test struct {
+ Text string
+ Words map[string]bool
+ Filtered string
+}
diff --git a/logs/api-logs.go b/logs/api-logs.go
index da4c1b5ab9a192cb688f5f275f2a9a55f899132b..3474270456b53322454741d8f5040253f92c7e38 100644
--- a/logs/api-logs.go
+++ b/logs/api-logs.go
@@ -9,7 +9,6 @@ import (
"github.com/aws/aws-lambda-go/events"
"gitlab.com/uafrica/go-utils/errors"
- "gitlab.com/uafrica/go-utils/logger"
"gitlab.com/uafrica/go-utils/queues"
)
@@ -27,7 +26,7 @@ func LogIncomingAPIRequest(startTime time.Time, requestID string, claim map[stri
}
//todo: filter out some noisy (method+path)
- logger.Debugf("claim: %+v", claim)
+ //logger.Debugf("claim: %+v", claim)
endTime := time.Now()
@@ -103,7 +102,8 @@ func LogIncomingAPIRequest(startTime time.Time, requestID string, claim map[stri
apiLog.Response.Body = "<not logged>"
}
- logger.Debugf("Send api-log to SQS: %+v", apiLog)
+ //this global logger debug will expose sensitive info ... do not leave it in the code for production!
+ //logger.Debugf("Send api-log to SQS: %+v", apiLog)
//todo: filter out sensitive values (e.g. OTP)
if _, err := producer.NewEvent("API_LOGS").
diff --git a/service/context.go b/service/context.go
index 49595c4e41efb4a280844ba665998d145a298eaf..4ae3f444ed42a6e9825dc12442d53ef21bd124bb 100644
--- a/service/context.go
+++ b/service/context.go
@@ -58,6 +58,8 @@ type Context interface {
//Sleep() does a time.Sleep and record it in log actions so that we can account for the time spent sleeping
//vs e.g. time waiting for outgoing API calls or db queries
Sleep(dur time.Duration)
+
+ AddSensitiveWord(word string)
}
//values: are added to context and logger
@@ -77,7 +79,7 @@ func (s service) NewContext(base context.Context, requestID string, values map[s
base = context.WithValue(base, valueKey(n), v)
}
l := logger.New().WithFields(values)
- l.IFormatter = l.IFormatter.NextColor()
+ //l.NextColor() - to be fixed but not showing colours in mage or cloud watch, so not urgent...
Ctx = &serviceContext{
Context: base,
@@ -241,3 +243,7 @@ func (ctx *serviceContext) Sleep(dur time.Duration) {
logs.LogSleep(startTime)
}
}
+
+func (ctx *serviceContext) AddSensitiveWord(word string) {
+ ctx.Logger = ctx.Logger.WithSensitiveWord(word)
+}