Log trace ID when handling events

cloudfoundry · May 23, 2023 · b6a50dc · b6a50dc
1 parent a4bc575
commit b6a50dc
Show file tree

Hide file tree

Showing 4 changed files with 38 additions and 28 deletions.
diff --git a/routehandlers/handler.go b/routehandlers/handler.go
@@ -4,6 +4,7 @@ import (
 	"errors"
 
 	"code.cloudfoundry.org/bbs/models"
+	"code.cloudfoundry.org/bbs/trace"
 	loggingclient "code.cloudfoundry.org/diego-logging-client"
 	"code.cloudfoundry.org/lager/v3"
 	"code.cloudfoundry.org/route-emitter/emitter"
@@ -54,21 +55,26 @@ func (handler *Handler) HandleEvent(logger lager.Logger, event models.Event) {
 
 	switch event := event.(type) {
 	case *models.DesiredLRPCreatedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		handler.handleDesiredCreate(logger, event.DesiredLrp)
 	case *models.DesiredLRPChangedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		err := handler.handleDesiredUpdate(logger, event.Before, event.After)
 		if err != nil {
 			logger.Error("failed-to-handle-desired-update", err)
 		}
 	case *models.DesiredLRPRemovedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		handler.handleDesiredDelete(logger, event.DesiredLrp)
 	case *models.ActualLRPInstanceCreatedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		if event.ActualLrp == nil {
 			logger.Error("nil-actual-lrp", nil, lager.Data{"event-type": event.EventType()})
 			return
 		}
 		handler.handleActualCreate(logger, event.ActualLrp)
 	case *models.ActualLRPInstanceChangedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		before := event.Before.ToActualLRP(event.ActualLRPKey, event.ActualLRPInstanceKey)
 		after := event.After.ToActualLRP(event.ActualLRPKey, event.ActualLRPInstanceKey)
 		logger.Debug("received-actual-lrp-changed-event", lager.Data{"before": before, "after": after})
@@ -81,6 +87,7 @@ func (handler *Handler) HandleEvent(logger lager.Logger, event models.Event) {
 			logger.Error("failed-to-handle-actual-update", err)
 		}
 	case *models.ActualLRPInstanceRemovedEvent:
+		logger = trace.LoggerWithTraceInfo(logger, event.TraceId)
 		logger.Debug("received-actual-lrp-instance-removed-event", lager.Data{"lrp": event.ActualLrp})
 		if event.ActualLrp == nil {
 			logger.Error("nil-actual-lrp", nil, lager.Data{"event-type": event.EventType()})

diff --git a/routehandlers/handler_test.go b/routehandlers/handler_test.go
@@ -24,7 +24,10 @@ import (
 	"github.com/onsi/gomega/gbytes"
 )
 
-const logGuid = "some-log-guid"
+const (
+	logGuid = "some-log-guid"
+	traceId = "7f461654-74d1-1ee5-8367-77d85df2cdab"
+)
 
 type randomEvent struct {
 	proto.Message
@@ -154,7 +157,7 @@ var _ = Describe("Handler", func() {
 			})
 
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPCreatedEvent(desiredLRP))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPCreatedEvent(desiredLRP, traceId))
 			})
 
 			It("should set the routes on the table", func() {
@@ -247,7 +250,7 @@ var _ = Describe("Handler", func() {
 			})
 
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPChangedEvent(originalDesiredLRP, changedDesiredLRP))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPChangedEvent(originalDesiredLRP, changedDesiredLRP, traceId))
 			})
 
 			It("should set the routes on the table", func() {
@@ -346,7 +349,7 @@ var _ = Describe("Handler", func() {
 			})
 
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPRemovedEvent(desiredLRP))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPRemovedEvent(desiredLRP, "some-trace-id"))
 			})
 
 			It("should remove the routes from the table", func() {
@@ -392,11 +395,11 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP, traceId))
 				})
 
 				It("logs an error", func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP, traceId))
 					Expect(logger).To(gbytes.Say("nil-actual-lrp"))
 				})
 			})
@@ -420,7 +423,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP, "some-trace-id"))
 				})
 
 				It("should add/update the endpoints on the table", func() {
@@ -519,7 +522,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 				})
 
 				It("should add/update the endpoint on the table", func() {
@@ -556,7 +559,7 @@ var _ = Describe("Handler", func() {
 							beforeActualLRP = nil
 						})
 						It("logs an error", func() {
-							routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+							routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 							Expect(logger).To(gbytes.Say("nil-actual-lrp"))
 						})
 					})
@@ -566,7 +569,7 @@ var _ = Describe("Handler", func() {
 							afterActualLRP = nil
 						})
 						It("logs an error", func() {
-							routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+							routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 							Expect(logger).To(gbytes.Say("nil-actual-lrp"))
 						})
 					})
