From dbece7588a82ce9321aa5bff522d7a827249ed18 Mon Sep 17 00:00:00 2001 From: Anderson Queiroz Date: Wed, 9 Sep 2020 16:03:45 +0200 Subject: [PATCH] logger: fix logger being shared among different requests (#14) * HTTPAddLogger and HTTPRequestLogger add a new logger to the request context avoiding multiple requests sharing the same logger. --- logger/go.mod | 1 + logger/middleware/events_test.go | 6 +-- logger/middleware/http.go | 14 +++--- logger/middleware/http_example_test.go | 6 +-- logger/middleware/http_test.go | 67 ++++++++++++++++++++++++++ 5 files changed, 82 insertions(+), 12 deletions(-) create mode 100644 logger/middleware/http_test.go diff --git a/logger/go.mod b/logger/go.mod index b6e7c45..f0021c8 100644 --- a/logger/go.mod +++ b/logger/go.mod @@ -5,6 +5,7 @@ go 1.14 require ( github.com/blacklane/go-libs/tracking v0.0.1 github.com/blacklane/go-libs/x/events v0.0.0-20200729083625-bff51d3ec664 + github.com/google/go-cmp v0.5.0 github.com/rs/zerolog v1.18.0 golang.org/x/net v0.0.0-20200707034311-ab3426394381 // indirect ) diff --git a/logger/middleware/events_test.go b/logger/middleware/events_test.go index 4d18cb5..065c1e2 100644 --- a/logger/middleware/events_test.go +++ b/logger/middleware/events_test.go @@ -62,7 +62,7 @@ func ExampleEventsHandlerStatusLogger_success() { _ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"event_name_here"}`)}) // Output: - // {"level":"info","application":"ExampleEventsLogger","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","event":"event_name_here","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"} + // {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"} } func ExampleEventsHandlerStatusLogger_failure() { @@ -91,7 +91,7 @@ func ExampleEventsHandlerStatusLogger_failure() { _ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"event_name_here"}`)}) // Output: - // {"level":"info","application":"ExampleEventsLogger","request_id":"tracking_id-ExampleEventsLogger_Failure","tracking_id":"tracking_id-ExampleEventsLogger_Failure","event":"event_name_here","duration_ms":1000,"error":"bad","timestamp":"2009-11-10T23:00:01Z","message":"event_name_here failed"} + // {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Failure","tracking_id":"tracking_id-ExampleEventsLogger_Failure","duration_ms":1000,"error":"bad","timestamp":"2009-11-10T23:00:01Z","message":"event_name_here failed"} } func ExampleEventsHandlerStatusLoggerWithNameFn() { @@ -132,5 +132,5 @@ func ExampleEventsHandlerStatusLoggerWithNameFn() { _ = h.Handle(ctx, events.Event{Payload: []byte(`{"name":"event_name_here"}`)}) // Output: - // {"level":"info","application":"ExampleEventsLogger","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","event":"event_name_here","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"} + // {"level":"info","application":"ExampleEventsLogger","event":"event_name_here","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"event_name_here succeeded"} } diff --git a/logger/middleware/http.go b/logger/middleware/http.go index 2ab85b0..713a242 100644 --- a/logger/middleware/http.go +++ b/logger/middleware/http.go @@ -7,7 +7,6 @@ import ( "strings" "github.com/blacklane/go-libs/tracking" - "github.com/rs/zerolog" "github.com/blacklane/go-libs/logger" "github.com/blacklane/go-libs/logger/internal" @@ -17,6 +16,7 @@ import ( func HTTPAddLogger(log logger.Logger) func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log = log.With().Logger() // Creates a sub logger so all requests won't share the same logger instance ctx := log.WithContext(r.Context()) next.ServeHTTP(w, r.WithContext(ctx)) }) @@ -38,11 +38,12 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler { urlPath := strings.Split(r.URL.Path, "?")[0] // TODO: obfuscate query string values and show the keys ctx := r.Context() - l := logger.FromContext(ctx) + log := *logger.FromContext(ctx) logFields := map[string]interface{}{ internal.FieldEntryPoint: isEntryPoint(r), // TODO double check if they are a must and make them optional if not internal.FieldRequestDepth: tracking.RequestDepthFromCtx(ctx), + internal.FieldTrackingID: tracking.IDFromContext(ctx), internal.FieldRequestID: tracking.IDFromContext(ctx), internal.FieldTreePath: tracking.TreePathFromCtx(ctx), internal.FieldRoute: tracking.RequestRouteFromCtx(ctx), @@ -53,9 +54,10 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler { internal.FieldVerb: r.Method, internal.FieldPath: r.URL.Path, } - l.UpdateContext(func(c zerolog.Context) zerolog.Context { - return c.Fields(logFields) - }) + + log = log.With().Fields(logFields).Logger() + ctx = log.WithContext(ctx) + r = r.WithContext(ctx) ww := responseWriter{w: w, body: &bytes.Buffer{}} @@ -66,7 +68,7 @@ func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler { return } } - l.Info(). + log.Info(). Str(internal.FieldEvent, internal.EventRequestFinished). Int(internal.FieldStatus, ww.statusCode). Dur(internal.FieldRequestDuration, logger.Now().Sub(startTime)). diff --git a/logger/middleware/http_example_test.go b/logger/middleware/http_example_test.go index 4850f50..87454a1 100644 --- a/logger/middleware/http_example_test.go +++ b/logger/middleware/http_example_test.go @@ -61,7 +61,7 @@ func ExampleNewHttpHandlerLogger_simple() { h.ServeHTTP(w, r.WithContext(ctx)) // Output: - // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"} + // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"} } func ExampleNewHttpHandlerLogger_complete() { @@ -90,7 +90,7 @@ func ExampleNewHttpHandlerLogger_complete() { h.ServeHTTP(w, rr) // Output: - // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"42.42.42.42","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"42","route":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":1000,"timestamp":"2009-11-10T23:00:02Z","message":"GET /foo"} + // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"42.42.42.42","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"42","route":"","tracking_id":"42","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":1000,"timestamp":"2009-11-10T23:00:02Z","message":"GET /foo"} } func ExampleNewHttpHandlerLogger_skipRoutes() { @@ -121,5 +121,5 @@ func ExampleNewHttpHandlerLogger_skipRoutes() { h.ServeHTTP(w, rLive.WithContext(ctx)) // Output: - // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"} + // {"level":"info","application":"","entry_point":true,"host":"example.com","ip":"localhost","params":"bar=foo","path":"/foo","request_depth":0,"request_id":"","route":"","tracking_id":"","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":200,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /foo"} } diff --git a/logger/middleware/http_test.go b/logger/middleware/http_test.go new file mode 100644 index 0000000..d3883ce --- /dev/null +++ b/logger/middleware/http_test.go @@ -0,0 +1,67 @@ +package middleware + +import ( + "bytes" + "fmt" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/blacklane/go-libs/tracking/middleware" + "github.com/google/go-cmp/cmp" + + "github.com/blacklane/go-libs/logger" + "github.com/blacklane/go-libs/logger/internal" +) + +type chain []func(http.Handler) http.Handler + +func (m chain) apply(handler http.Handler) http.Handler { + h := m[len(m)-1](handler) + for i := len(m) - 2; i >= 0; i-- { + h = m[i](h) + } + + return h +} + +func TestHTTPRequestLogger(t *testing.T) { + want := `{"level":"info","application":"TestHTTPRequestLogger","entry_point":false,"host":"example.com","ip":"localhost","params":"","path":"/do_not_skip","request_depth":0,"request_id":"a_known_id","route":"","tracking_id":"a_known_id","tree_path":"","user_agent":"","verb":"GET","event":"request_finished","status":0,"request_duration":0,"timestamp":"2009-11-10T23:00:00Z","message":"GET /do_not_skip"}` + "\n" + + // 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) + }) + skipRoutes := []string{"/skip1", "/live"} + + buf := bytes.NewBufferString("") + w := httptest.NewRecorder() + + rSkip := httptest.NewRequest( + http.MethodGet, + fmt.Sprintf("http://example.com%s", skipRoutes[1]), nil) + rLog := httptest.NewRequest( + http.MethodGet, + fmt.Sprintf("http://example.com/do_not_skip"), nil) + rLog.Header.Set(internal.HeaderForwardedFor, "localhost") + rLog.Header.Set(internal.HeaderRequestID, "a_known_id") + + log := logger.New(buf, "TestHTTPRequestLogger") + ms := chain{middleware.RequestID, HTTPAddLogger(log), HTTPRequestLogger(skipRoutes)} + h := ms.apply(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + })) + + h.ServeHTTP(w, rSkip) + h.ServeHTTP(w, rSkip) + h.ServeHTTP(w, rSkip) + h.ServeHTTP(w, rSkip) + h.ServeHTTP(w, rSkip) + h.ServeHTTP(w, rLog) + + got := buf.String() + if want != got { + t.Errorf("\n\twant: %s,\n\tgot: %s\n\tdiff: %s", + want, got, cmp.Diff(want, got)) + } +}