Skip to content

Commit

Permalink
logger: fix logger being shared among different requests (#14)
Browse files Browse the repository at this point in the history
* HTTPAddLogger and HTTPRequestLogger add a new logger to the request context avoiding multiple requests sharing the same logger.
  • Loading branch information
AndersonQ authored Sep 9, 2020
1 parent c04f769 commit dbece75
Show file tree
Hide file tree
Showing 5 changed files with 82 additions and 12 deletions.
1 change: 1 addition & 0 deletions logger/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
6 changes: 3 additions & 3 deletions logger/middleware/events_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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() {
Expand Down Expand Up @@ -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"}
}
14 changes: 8 additions & 6 deletions logger/middleware/http.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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))
})
Expand All @@ -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),
Expand All @@ -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{}}

Expand All @@ -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)).
Expand Down
6 changes: 3 additions & 3 deletions logger/middleware/http_example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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() {
Expand Down Expand Up @@ -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"}
}
67 changes: 67 additions & 0 deletions logger/middleware/http_test.go
Original file line number Diff line number Diff line change
@@ -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))
}
}

0 comments on commit dbece75

Please sign in to comment.