logger: adding body to http logger (#110)

* [CHAR-3182] adding body to http logger * [CHAR-3182] adding more tests * [CHAR-3182] testing changes * [CHAR-3182] fixing empty body validation * [CHAR-3182] adding log of error reading body * [CHAR-3182] adding default keys to filter email, and mobile phone
blacklane · Apr 11, 2022 · da5b17c · da5b17c
1 parent 0c01dce
commit da5b17c
Show file tree

Hide file tree

Showing 5 changed files with 159 additions and 4 deletions.
diff --git a/logger/go.mod b/logger/go.mod
@@ -7,16 +7,20 @@ require (
 	github.com/blacklane/go-libs/x/events v0.2.0
 	github.com/google/go-cmp v0.5.6
 	github.com/rs/zerolog v1.20.0
+	github.com/stretchr/testify v1.7.0
 )
 
 require (
 	github.com/confluentinc/confluent-kafka-go v1.4.2 // indirect
+	github.com/davecgh/go-spew v1.1.0 // indirect
 	github.com/golang/protobuf v1.4.2 // indirect
 	github.com/google/uuid v1.2.0 // indirect
+	github.com/pmezard/go-difflib v1.0.0 // indirect
 	go.opentelemetry.io/otel v1.0.0 // indirect
 	go.opentelemetry.io/otel/trace v1.0.0 // indirect
 	golang.org/x/net v0.0.0-20200625001655-4c5254603344 // indirect
 	golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d // indirect
 	google.golang.org/appengine v1.6.6 // indirect
 	google.golang.org/protobuf v1.25.0 // indirect
+	gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c // indirect
 )
diff --git a/logger/internal/constants.go b/logger/internal/constants.go
@@ -3,6 +3,7 @@ package internal
 // Internal constants
 const (
 	FieldApplication     = "application"
+	FieldBody            = "body"
 	FieldDuration        = "duration_ms"
 	FieldEvent           = "event"
 	FieldHTTPStatus      = "http_status"
@@ -26,3 +27,12 @@ const (
 	HeaderRequestID    = "X-Request-Id"
 	HeaderTrackingID   = "X-Tracking-Id"
 )
+
+const (
+	FilterTag  = "[FILTERED]"
+	FilterKeys = "filterKeys"
+)
+
+// DefaultKeys Please don't mutate it!
+var DefaultKeys = []string{"new_payer_email", "new_booker_email", "email", "new_booker_mobile_phone",
+	"old_booker_new_booker_mobile_phone", "new_payer_mobile_phone", "mobile_phone", "phone"}
diff --git a/logger/middleware/http.go b/logger/middleware/http.go
@@ -2,16 +2,18 @@ package middleware
 
 import (
 	"bytes"
+	"context"
+	"encoding/json"
 	"fmt"
+	"io/ioutil"
 	"net"
 	"net/http"
 	"strings"
 
-	"github.com/blacklane/go-libs/tracking"
-	"github.com/rs/zerolog"
-
 	"github.com/blacklane/go-libs/logger"
 	"github.com/blacklane/go-libs/logger/internal"
+	"github.com/blacklane/go-libs/tracking"
+	"github.com/rs/zerolog"
 )
 
 // HTTPAddLogger adds the logger into the request context.
@@ -25,6 +27,16 @@ func HTTPAddLogger(log logger.Logger) func(http.Handler) http.Handler {
 	}
 }
 
+// HTTPAddBodyFilters adds body filter values into the request context.
+func HTTPAddBodyFilters(filterKeys []string) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			ctx := context.WithValue(r.Context(), internal.FilterKeys, filterKeys)
+			next.ServeHTTP(w, r.WithContext(ctx))
+		})
+	}
+}
+
 // HTTPRequestLogger produces a log line with the request status and fields
 // following Blacklane's logging standard.
 func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
@@ -36,6 +48,17 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
 			log := *logger.FromContext(ctx)
 
 			trackingID := tracking.IDFromContext(ctx)
+			var body []byte
+
+			//save body to log later
+			if r.Body != http.NoBody {
+				var err error
+				body, err = ioutil.ReadAll(r.Body) //Body swap
+				if err != nil {
+					log.Log().Msg("error reading body")
+				}
+				r.Body = ioutil.NopCloser(bytes.NewBuffer(body))
+			}
 
 			logFields := map[string]interface{}{
 				internal.FieldHost:       r.Host,
@@ -61,9 +84,20 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
 					}
 				}
 
+				var b map[string]interface{}
+				if body != nil {
+					keys := getKeys(ctx, log)
+					b = filterBody(body, keys)
+				}
+
+				//post process fields
+				f := make(map[string]interface{})
+				f[internal.FieldBody] = b
+
 				getLogLevel(log, ww).
 					Int(internal.FieldHTTPStatus, ww.statusCode).
 					Dur(internal.FieldRequestDuration, logger.Now().Sub(startTime)).
+					Fields(f).
 					Msgf("%s %s", r.Method, urlPath)
 			}()
 
@@ -72,6 +106,44 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
 	}
 }
 
