logger: adds events middleware to log the event handler status (#12)

- add EventsHandlerStatusLogger to update the logger with the tracking id and log each handed event with event name, duration and error if any
- update constants
- add new HTTP... middleware and deprecate the ones without prefix

logger/internal/constants.go

@@ -1,9 +1,11 @@
 package internal
 
 const (
-	// For a definition of each constant check the logging standards on http://handbook.int.blacklane.io/monitoring/kiev.html
+	// Field log constants
+	FieldTrackingID = "tracking_id"
+	FieldDuration   = "duration_ms"
 
-	// Fields constants
+	// Fields, Event and Headers constants following http://handbook.int.blacklane.io/monitoring/kiev.html
 
 	FieldApplication  = "application"
 	FieldTimestamp    = "timestamp"
@@ -24,17 +26,12 @@ const (
 	FieldStatus          = "status"
 	FieldRequestDuration = "request_duration"
 
-	FieldErrorClass   = "error_class"
-	FieldErrorMessage = "error_message"
-	FieldBody         = "body"
-
 	// Event constants
 
 	// EventRequestFinished should be used as 'event' when logging a finished request/job
 	EventRequestFinished = "request_finished"
 
 	// Headers constants
-
 	HeaderForwardedFor = "X-Forwarded-For"
 	HeaderRequestID    = "X-Request-Id"
 	HeaderRequestDepth = "X-Request-Depth"

logger/middleware/events.go

@@ -2,17 +2,90 @@ package middleware
 
 import (
 	"context"
+	"encoding/json"
 
+	"github.com/blacklane/go-libs/tracking"
 	"github.com/blacklane/go-libs/x/events"
+	"github.com/rs/zerolog"
 
 	"github.com/blacklane/go-libs/logger"
+	"github.com/blacklane/go-libs/logger/internal"
 )
 
-// EventsAddLogger add the logger into the context
+// EventsAddLogger adds the logger into the context.
 func EventsAddLogger(log logger.Logger) events.Middleware {
 	return func(next events.Handler) events.Handler {
 		return events.HandlerFunc(func(ctx context.Context, e events.Event) error {
 			return next.Handle(log.WithContext(ctx), e)
 		})
 	}
 }
+
+// EventsHandlerStatusLogger produces a log line after every event handled with
+// the status (success or failure), tracking id, duration, event name.
+// If it failed the error is added to the log line as well.
+// It also updates the logger in the context adding the tracking id present in
+// the context.
+//
+// To extract the event name it considers the event.Payload is a JSON with a top
+// level key 'event' and uses its value as the event name.
+// It is possible to pass a custom function to extract the event name,
+// check EventsLoggerWithNameFn.
+func EventsHandlerStatusLogger() events.Middleware {
+	return EventsHandlerStatusLoggerWithNameFn(eventName)
+}
+
+// EventsLoggerWithNameFn is the same as EventsHandlerStatusLogger, but using a custom
+// function to extract the event name.
+func EventsHandlerStatusLoggerWithNameFn(eventNameFn func(e events.Event) string) events.Middleware {
+	return func(next events.Handler) events.Handler {
+		return events.HandlerFunc(func(ctx context.Context, e events.Event) (err error) {
+			startTime := logger.Now()
+
+			if eventNameFn == nil {
+				eventNameFn = eventName
+			}
+			evName := eventNameFn(e)
+
+			l := logger.FromContext(ctx)
+			trackingID := tracking.IDFromContext(ctx)
+			logFields := map[string]interface{}{
+				internal.FieldTrackingID: trackingID,
+				internal.FieldRequestID:  trackingID,
+				internal.FieldEvent:      evName,
+			}
+			l.UpdateContext(func(c zerolog.Context) zerolog.Context {
+				return c.Fields(logFields)
+			})
+
+			defer func() {
+				status := "succeeded"
+
+				duration := logger.Now().Sub(startTime)
+
+				zlEvent := l.Info().
+					Dur(internal.FieldDuration, duration)
+
+				if err != nil {
+					status = "failed"
+					zlEvent.Err(err)
+				}
+				zlEvent.Msgf("%s %s", evName, status)
+			}()
+			return next.Handle(ctx, e)
+		})
+	}
+}
+
+func eventName(e events.Event) string {
+	type ePayload struct {
+		Name string `json:"event"`
+	}
+	payload := &ePayload{}
+
+	if err := json.Unmarshal(e.Payload, payload); err != nil {
+		return "name_error"
+	}
+
+	return payload.Name
+}

logger/middleware/events_test.go

@@ -2,9 +2,12 @@ package middleware
 
 import (
 	"context"
+	"encoding/json"
+	"errors"
 	"os"
 	"time"
 
+	"github.com/blacklane/go-libs/tracking"
 	"github.com/blacklane/go-libs/x/events"
 
 	"github.com/blacklane/go-libs/logger"
@@ -16,11 +19,11 @@ func ExampleEventsAddLogger() {
 		return time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC)
 	})
 
-	log := logger.New(os.Stdout, "")
+	log := logger.New(os.Stdout, "ExampleEventsAddLogger")
 
 	h := events.HandlerFunc(func(ctx context.Context, _ events.Event) error {
 		l := logger.FromContext(ctx)
-		l.Info().Msg("Hello, Gophers")
+		l.Info().Msg("Hello, Gophers from events")
 		return nil
 	})
 
@@ -30,5 +33,104 @@ func ExampleEventsAddLogger() {
 	_ = hh.Handle(context.Background(), events.Event{})
 
 	// Output:
-	// {"level":"info","application":"","timestamp":"2009-11-10T23:00:00Z","message":"Hello, Gophers"}
+	// {"level":"info","application":"ExampleEventsAddLogger","timestamp":"2009-11-10T23:00:00Z","message":"Hello, Gophers from events"}
+}
+
+func ExampleEventsHandlerStatusLogger_success() {
+	// Set current time function so we can control the logged timestamp and duration
+	timeNowCalled := false
+	logger.SetNowFunc(func() time.Time {
+		now := time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC)
+		if timeNowCalled {
+			now = now.Add(time.Second)
+		}
+		timeNowCalled = true
+		return now
+	})
+
+	ctx := tracking.SetContextID(context.Background(), "tracking_id-ExampleEventsLogger_Success")
+
+	log := logger.New(os.Stdout, "ExampleEventsLogger")
+
+	hb := events.HandlerBuilder{}
+	hb.UseMiddleware(EventsHandlerStatusLogger(), EventsAddLogger(log))
+	hb.AddHandler(
+		events.HandlerFunc(func(context.Context, events.Event) error { return nil }))
+
+	h := hb.Build()[0]
+
+	_ = 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"}
+}
+
+func ExampleEventsHandlerStatusLogger_failure() {
+	// Set current time function so we can control the logged timestamp and duration
+	timeNowCalled := false
+	logger.SetNowFunc(func() time.Time {
+		now := time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC)
+		if timeNowCalled {
+			now = now.Add(time.Second)
+		}
+		timeNowCalled = true
+		return now
+	})
+
+	ctx := tracking.SetContextID(context.Background(), "tracking_id-ExampleEventsLogger_Failure")
+
+	log := logger.New(os.Stdout, "ExampleEventsLogger")
+
+	hb := events.HandlerBuilder{}
+	hb.UseMiddleware(EventsHandlerStatusLogger(), EventsAddLogger(log))
+	hb.AddHandler(
+		events.HandlerFunc(func(context.Context, events.Event) error { return errors.New("bad") }))
+
+	h := hb.Build()[0]
+
+	_ = 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"}
+}
+
+func ExampleEventsHandlerStatusLoggerWithNameFn() {
+	// Set current time function so we can control the logged timestamp and duration
+	timeNowCalled := false
+	logger.SetNowFunc(func() time.Time {
+		now := time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC)
+		if timeNowCalled {
+			now = now.Add(time.Second)
+		}
+		timeNowCalled = true
+		return now
+	})
+
+	ctx := tracking.SetContextID(context.Background(), "tracking_id-ExampleEventsLogger_Success")
+
+	log := logger.New(os.Stdout, "ExampleEventsLogger")
+
+	hb := events.HandlerBuilder{}
+	nameFn := func(e events.Event) string {
+		type ePayload struct {
+			Name string `json:"name"`
+		}
+		payload := &ePayload{}
+
+		if err := json.Unmarshal(e.Payload, payload); err != nil {
+			return "name_error"
+		}
+
+		return payload.Name
+	}
+	hb.UseMiddleware(EventsHandlerStatusLoggerWithNameFn(nameFn), EventsAddLogger(log))
+	hb.AddHandler(
+		events.HandlerFunc(func(context.Context, events.Event) error { return nil }))
+
+	h := hb.Build()[0]
+
+	_ = 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"}
 }