@@ -613,7 +616,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 				})
 
 				It("should remove the endpoint from the table", func() {
@@ -685,7 +688,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 				})
 
 				Context("when the resulting LRP presence does not change", func() {
@@ -781,7 +784,7 @@ var _ = Describe("Handler", func() {
 						),
 						State: models.ActualLRPStateClaimed,
 					}
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(beforeActualLRP, afterActualLRP, "some-trace-id"))
 				})
 
 				It("should NOT log the net info", func() {
@@ -833,7 +836,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				JustBeforeEach(func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP, "some-trace-id"))
 				})
 
 				It("should remove the endpoint from the table", func() {
@@ -865,7 +868,7 @@ var _ = Describe("Handler", func() {
 						State: models.ActualLRPStateCrashed,
 					}
 
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP, "some-trace-id"))
 				})
 
 				It("should NOT log the net info", func() {
@@ -896,7 +899,7 @@ var _ = Describe("Handler", func() {
 				})
 
 				It("logs an error", func() {
-					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP))
+					routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP, "some-trace-id"))
 					Expect(logger).To(gbytes.Say("nil-actual-lrp"))
 				})
 			})
@@ -1163,7 +1166,7 @@ var _ = Describe("Handler", func() {
 						ProcessGuid: "pg-4",
 						Routes:      &routes,
 						Instances:   1,
-					})
+					}, "some-trace-id")
 
 					endpoint4 = routingtable.Endpoint{
 						InstanceGUID:    "ig-4",
@@ -1180,7 +1183,7 @@ var _ = Describe("Handler", func() {
 						ActualLRPInstanceKey: models.NewActualLRPInstanceKey(endpoint4.InstanceGUID, "cell-id"),
 						ActualLRPNetInfo:     models.NewActualLRPNetInfo(endpoint4.Host, "container-ip-4", models.ActualLRPNetInfo_PreferredAddressHost, models.NewPortMapping(endpoint4.Port, endpoint4.ContainerPort)),
 						State:                models.ActualLRPStateRunning,
-					})
+					}, "some-trace-id")
 
 					cachedEvents := map[string]models.Event{
 						desiredLRPEvent.Key(): desiredLRPEvent,

diff --git a/routehandlers/routing_api_handler_test.go b/routehandlers/routing_api_handler_test.go
@@ -67,7 +67,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 
 		Describe("HandleDesiredCreate", func() {
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPCreatedEvent(desiredLRP))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPCreatedEvent(desiredLRP, "some-trace-id"))
 			})
 
 			It("invokes AddRoutes on RoutingTable", func() {
@@ -111,7 +111,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 			})
 
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPChangedEvent(desiredLRP, after))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPChangedEvent(desiredLRP, after, "some-trace-id"))
 			})
 
 			It("invokes UpdateRoutes on RoutingTable", func() {
@@ -142,7 +142,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 				fakeRoutingTable.RemoveRoutesReturns(unregistrationEvent, emptyNatsMessages)
 			})
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewDesiredLRPRemovedEvent(desiredLRP))
+				routeHandler.HandleEvent(logger, models.NewDesiredLRPRemovedEvent(desiredLRP, "some-trace-id"))
 			})
 
 			It("does not invoke AddRoutes on RoutingTable", func() {
@@ -168,7 +168,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 
 		Describe("HandleActualCreate", func() {
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP))
+				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceCreatedEvent(actualLRP, "some-trace-id"))
 			})
 
 			Context("when state is Running", func() {
@@ -236,7 +236,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 			)
 
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(actualLRP, afterLRP))
+				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceChangedEvent(actualLRP, afterLRP, "some-trace-id"))
 			})
 
 			Context("when after state is Running", func() {
@@ -366,7 +366,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 
 		Describe("HandleActualDelete", func() {
 			JustBeforeEach(func() {
-				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP))
+				routeHandler.HandleEvent(logger, models.NewActualLRPInstanceRemovedEvent(actualLRP, "some-trace-id"))
 			})
 
 			Context("when state is Running", func() {
@@ -615,7 +615,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 						ProcessGuid: "process-guid-2",
 						Routes:      tcpRoutes.RoutingInfo(),
 						Instances:   1,
-					})
+					}, "some-trace-id")
 
 					actualLRPEvent := models.NewActualLRPInstanceCreatedEvent(&models.ActualLRP{
 						ActualLRPKey:         models.NewActualLRPKey("process-guid-2", 0, "domain"),
@@ -628,7 +628,7 @@ var _ = Describe("RoutingAPIHandler", func() {
 						),
 						State:           models.ActualLRPStateRunning,
 						ModificationTag: modificationTag,
-					})
+					}, "some-trace-id")
 
 					cachedEvents := map[string]models.Event{
 						desiredLRPEvent.Key(): desiredLRPEvent,

diff --git a/watcher/watcher_test.go b/watcher/watcher_test.go
@@ -841,7 +841,7 @@ var _ = Describe("Watcher", func() {
 					Context("when an invalid actual lrp created event is received", func() {
 						BeforeEach(func() {
 							sendEvent = func() {
-								Eventually(eventCh).Should(BeSent(EventHolder{models.NewActualLRPInstanceCreatedEvent(nil, "")}))
+								Eventually(eventCh).Should(BeSent(EventHolder{models.NewActualLRPInstanceCreatedEvent(nil, "some-trace-id")}))
 							}
 						})
 
@@ -853,7 +853,7 @@ var _ = Describe("Watcher", func() {
 					Context("when an invalid actual lrp change event is received", func() {
 						BeforeEach(func() {
 							sendEvent = func() {
-								Eventually(eventCh).Should(BeSent(EventHolder{models.NewActualLRPInstanceChangedEvent(nil, nil, "")}))
+								Eventually(eventCh).Should(BeSent(EventHolder{models.NewActualLRPInstanceChangedEvent(nil, nil, "some-trace-id")}))
 							}
 						})