From 880cd4d600d3662727dc93d401000c5100e92415 Mon Sep 17 00:00:00 2001
From: Marcelo Xavier <64842024+marcelo-xavier-bl@users.noreply.github.com>
Date: Mon, 1 Feb 2021 17:44:49 +0100
Subject: [PATCH] logger: fix events middlewate to always update the logger in
 the context  (#31)

The events middleware was not calling the handler with the updated logger in the context. This commit fixes it.
---
 .gitignore                       |  1 +
 logger/middleware/events.go      |  8 +++----
 logger/middleware/events_test.go | 36 ++++++++++++++++++++++++++++++++
 3 files changed, 41 insertions(+), 4 deletions(-)

diff --git a/.gitignore b/.gitignore
index 4c49bd7..a9ad188 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1 +1,2 @@
 .env
+.idea/
diff --git a/logger/middleware/events.go b/logger/middleware/events.go
index f8fcd84..f4e8e62 100644
--- a/logger/middleware/events.go
+++ b/logger/middleware/events.go
@@ -52,10 +52,6 @@ func EventsHandlerStatusLoggerWithNameFn(
 			}
 			evName := eventNameFn(e)
 
-			if !logEvent(evName, eventNames...) {
-				return next.Handle(ctx, e)
-			}
-
 			log := *logger.FromContext(ctx)
 			trackingID := tracking.IDFromContext(ctx)
 			logFields := map[string]interface{}{
@@ -67,6 +63,10 @@ func EventsHandlerStatusLoggerWithNameFn(
 			log = log.With().Fields(logFields).Logger()
 			ctx = log.WithContext(ctx)
 
+			if !logEvent(evName, eventNames...) {
+				return next.Handle(ctx, e)
+			}
+
 			defer func() {
 				zlEvent := log.Info()
 				status := "succeeded"
diff --git a/logger/middleware/events_test.go b/logger/middleware/events_test.go
index a166319..bc6cd18 100644
--- a/logger/middleware/events_test.go
+++ b/logger/middleware/events_test.go
@@ -164,3 +164,39 @@ func ExampleEventsHandlerStatusLoggerWithNameFn() {
 	// Output:
 	// {"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:01.000Z","message":"event_name_here succeeded"}
 }
+
+func ExampleEventsHandlerStatusLogger_loggerFieldsSetForAllEvents() {
+	// 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("log_event"), EventsAddLogger(log))
+	hb.AddHandler(
+		events.HandlerFunc(func(ctx context.Context, e events.Event) error {
+			log := logger.FromContext(ctx)
+			log.Info().Msgf("Log from handler")
+			return nil
+		}))
+
+	h := hb.Build()[0]
+
+	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"log_event"}`)})
+	_ = h.Handle(ctx, events.Event{Payload: []byte(`{"event":"do_not_log_event"}`)})
+
+	// Output:
+	// {"level":"info","application":"ExampleEventsLogger","event":"log_event","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","timestamp":"2009-11-10T23:00:01Z","message":"Log from handler"}
+	// {"level":"info","application":"ExampleEventsLogger","event":"log_event","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","duration_ms":1000,"timestamp":"2009-11-10T23:00:01Z","message":"log_event succeeded"}
+	// {"level":"info","application":"ExampleEventsLogger","event":"do_not_log_event","request_id":"tracking_id-ExampleEventsLogger_Success","tracking_id":"tracking_id-ExampleEventsLogger_Success","timestamp":"2009-11-10T23:00:01Z","message":"Log from handler"}
+}