Filtered param logger

middleware/param_logger.go

@@ -4,47 +4,94 @@ import (
 	"encoding/json"
 	"mime/multipart"
 	"net/url"
+	"strings"
 
 	"github.com/gobuffalo/buffalo"
 	"github.com/pkg/errors"
 )
 
+//ParameterFilterBlackList is the list of parameter names that will be filtered
+//from the application logs (see maskSecrets).
+//Important: this list will be used in case insensitive.
+var ParameterFilterBlackList = []string{
+	"Password",
+	"PasswordConfirmation",
+	"CreditCard",
+	"CVC",
+}
+
+var filteredIndicator = []string{"[FILTERED]"}
+
 // ParameterLogger logs form and parameter values to the logger
+type parameterLogger struct {
+	blacklist []string
+}
+
+// ParameterLogger logs form and parameter values to the loggers
 func ParameterLogger(next buffalo.Handler) buffalo.Handler {
+	pl := parameterLogger{
+		blacklist: ParameterFilterBlackList,
+	}
+
+	return func(c buffalo.Context) error {
+		defer func() {
+			req := c.Request()
+			if req.Method != "GET" {
+				if err := pl.logForm(c); err != nil {
+					c.Logger().Error(err)
+				}
+			}
+
+			b, err := json.Marshal(c.Params())
+			if err != nil {
+				c.Logger().Error(err)
+			}
+
+			c.LogField("params", string(b))
+		}()
+
+		return next(c)
+	}
+}
+
+//Middleware is a buffalo middleware function to connect this parameter filterer with buffalo
+func (pl parameterLogger) Middleware(next buffalo.Handler) buffalo.Handler {
 	return func(c buffalo.Context) error {
 		defer func() {
 			req := c.Request()
 			if req.Method != "GET" {
-				if err := postParamLogger(c); err != nil {
+				if err := pl.logForm(c); err != nil {
 					c.Logger().Error(err)
 				}
 			}
+
 			b, err := json.Marshal(c.Params())
 			if err != nil {
 				c.Logger().Error(err)
 			}
+
 			c.LogField("params", string(b))
 		}()
+
 		return next(c)
 	}
 }
 
-func postParamLogger(c buffalo.Context) error {
+func (pl parameterLogger) logForm(c buffalo.Context) error {
 	req := c.Request()
 	mp := req.MultipartForm
 	if mp != nil {
-		return multipartParamLogger(mp, c)
+		return pl.multipartParamLogger(mp, c)
 	}
 
-	b, err := json.Marshal(req.Form)
-	if err != nil {
+	if err := pl.addFormFieldTo(c, req.Form); err != nil {
 		return errors.WithStack(err)
 	}
-	c.LogField("form", string(b))
+
 	return nil
 }
 
-func multipartParamLogger(mp *multipart.Form, c buffalo.Context) error {
+func (pl parameterLogger) multipartParamLogger(mp *multipart.Form, c buffalo.Context) error {
 	uv := url.Values{}
 	for k, v := range mp.Value {
 		for _, vv := range v {
@@ -56,10 +103,44 @@ func multipartParamLogger(mp *multipart.Form, c buffalo.Context) error {
 			uv.Add(k, vv.Filename)
 		}
 	}
-	b, err := json.Marshal(uv)
-	if err != nil {
+
+	if err := pl.addFormFieldTo(c, uv); err != nil {
 		return errors.WithStack(err)
 	}
+	return nil
+}
+
+func (pl parameterLogger) addFormFieldTo(c buffalo.Context, form url.Values) error {
+	maskedForm := pl.maskSecrets(form)
+	b, err := json.Marshal(maskedForm)
+
+	if err != nil {
+		return err
+	}
+
 	c.LogField("form", string(b))
 	return nil
 }
+
+//maskSecrets matches ParameterFilterBlackList against parameters passed in the
+//request, and returns a copy of the request parameters replacing blacklisted params
+//with [FILTERED].
+func (pl parameterLogger) maskSecrets(form url.Values) url.Values {
+	if len(pl.blacklist) == 0 {
+		pl.blacklist = ParameterFilterBlackList
+	}
+
+	copy := url.Values{}
+	for key, values := range form {
+	blcheck:
+		for _, blacklisted := range pl.blacklist {
+			copy[key] = values
+			if strings.ToUpper(key) == strings.ToUpper(blacklisted) {
+				copy[key] = filteredIndicator
+				break blcheck
+			}
+
+		}
+	}
+	return copy
+}

middleware/param_logger_test.go

@@ -0,0 +1,122 @@
+package middleware
+
+import (
+	"net/url"
+	"testing"
+
+	"github.com/gobuffalo/buffalo"
+	"github.com/markbates/willie"
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+)
+
+func Test_maskSecrets(t *testing.T) {
+	r := require.New(t)
+	pl := parameterLogger{}
+
+	filteredForm := pl.maskSecrets(url.Values{
+		"FirstName":            []string{"Antonio"},
+		"MiddleName":           []string{"José"},
+		"LastName":             []string{"Pagano"},
+		"Password":             []string{"Secret!"},
+		"password":             []string{"Other"},
+		"pAssWorD":             []string{"Weird one"},
+		"PasswordConfirmation": []string{"Secret!"},
+
+		"SomeCVC": []string{"Untouched"},
+	})
+
+	r.Equal(filteredForm.Get("Password"), filteredIndicator[0])
+	r.Equal(filteredForm.Get("password"), filteredIndicator[0])
+	r.Equal(filteredForm.Get("pAssWorD"), filteredIndicator[0])
+	r.Equal(filteredForm.Get("PasswordConfirmation"), filteredIndicator[0])
+	r.Equal(filteredForm.Get("LastName"), "Pagano")
+	r.Equal(filteredForm.Get("SomeCVC"), "Untouched")
+}
+
+func Test_maskSecretsCustom(t *testing.T) {
+	r := require.New(t)
+	pl := parameterLogger{
+		blacklist: []string{
+			"FirstName", "LastName", "MiddleName",
+		},
+	}
+
+	filteredForm := pl.maskSecrets(url.Values{
+		"FirstName":            []string{"Antonio"},
+		"MiddleName":           []string{"José"},
+		"LastName":             []string{"Pagano"},
+		"Password":             []string{"Secret!"},
+		"password":             []string{"Other"},
+		"pAssWorD":             []string{"Weird one"},
+		"PasswordConfirmation": []string{"Secret!"},
+
+		"SomeCVC": []string{"Untouched"},
+	})
+
+	r.Equal(filteredForm.Get("Password"), "Secret!")
+	r.Equal(filteredForm.Get("password"), "Other")
+	r.Equal(filteredForm.Get("LastName"), filteredIndicator[0])
+	r.Equal(filteredForm.Get("SomeCVC"), "Untouched")
+}
+
+var lastEntry *logrus.Entry
+
+type testHook struct{}
+
+func (th testHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (th testHook) Fire(entry *logrus.Entry) error {
+	lastEntry = entry
+	return nil
+}
+
+type testLogger struct {
+	logrus.FieldLogger
+}
+
+func (l testLogger) WithField(s string, i interface{}) buffalo.Logger {
+	return testLogger{l.FieldLogger.WithField(s, i)}
+}
+
+func (l testLogger) WithFields(m map[string]interface{}) buffalo.Logger {
+	return testLogger{l.FieldLogger.WithFields(m)}
+}
+
+func newTestLogger() testLogger {
+	l := logrus.New()
+	l.AddHook(testHook{})
+	l.Level, _ = logrus.ParseLevel("debug")
+
+	return testLogger{l}
+}
+
+func Test_Logger(t *testing.T) {
+	r := require.New(t)
+	app := buffalo.New(buffalo.Options{})
+	app.Use(ParameterLogger)
+	app.Logger = newTestLogger()
+	emptyHandler := func(c buffalo.Context) error {
+		return nil
+	}
+
+	app.GET("/", emptyHandler)
+	app.POST("/", emptyHandler)
+
+	wi := willie.New(app)
+	wi.HTML("/?param=value").Get()
+
+	r.Contains(lastEntry.Data["params"], "{\"param\":[\"value\"]}")
+
+	wi.HTML("/").Post(url.Values{
+		"Password": []string{"123"},
+		"Name":     []string{"Antonio"},
+		"CVC":      []string{"123"},
+	})
+
+	r.Contains(lastEntry.Data["form"], "\"CVC\":[\"[FILTERED]\"]")
+	r.Contains(lastEntry.Data["form"], "\"Name\":[\"Antonio\"]")
+	r.Contains(lastEntry.Data["form"], "\"Password\":[\"[FILTERED]\"]")
+}