+func getKeys(ctx context.Context, log logger.Logger) []string {
+	keys, ok := ctx.Value(internal.FilterKeys).([]string)
+	if !ok {
+		log.Log().Msg("error getting filter keys from context")
+	}
+
+	if len(keys) == 0 {
+		return internal.DefaultKeys
+	}
+
+	return keys
+}
+
+func filterBody(body []byte, filterKeys []string) map[string]interface{} {
+	var b map[string]interface{}
+	err := json.Unmarshal(body, &b)
+	if err != nil {
+		return nil
+	}
+
+	for k, v := range b {
+		if _, ok := v.(map[string]interface{}); ok {
+			marshalData, err := json.Marshal(v)
+			if err != nil {
+				return nil
+			}
+			b[k] = filterBody(marshalData, filterKeys)
+		}
+
+		//validate tag list
+		toSearch := strings.Join(filterKeys, ",")
+		if strings.Contains(toSearch, k) {
+			b[k] = internal.FilterTag
+		}
+	}
+	return b
+}
+
 // Logger adds the logger into the request context.
 // Deprecated, use HTTPAddLogger instead.
 func Logger(log logger.Logger) func(http.Handler) http.Handler {

diff --git a/logger/middleware/http_example_test.go b/logger/middleware/http_example_test.go
@@ -67,6 +67,7 @@ func ExampleHTTPRequestLogger_simple() {
 	// Output:
 	// {
 	//   "application": "ExampleHTTPRequestLogger_simple",
+	//   "body": null,
 	//   "duration_ms": 0,
 	//   "host": "example.com",
 	//   "http_status": 200,
@@ -112,6 +113,7 @@ func ExampleHTTPRequestLogger_complete() {
 	// Output:
 	// {
 	//   "application": "ExampleHTTPRequestLogger_complete",
+	//   "body": null,
 	//   "duration_ms": 1000,
 	//   "host": "example.com",
 	//   "http_status": 200,
@@ -173,6 +175,7 @@ func ExampleHTTPRequestLogger_skipRoutes() {
 	// }
 	// {
 	//   "application": "ExampleHTTPRequestLogger_skipRoutes",
+	//   "body": null,
 	//   "duration_ms": 0,
 	//   "host": "example.com",
 	//   "http_status": 200,

diff --git a/logger/middleware/http_test.go b/logger/middleware/http_test.go
@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/google/go-cmp/cmp"
+	"github.com/stretchr/testify/assert"
 
 	"github.com/blacklane/go-libs/logger"
 	"github.com/blacklane/go-libs/logger/internal"
@@ -26,7 +27,7 @@ func (m chain) apply(handler http.Handler) http.Handler {
 }
 
 func TestHTTPRequestLogger(t *testing.T) {
-	want := `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"localhost","params":"","path":"/do_not_skip","request_id":"","tracking_id":"","user_agent":"","verb":"GET","http_status":200,"duration_ms":0,"timestamp":"2009-11-10T23:00:00.000Z","message":"GET /do_not_skip"}` + "\n"
+	want := `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"localhost","params":"","path":"/do_not_skip","request_id":"","tracking_id":"","user_agent":"","verb":"GET","http_status":200,"duration_ms":0,"body":null,"timestamp":"2009-11-10T23:00:00.000Z","message":"GET /do_not_skip"}` + "\n"
 
 	// Set current time function so we can control the request duration
 	logger.SetNowFunc(func() time.Time {
@@ -65,3 +66,68 @@ func TestHTTPRequestLogger(t *testing.T) {
 			want, got, cmp.Diff(want, got))
 	}
 }
+
+func TestHTTPAddBodyFilters(t *testing.T) {
+	// Set current time function so we can control the request duration
+	logger.SetNowFunc(func() time.Time {
+		return time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC)
+	})
+	type args struct {
+		filterKeys []string
+	}
+	tests := []struct {
+		name string
+		args args
+		want string
+	}{
+		{
+			name: "working with body",
+			args: args{
+				filterKeys: []string{"hello"},
+			},
+			want: `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"192.0.2.1","params":"","path":"/with_body","request_id":"","tracking_id":"","user_agent":"","verb":"POST","http_status":200,"duration_ms":0,"body":{"hello":"[FILTERED]"},"timestamp":"2009-11-10T23:00:00.000Z","message":"POST /with_body"}` + "\n",
+		},
+		{
+			name: "working body with embedded object",
+			args: args{
+				filterKeys: []string{"hello", "bye"},
+			},
+			want: `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"192.0.2.1","params":"","path":"/with_body","request_id":"","tracking_id":"","user_agent":"","verb":"POST","http_status":200,"duration_ms":0,"body":{"another":{"bye":"[FILTERED]"},"hello":"[FILTERED]"},"timestamp":"2009-11-10T23:00:00.000Z","message":"POST /with_body"}` + "\n",
+		},
+	}
+	for _, tt := range tests {
+		switch tt.name {
+		case "working with body":
+			buf := bytes.NewBufferString("")
+			w := httptest.NewRecorder()
+			r := httptest.NewRequest(
+				http.MethodPost,
+				"http://example.com/with_body", bytes.NewBuffer([]byte(`{"hello":"world"}`)))
+			log := logger.New(buf, "TestHTTPRequestLogger")
+			ms := chain{HTTPAddLogger(log), HTTPAddBodyFilters(tt.args.filterKeys), HTTPRequestLogger([]string{})}
+			h := ms.apply(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				w.Write([]byte(``))
+			}))
+
+			h.ServeHTTP(w, r)
+			assert.Equal(t, http.StatusOK, w.Code)
+			assert.Equal(t, tt.want, buf.String())
+
+		case "working body with embedded object":
+			buf := bytes.NewBufferString("")
+			w := httptest.NewRecorder()
+			r := httptest.NewRequest(
+				http.MethodPost,
+				"http://example.com/with_body", bytes.NewBuffer([]byte(`{"hello":"world","another":{"bye":"bye bye"}}`)))
+			log := logger.New(buf, "TestHTTPRequestLogger")
+			ms := chain{HTTPAddLogger(log), HTTPAddBodyFilters(tt.args.filterKeys), HTTPRequestLogger([]string{})}
+			h := ms.apply(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				w.Write([]byte(``))
+			}))
+
+			h.ServeHTTP(w, r)
+			assert.Equal(t, http.StatusOK, w.Code)
+			assert.Equal(t, tt.want, buf.String())
+		}
+	}
+}