From d4c7a805800a44239f11d806c254eb3b59dfe7ff Mon Sep 17 00:00:00 2001 From: Sergey Bolzhatov Date: Mon, 21 Oct 2024 18:17:43 +0300 Subject: [PATCH] Add log.MaskingLogger and log.Masker (#14) Add log.MaskingLogger and log.Masker --------- Co-authored-by: Sergey Bolzhatov --- log/config.go | 55 +++++++++- log/config_test.go | 69 +++++++++++++ log/logger.go | 11 +- log/logger_test.go | 136 +++++++++++++++++++++++++ log/masker.go | 99 ++++++++++++++++++ log/masker_test.go | 198 ++++++++++++++++++++++++++++++++++++ log/masking_logger.go | 201 +++++++++++++++++++++++++++++++++++++ log/masking_logger_test.go | 161 +++++++++++++++++++++++++++++ 8 files changed, 928 insertions(+), 2 deletions(-) create mode 100644 log/masker.go create mode 100644 log/masker_test.go create mode 100644 log/masking_logger.go create mode 100644 log/masking_logger_test.go diff --git a/log/config.go b/log/config.go index 21d637a..2fb5c97 100644 --- a/log/config.go +++ b/log/config.go @@ -28,6 +28,7 @@ const ( cfgKeyAddCaller = "log.addCaller" cfgKeyErrorNoVerbose = "log.error.noVerbose" cfgKeyErrorVerboseSuffix = "log.error.verboseSuffix" + cfgKeyMasking = "log.masking" ) // Default and restriction values. @@ -61,6 +62,8 @@ type Config struct { // {"level":"info","time":"...","msg":"starting application HTTP server...","caller":"httpserver/http_server.go:98","address":":8888"} AddCaller bool + Masking MaskingConfig + keyPrefix string } @@ -139,6 +142,7 @@ func (c *Config) SetProviderDefaults(dp config.DataProvider) { dp.SetDefault(cfgKeyFileRotationMaxBackups, DefaultFileRotationMaxBackups) dp.SetDefault(cfgKeyErrorNoVerbose, false) dp.SetDefault(cfgKeyErrorVerboseSuffix, "_verbose") + c.Masking.SetProviderDefaults(config.NewKeyPrefixedDataProvider(dp, cfgKeyMasking)) } var ( @@ -187,7 +191,9 @@ func (c *Config) Set(dp config.DataProvider) error { if c.ErrorVerboseSuffix, err = dp.GetString(cfgKeyErrorVerboseSuffix); err != nil { return err } - + if err := c.Masking.Set(config.NewKeyPrefixedDataProvider(dp, cfgKeyMasking)); err != nil { + return err + } return nil } @@ -235,3 +241,50 @@ func (c *Config) setFileOutputConfig(dp config.DataProvider) error { return nil } + +type MaskingConfig struct { + Enabled bool + UseDefaultRules bool + Rules []MaskingRuleConfig +} + +type MaskingRuleConfig struct { + Field string `mapstructure:"field"` + Formats []FieldMaskFormat `mapstructure:"formats"` + Masks []MaskConfig `mapstructure:"masks"` +} + +type MaskConfig struct { + RegExp string `mapstructure:"regexp"` + Mask string `mapstructure:"mask"` +} + +type FieldMaskFormat string + +const ( + FieldMaskFormatHTTPHeader FieldMaskFormat = "http_header" + FieldMaskFormatJSON FieldMaskFormat = "json" + FieldMaskFormatURLEncoded FieldMaskFormat = "urlencoded" + + cfgKeyMaskingEnabled = "enabled" + cfgKeyMaskingUseDefaultRules = "useDefaultRules" + cfgKeyMaskingRules = "rules" +) + +func (c *MaskingConfig) SetProviderDefaults(dp config.DataProvider) { + dp.SetDefault(cfgKeyMaskingUseDefaultRules, true) +} + +// Set sets logger configuration values from config.DataProvider. +func (c *MaskingConfig) Set(dp config.DataProvider) (err error) { + if c.Enabled, err = dp.GetBool(cfgKeyMaskingEnabled); err != nil { + return err + } + if c.UseDefaultRules, err = dp.GetBool(cfgKeyMaskingUseDefaultRules); err != nil { + return err + } + if err := dp.UnmarshalKey(cfgKeyMaskingRules, &c.Rules); err != nil { + return err + } + return nil +} diff --git a/log/config_test.go b/log/config_test.go index 64f1482..54191c9 100644 --- a/log/config_test.go +++ b/log/config_test.go @@ -62,6 +62,9 @@ log: require.Equal(t, 42, cfg.File.Rotation.MaxBackups) require.True(t, cfg.File.Rotation.Compress) require.True(t, cfg.AddCaller) + require.False(t, cfg.Masking.Enabled) + require.True(t, cfg.Masking.UseDefaultRules) + require.Nil(t, cfg.Masking.Rules) }) t.Run("errors", func(t *testing.T) { @@ -102,3 +105,69 @@ log: require.EqualError(t, err, `log.file.path: cannot be empty when "file" output is used`) }) } + +func TestMaskingConfig(t *testing.T) { + for _, tc := range []struct { + name string + cfg string + masking MaskingConfig + }{ + { + name: "enable default", + cfg: ` +log: + masking: + enabled: true`, + masking: MaskingConfig{Enabled: true, UseDefaultRules: true, Rules: nil}, + }, + { + name: "default with custom rules", + cfg: ` +log: + masking: + enabled: true + useDefaultRules: true + rules: + - field: "api_key" + formats: ["http_header", "json", "urlencoded"]`, + masking: MaskingConfig{ + Enabled: true, UseDefaultRules: true, Rules: []MaskingRuleConfig{ + { + Field: "api_key", + Formats: []FieldMaskFormat{FieldMaskFormatHTTPHeader, FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + }, + }, + }, + { + name: "ultimate", + cfg: ` +log: + masking: + enabled: true + useDefaultRules: false + rules: + - field: "api_key" + formats: ["http_header", "json", "urlencoded"] + masks: + - regexp: ".+?" + mask: "***"`, + masking: MaskingConfig{ + Enabled: true, UseDefaultRules: false, Rules: []MaskingRuleConfig{ + { + Field: "api_key", + Formats: []FieldMaskFormat{FieldMaskFormatHTTPHeader, FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + Masks: []MaskConfig{{RegExp: ".+?", Mask: "***"}}, + }, + }, + }, + }, + } { + t.Run(tc.name, func(t *testing.T) { + cfg := Config{} + err := config.NewDefaultLoader("").LoadFromReader(bytes.NewBuffer([]byte(tc.cfg)), config.DataTypeYAML, &cfg) + require.NoError(t, err) + require.Equal(t, tc.masking, cfg.Masking) + }) + } +} diff --git a/log/logger.go b/log/logger.go index 92e641e..1d1e68d 100644 --- a/log/logger.go +++ b/log/logger.go @@ -137,7 +137,16 @@ func NewLogger(cfg *Config) (FieldLogger, CloseFunc) { // to receive log line not in this file logfLogger = logfLogger.WithCaller().WithCallerSkip(1) } - return &LogfAdapter{logfLogger}, CloseFunc(closeFunc) + var logger FieldLogger = &LogfAdapter{logfLogger} + + if cfg.Masking.Enabled { + rules := cfg.Masking.Rules + if cfg.Masking.UseDefaultRules { + rules = append(rules, DefaultMasks...) + } + logger = NewMaskingLogger(logger, NewMasker(rules)) + } + return logger, CloseFunc(closeFunc) } // With returns a new logger with the given additional fields. diff --git a/log/logger_test.go b/log/logger_test.go index 1eb3653..6a70410 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -13,6 +13,7 @@ import ( "fmt" "io" "os" + "regexp" "testing" "github.com/ssgreg/logf" @@ -124,3 +125,138 @@ func TestTextFormat(t *testing.T) { require.Contains(t, buf.String(), `error="some error"`) require.Contains(t, buf.String(), fmt.Sprintf(`pid=%d`, os.Getpid())) } + +func TestLoggerWithMasking(t *testing.T) { + logger, closer := NewLogger(&Config{ + Masking: MaskingConfig{ + Enabled: true, UseDefaultRules: true, Rules: []MaskingRuleConfig{ + { + Field: "api_key", + Formats: []FieldMaskFormat{FieldMaskFormatHTTPHeader, FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + Masks: []MaskConfig{{RegExp: ".+?", Mask: "***"}}, + }, + }, + }, + }) + defer closer() + + mLogger, ok := logger.(MaskingLogger) + require.True(t, ok) + + require.IsType(t, &LogfAdapter{}, mLogger.log) + + masker, ok := mLogger.masker.(*Masker) + require.True(t, ok) + + expectedMasks := []FieldMasker{ + { + Field: "api_key", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`.+?`), + Mask: "***", + }, + { + RegExp: regexp.MustCompile(`(?i)api_key: .+?\r\n`), + Mask: "api_key: ***\r\n", + }, + { + RegExp: regexp.MustCompile(`(?i)"api_key"\s*:\s*".*?[^\\]"`), + Mask: `"api_key": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)api_key\s*=\s*[^&\s]+`), + Mask: "api_key=***", + }, + }, + }, + { + Field: "authorization", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)Authorization: .+?\r\n`), + Mask: "Authorization: ***\r\n", + }, + }, + }, + { + Field: "password", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"password"\s*:\s*".*?[^\\]"`), + Mask: `"password": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)password\s*=\s*[^&\s]+`), + Mask: "password=***", + }, + }, + }, + { + Field: "client_secret", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"client_secret"\s*:\s*".*?[^\\]"`), + Mask: `"client_secret": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)client_secret\s*=\s*[^&\s]+`), + Mask: "client_secret=***", + }, + }, + }, + { + Field: "access_token", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"access_token"\s*:\s*".*?[^\\]"`), + Mask: `"access_token": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)access_token\s*=\s*[^&\s]+`), + Mask: "access_token=***", + }, + }, + }, + { + Field: "refresh_token", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"refresh_token"\s*:\s*".*?[^\\]"`), + Mask: `"refresh_token": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)refresh_token\s*=\s*[^&\s]+`), + Mask: "refresh_token=***", + }, + }, + }, + { + Field: "id_token", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"id_token"\s*:\s*".*?[^\\]"`), + Mask: `"id_token": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)id_token\s*=\s*[^&\s]+`), + Mask: "id_token=***", + }, + }, + }, + { + Field: "assertion", + Masks: []Mask{ + { + RegExp: regexp.MustCompile(`(?i)"assertion"\s*:\s*".*?[^\\]"`), + Mask: `"assertion": "***"`, + }, + { + RegExp: regexp.MustCompile(`(?i)assertion\s*=\s*[^&\s]+`), + Mask: "assertion=***", + }, + }, + }, + } + require.Equal(t, expectedMasks, masker.FieldMasks) +} diff --git a/log/masker.go b/log/masker.go new file mode 100644 index 0000000..0dd825a --- /dev/null +++ b/log/masker.go @@ -0,0 +1,99 @@ +package log + +import ( + "regexp" + "strings" +) + +// Mask is used to mask a secret in strings. +type Mask struct { + RegExp *regexp.Regexp + Mask string +} + +func NewMask(cfg MaskConfig) Mask { + return Mask{regexp.MustCompile(cfg.RegExp), cfg.Mask} +} + +// FieldMasker is used to mask a field in different formats. +type FieldMasker struct { + Field string // Field is a name of a field used in RegExp, must be lowercase + Masks []Mask +} + +const ignoreCase = `(?i)` + +func NewFieldMasker(cfg MaskingRuleConfig) FieldMasker { + fMask := FieldMasker{Field: strings.ToLower(cfg.Field), Masks: make([]Mask, 0, len(cfg.Masks))} + + for _, repCfg := range cfg.Masks { + fMask.Masks = append(fMask.Masks, NewMask(repCfg)) + } + for _, format := range cfg.Formats { + switch format { + case FieldMaskFormatHTTPHeader: + fMask.Masks = append(fMask.Masks, NewMask(MaskConfig{ignoreCase + cfg.Field + `: .+?\r\n`, cfg.Field + ": ***\r\n"})) + case FieldMaskFormatJSON: + fMask.Masks = append(fMask.Masks, NewMask(MaskConfig{ignoreCase + `"` + cfg.Field + `"\s*:\s*".*?[^\\]"`, `"` + cfg.Field + `": "***"`})) + case FieldMaskFormatURLEncoded: + fMask.Masks = append(fMask.Masks, NewMask(MaskConfig{ignoreCase + cfg.Field + `\s*=\s*[^&\s]+`, cfg.Field + "=***"})) + } + } + return fMask +} + +// Masker is used to mask various secrets in strings. +type Masker struct { + FieldMasks []FieldMasker +} + +func NewMasker(rules []MaskingRuleConfig) *Masker { + r := &Masker{FieldMasks: make([]FieldMasker, 0, len(rules))} + for _, rule := range rules { + r.FieldMasks = append(r.FieldMasks, NewFieldMasker(rule)) + } + return r +} + +func (r *Masker) Mask(s string) string { + lower := strings.ToLower(s) + for _, fieldMask := range r.FieldMasks { + if strings.Contains(lower, fieldMask.Field) { + for _, rep := range fieldMask.Masks { + s = rep.RegExp.ReplaceAllString(s, rep.Mask) + } + } + } + return s +} + +var DefaultMasks = []MaskingRuleConfig{ + { + Field: "Authorization", + Formats: []FieldMaskFormat{FieldMaskFormatHTTPHeader}, + }, + { + Field: "password", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + { + Field: "client_secret", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + { + Field: "access_token", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + { + Field: "refresh_token", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + { + Field: "id_token", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, + { + Field: "assertion", + Formats: []FieldMaskFormat{FieldMaskFormatJSON, FieldMaskFormatURLEncoded}, + }, +} diff --git a/log/masker_test.go b/log/masker_test.go new file mode 100644 index 0000000..9185782 --- /dev/null +++ b/log/masker_test.go @@ -0,0 +1,198 @@ +// nolint: lll +package log + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +func TestMasker(t *testing.T) { + replAToB := MaskingRuleConfig{Masks: []MaskConfig{{`A`, `B`}}} + replBToA := MaskingRuleConfig{Masks: []MaskConfig{{`B`, `A`}}} + cases := []struct { + masker *Masker + input string + expected string + }{ + { + NewMasker([]MaskingRuleConfig{replAToB}), + "ABA", + "BBB", + }, + { + NewMasker([]MaskingRuleConfig{replAToB, replBToA}), + "ABA", + "AAA", + }, + { + NewMasker([]MaskingRuleConfig{replBToA, replAToB}), + "ABA", + "BBB", + }, + } + for _, c := range cases { + out := c.masker.Mask(c.input) + require.Equal(t, c.expected, out) + } +} + +func TestDefaultMasks(t *testing.T) { + tests := []struct { + name, s, expected string + }{ + { + name: "simple", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg&grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_secret=***&grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + }, + { + name: "short", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_secret=***", + }, + { + name: "after", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000&client_secret=***", + }, + { + name: "middle", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + }, + { + name: "new line", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000\n", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000\n", + }, + { + name: "new line 2", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg\n&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***\n&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + }, + { + name: "crlf", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000\r\n", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000\r\n", + }, + { + name: "crlf2", + s: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=eyJhbGciOiJSUzI1NiIsImVhcCI6MSwiaXJpIjoiY2hlNWphMmowaW9kN3E0c21kbDAiLCJraWQiOiU1NzVkYjAifQ.eyJhdWQiOiJ1cy1jbG91ZC5hY3JvbmlzLmNvbSIs7QI0ctcs7ZN8OsCDUxhM4liWPGg\r\n&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + expected: "POST /idp/token HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test-agent\r\nContent-Length: 3691\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\ngrant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***\r\n&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000", + }, + { + name: "Authorization", + s: "GET /abc HTTP/1.1\r\nHost: example.com\r\nAuthorization: Bearer abcdef\r\nContent-Length: 3691\r\n\r\n", + expected: "GET /abc HTTP/1.1\r\nHost: example.com\r\nAuthorization: ***\r\nContent-Length: 3691\r\n\r\n", + }, + { + name: "authorization", + s: "GET /abc HTTP/1.1\r\nHost: example.com\r\nauthorization: Bearer abcdef\r\nContent-Length: 3691\r\n\r\n", + expected: "GET /abc HTTP/1.1\r\nHost: example.com\r\nAuthorization: ***\r\nContent-Length: 3691\r\n\r\n", + }, + { + name: "password JSON", + s: `{"password": "abc"},`, + expected: `{"password": "***"},`, + }, + { + name: "password URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&password=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&password=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "client_secret JSON", + s: `{"client_secret": "abc"},`, + expected: `{"client_secret": "***"},`, + }, + { + name: "client_secret URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&client_secret=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "access_token JSON", + s: `{"access_token": "abc"},`, + expected: `{"access_token": "***"},`, + }, + { + name: "access_token URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&access_token=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&access_token=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "refresh_token JSON", + s: `{"refresh_token": "abc"},`, + expected: `{"refresh_token": "***"},`, + }, + { + name: "refresh_token URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&refresh_token=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&refresh_token=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "id_token JSON", + s: `{"id_token": "ab\"c"},`, + expected: `{"id_token": "***"},`, + }, + { + name: "id_token URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&id_token=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&id_token=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "assertion JSON", + s: `{"assertion": "abc"},`, + expected: `{"assertion": "***"},`, + }, + { + name: "assertion URL encoded", + s: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&assertion=asdf$%^*(&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + expected: `grant_type=urn%3Aietf%3Aparams%3Aoauth%3Agrant-type%3Ajwt-bearer&assertion=***&scope=scope1%3Atenant-id%0000000000-0000-0000-0000-000000000000`, + }, + { + name: "Handle multiple masks", + s: `POST / HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test/1/\r\nContent-Length: 123\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_id=f1e3bb97-552d-4a21-aa7d-543ad8bde840&client_secret=supersecret&refresh_token=token123&id_token=idToken`, + expected: `POST / HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test/1/\r\nContent-Length: 123\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_id=f1e3bb97-552d-4a21-aa7d-543ad8bde840&client_secret=***&refresh_token=***&id_token=***`, + }, + { + name: "No masking needed", + s: `POST / HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test/1/\r\nContent-Length: 123\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_id=f1e3bb97-552d-4a21-aa7d-543ad8bde840&grant_type=test`, + expected: `POST / HTTP/1.1\r\nHost: example.com\r\nUser-Agent: test/1/\r\nContent-Length: 123\r\nContent-Type: application/x-www-form-urlencoded\r\nAccept-Encoding: gzip\r\n\r\nclient_id=f1e3bb97-552d-4a21-aa7d-543ad8bde840&grant_type=test`, + }, + } + + masker := NewMasker(DefaultMasks) + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + out := masker.Mask(test.s) + require.Equal(t, test.expected, out) + }) + } +} + +func BenchmarkMasker(b *testing.B) { + r := NewMasker(DefaultMasks) + + for _, test := range []struct{ name, text string }{ + { + name: "0 matches", + text: `{"passwSDFord": "abc", "clientSDF_secret": "clientkey123", "accesSDFSs_token": "accessToken123", "refreshSDF_token": "refresh123"}, assertSDFion=abcdef&client_sSDFecret=sjdlkfjl&refreSDFsh_token=sjdkjlk&api_kSDFey=lskdjflksjdl& AuthorSDFization: Bearer ABC`, + }, + { + name: "1 match", + text: `{"passwSDFord": "abc", "clientSDF_secret": "clientkey123", "accesSDFSs_token": "accessToken123", "refreshSDF_token": "refresh123"}, assertSDFion=abcdef&client_sSDFecret=sjdlkfjl&refreSDFsh_token=sjdkjlk&id_token=lskdjflksjdl& AuthorSDFization: Bearer ABC`, + }, + { + name: "2 matches", + text: `{"passwSDFord": "abc", "clientSDF_secret": "clientkey123", "accesSDFSs_token": "accessToken123", "refreshSDF_token": "refresh123"}, assertSDFion=abcdef&client_sSDFecret=sjdlkfjl&refresh_token=sjdkjlk&id_token=lskdjflksjdl& AuthorSDFization: Bearer ABC`, + }, + } { + b.Run(test.name, func(b *testing.B) { + for i := 0; i < b.N; i++ { + r.Mask(test.text) + } + }) + } +} diff --git a/log/masking_logger.go b/log/masking_logger.go new file mode 100644 index 0000000..3c68668 --- /dev/null +++ b/log/masking_logger.go @@ -0,0 +1,201 @@ +package log + +import ( + "errors" + "fmt" + "io" + "reflect" + "unsafe" + + "github.com/ssgreg/logf" +) + +// MaskingLogger is a logger that masks secrets in log fields. +// Use it to make sure secrets are not leaked in logs: +// - If you dump HTTP requests and responses in debug mode. +// - If a secret is passed via URL (like &api_key=), network connectivity error will leak it. +type MaskingLogger struct { + log FieldLogger + masker StringMasker +} + +type StringMasker interface { + Mask(s string) string +} + +func NewMaskingLogger(l FieldLogger, r StringMasker) FieldLogger { + return MaskingLogger{l, r} +} + +// With returns a new logger with the given additional fields. +func (l MaskingLogger) With(fs ...Field) FieldLogger { + return MaskingLogger{l.log.With(l.maskFields(fs)...), l.masker} +} + +// Debug logs a formatted Message at "debug" level. +func (l MaskingLogger) Debug(text string, fs ...Field) { + l.log.Debug(l.masker.Mask(text), l.maskFields(fs)...) +} + +// Info logs a formatted Message at "info" level. +func (l MaskingLogger) Info(text string, fs ...Field) { + l.log.Info(l.masker.Mask(text), l.maskFields(fs)...) +} + +// Warn logs a formatted Message at "warn" level. +func (l MaskingLogger) Warn(text string, fs ...Field) { + l.log.Warn(l.masker.Mask(text), l.maskFields(fs)...) +} + +// Error logs a formatted Message at "error" level. +func (l MaskingLogger) Error(text string, fs ...Field) { + l.log.Error(l.masker.Mask(text), l.maskFields(fs)...) +} + +// Debugf logs a formatted Message at "debug" level. +func (l MaskingLogger) Debugf(format string, args ...interface{}) { + l.Debug(fmt.Sprintf(format, args...)) +} + +// Infof logs a formatted Message at "info" level. +func (l MaskingLogger) Infof(format string, args ...interface{}) { + l.Info(fmt.Sprintf(format, args...)) +} + +// Warnf logs a formatted Message at "warn" level. +func (l MaskingLogger) Warnf(format string, args ...interface{}) { + l.Warn(fmt.Sprintf(format, args...)) +} + +// Errorf logs a formatted Message at "error" level. +func (l MaskingLogger) Errorf(format string, args ...interface{}) { + l.Error(fmt.Sprintf(format, args...)) +} + +// AtLevel calls the given fn if logging a Message at the specified level +// is enabled, passing a LogFunc with the bound level. +func (l MaskingLogger) AtLevel(level Level, fn func(logFunc LogFunc)) { + l.log.AtLevel(level, func(logFunc LogFunc) { + fn(func(msg string, fs ...Field) { + logFunc(l.masker.Mask(msg), l.maskFields(fs)...) + }) + }) +} + +// WithLevel returns a new logger with additional level check. +// All log messages below ("debug" is a minimal level, "error" - maximal) +// the given AND previously set level will be ignored (i.e. it makes sense to only increase level). +func (l MaskingLogger) WithLevel(level Level) FieldLogger { + return MaskingLogger{l.log.WithLevel(level), l.masker} +} + +var stringSliceType = reflect.TypeOf([]string{}) + +// maskFields masks secrets in log fields +// nolint: funlen,gocyclo +func (l MaskingLogger) maskFields(fields []Field) []Field { + var changedFields []*Field + for i, field := range fields { + field := field // Important when working with unsafe.Pointer + switch field.Type { + case logf.FieldTypeBytesToString: + s := *(*string)(unsafe.Pointer(&field.Bytes)) // nolint: gosec + masked := l.masker.Mask(s) + if masked != s { + if changedFields == nil { + changedFields = make([]*Field, len(fields)) + } + newField := String(field.Key, masked) + changedFields[i] = &newField + } + case logf.FieldTypeError: + if field.Any != nil { + err := field.Any.(error) + s := err.Error() + masked := l.masker.Mask(s) + if masked != s { + if changedFields == nil { + changedFields = make([]*Field, len(fields)) + } + newField := NamedError(field.Key, newMaskedError(err, l.masker, masked)) + changedFields[i] = &newField + } + } + case logf.FieldTypeBytes, logf.FieldTypeRawBytes: + if field.Bytes != nil { + masked := l.masker.Mask(string(field.Bytes)) + if masked != string(field.Bytes) { + if changedFields == nil { + changedFields = make([]*Field, len(fields)) + } + newField := logf.ConstBytes(field.Key, []byte(masked)) + changedFields[i] = &newField + } + } + case logf.FieldTypeArray: + if field.Any != nil { + value := reflect.ValueOf(field.Any) + if value.CanConvert(stringSliceType) { + ss := value.Convert(stringSliceType).Interface().([]string) + var changed bool + masked := make([]string, len(ss)) + for i, s := range ss { + masked[i] = l.masker.Mask(s) + if masked[i] != s { + changed = true + } + } + if changed { + if changedFields == nil { + changedFields = make([]*Field, len(fields)) + } + newField := Strings(field.Key, masked) + changedFields[i] = &newField + } + } + } + case logf.FieldTypeAny: + // NOTE: Not masked + } + } + + if changedFields == nil { + return fields + } + + newFields := make([]Field, len(fields)) + copy(newFields, fields) + for i, field := range changedFields { + if field != nil { + newFields[i] = *field + } + } + + return newFields +} + +func newMaskedError(err error, r StringMasker, masked string) error { + switch err.(type) { + case fmt.Formatter: + return maskedError{ + s: masked, + verboseS: r.Mask(fmt.Sprintf("%+v", err)), + } + default: + return errors.New(masked) + } +} + +// maskedError is needed to support logf "error_verbose" field. +type maskedError struct { + s string + verboseS string +} + +func (e maskedError) Error() string { + return e.s +} + +func (e maskedError) Format(f fmt.State, verb rune) { + _, _ = io.WriteString(f, e.verboseS) +} diff --git a/log/masking_logger_test.go b/log/masking_logger_test.go new file mode 100644 index 0000000..fd784a3 --- /dev/null +++ b/log/masking_logger_test.go @@ -0,0 +1,161 @@ +package log_test + +import ( + "errors" + "fmt" + "io" + "net/http" + "net/http/httptest" + "os" + "testing" + + "github.com/ssgreg/logf" + "github.com/stretchr/testify/require" + + "github.com/acronis/go-appkit/httpserver/middleware" + "github.com/acronis/go-appkit/log" + "github.com/acronis/go-appkit/log/logtest" +) + +func TestMaskingLogger(t *testing.T) { + recorder := logtest.NewRecorder() + maskingLog := log.NewMaskingLogger(recorder, log.NewMasker(log.DefaultMasks)) + + checkRecordedLogAndReset := func(wantText string, wantLevel log.Level, wantFields ...log.Field) { + entries := recorder.Entries() + require.Len(t, entries, 1) + require.Equal(t, wantText, entries[0].Text) + require.Equal(t, wantLevel, entries[0].Level) + require.ElementsMatch(t, wantFields, entries[0].Fields) + recorder.Reset() + } + + maskingLog.Error("client_secret=123", log.String("value", "client_secret=333"), log.Error(errors.New("client_secret=665"))) + checkRecordedLogAndReset("client_secret=***", log.LevelError, log.String("value", "client_secret=***"), + log.Error(errors.New("client_secret=***"))) + + maskingLog.Info("client_secret=123", log.String("value", "client_secret=346"), log.Error(errors.New("client_secret=668"))) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, log.String("value", "client_secret=***"), + log.Error(errors.New("client_secret=***"))) + + maskingLog.Warn("client_secret=123", log.String("value", "client_secret=332"), log.Error(errors.New("client_secret=965"))) + checkRecordedLogAndReset("client_secret=***", log.LevelWarn, log.String("value", "client_secret=***"), + log.Error(errors.New("client_secret=***"))) + + maskingLog.Debug("client_secret=123", log.String("value", "client_secret=333"), log.Error(errors.New("client_secret=665"))) + checkRecordedLogAndReset("client_secret=***", log.LevelDebug, log.String("value", "client_secret=***"), + log.Error(errors.New("client_secret=***"))) + + maskingLog.Errorf("client_secret=%d", 123) + checkRecordedLogAndReset("client_secret=***", log.LevelError) + + maskingLog.Infof("client_secret=%d", 123) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo) + + maskingLog.Warnf("client_secret=%d", 123) + checkRecordedLogAndReset("client_secret=***", log.LevelWarn) + + maskingLog.Debugf("client_secret=%d", 123) + checkRecordedLogAndReset("client_secret=***", log.LevelDebug) + + maskingLog.With(log.String("value", "client_secret=346"), log.NamedError("error_field", errors.New("client_secret=668"))).Info("client_secret=123") + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, log.String("value", "client_secret=***"), + log.NamedError("error_field", errors.New("client_secret=***"))) + + maskingLog.AtLevel(log.LevelInfo, func(l log.LogFunc) { + l("client_secret=123", log.String("value", "client_secret=123")) + }) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, log.String("value", "client_secret=***")) + + maskingLog.WithLevel(log.LevelInfo).Info("client_secret=123", log.String("value", "client_secret=***")) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, log.String("value", "client_secret=***")) + + maskingLog.Error("abc", log.Error(fmtError{errors.New("client_secret=665")})) + errS := fmt.Sprintf("%s", recorder.Entries()[0].Fields[0].Any) + require.Contains(t, errS, "client_secret=***") + require.Contains(t, errS, "password=***") + recorder.Reset() + + maskingLog.Info("client_secret=123", log.Strings("value", []string{"client_secret=346"})) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, log.Strings("value", []string{"client_secret=***"})) + + maskingLog.Info("client_secret=123", log.Bytes("value", []byte("client_secret=346"))) + checkRecordedLogAndReset("client_secret=***", log.LevelInfo, logf.ConstBytes("value", []byte("client_secret=***"))) +} + +type fmtError struct { + err error +} + +func (e fmtError) Error() string { + return e.err.Error() +} + +func (e fmtError) Format(f fmt.State, verb rune) { + _, _ = io.WriteString(f, e.Error()+" password=123") +} + +var logFile = "output.log" + +func BenchmarkMaskingLogger(b *testing.B) { + defaultLogger, closer := log.NewLogger(&log.Config{ + Output: log.OutputFile, Format: log.FormatJSON, Level: log.LevelInfo, ErrorVerboseSuffix: "_verbose", AddCaller: true, File: log.FileOutputConfig{ + Path: logFile, + Rotation: log.FileRotationConfig{ + MaxSize: 2 << 30, + }, + }, + }) + defer func() { + closer() + _ = os.Remove(logFile) + }() + + for _, test := range []struct { + name string + logger log.FieldLogger + }{ + { + name: "Logger (file)", + logger: defaultLogger, + }, + { + name: "MaskingLogger", + logger: log.NewMaskingLogger(defaultLogger, log.NewMasker(log.DefaultMasks)), + }, + } { + b.Run(test.name, func(b *testing.B) { + loggingOpts := middleware.LoggingOpts{ + RequestStart: true, + AddRequestInfoToLogger: true, + RequestHeaders: map[string]string{"X-Original-URI": "original_uri", "Referer": "referer"}, + } + logger := test.logger.With( + log.String("logger", "ApiGateway"), + log.String("build", "1257"), + log.String("source", "api-gateway"), + ) + mw := middleware.LoggingWithOpts(logger, loggingOpts) + handler := mw(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + middleware.GetLoggerFromContext(r.Context()).Info("custom message") + w.WriteHeader(http.StatusOK) + })) + + for i := 0; i < b.N; i++ { + req := httptest.NewRequest(http.MethodGet, "https://au1-cloud.acronis.com/api/gateway/authorize", nil) + req.Header.Set("X-Forwarded-For", "181.58.39.81") + req.Header.Set("X-Original-URI", "/bc/api/task_manager/v2/activities") + req.Header.Set("Referer", "https://au1-cloud.acronis.com/ui/") + req.Header.Set("User-Agent", "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36") + + ctx := req.Context() + ctx = middleware.NewContextWithRequestID(ctx, "03497b44a93143e2c5ff8e0e0e57232a") + ctx = middleware.NewContextWithInternalRequestID(ctx, "cs4kq8gcedg46frf7v8g") + req = req.WithContext(ctx) + w := httptest.NewRecorder() + + handler.ServeHTTP(w, req) + } + }) + } +}