logger/middleware/http.go

@@ -13,7 +13,8 @@ import (
 	"github.com/blacklane/go-libs/logger/internal"
 )
 
-func Logger(log logger.Logger) func(http.Handler) http.Handler {
+// HTTPAddLogger adds the logger into the request context.
+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) {
 			ctx := log.WithContext(r.Context())
@@ -22,7 +23,15 @@ func Logger(log logger.Logger) func(http.Handler) http.Handler {
 	}
 }
 
-func RequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
+// Logger adds the logger into the request context.
+// Deprecated, use HTTPAddLogger instead.
+func Logger(log logger.Logger) func(http.Handler) http.Handler {
+	return HTTPAddLogger(log)
+}
+
+// HTTPRequestLogger produces a log line with the request status and fields
+// following the standard defined on http://handbook.int.blacklane.io/monitoring/kiev.html#requestresponse-logging
+func HTTPRequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			startTime := logger.Now()
@@ -69,6 +78,12 @@ func RequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
 	}
 }
 
+// RequestLogger use HTTPRequestLogger instead.
+// Deprecated
+func RequestLogger(skipRoutes []string) func(http.Handler) http.Handler {
+	return HTTPRequestLogger(skipRoutes)
+}
+
 func ipAddress(r *http.Request) string {
 	forwardedIP := r.Header.Get(internal.HeaderForwardedFor)
 	if len(forwardedIP) == 0 {