From e04c7c1be286e3a72f5fb1202bfef973de530565 Mon Sep 17 00:00:00 2001 From: Plamen Bardarov Date: Wed, 16 Oct 2024 10:02:40 +0300 Subject: [PATCH] Log desired LRP validation errors (#103) * app logging when desired lrp request is invalid * add tests * error handling * delete go.mod and go.sum * test for update LRP * add test for invalid process guid in parseAppGuidFromProcessGuid remove magic numbers in parseAppGuidFromProcessGuid change logging message so its less ambiguous * change logging message so its less ambiguous --- cmd/bbs/main.go | 1 + handlers/desired_lrp_handlers.go | 44 +++++++++++++++++++ handlers/desired_lrp_handlers_test.go | 62 ++++++++++++++++++++++++++- handlers/handlers.go | 4 +- 4 files changed, 108 insertions(+), 3 deletions(-) diff --git a/cmd/bbs/main.go b/cmd/bbs/main.go index 99997bb7..cdc0741a 100644 --- a/cmd/bbs/main.go +++ b/cmd/bbs/main.go @@ -278,6 +278,7 @@ func main() { taskStatMetronNotifier, migrationsDone, exitChan, + metronClient, ) bbsElectionMetronNotifier := metrics.NewBBSElectionMetronNotifier(logger, metronClient) diff --git a/handlers/desired_lrp_handlers.go b/handlers/desired_lrp_handlers.go index 75104f83..4bd01a32 100644 --- a/handlers/desired_lrp_handlers.go +++ b/handlers/desired_lrp_handlers.go @@ -2,7 +2,10 @@ package handlers import ( "context" + "errors" + "fmt" "net/http" + "strings" "code.cloudfoundry.org/auctioneer" "code.cloudfoundry.org/bbs/db" @@ -12,12 +15,15 @@ import ( "code.cloudfoundry.org/bbs/models" "code.cloudfoundry.org/bbs/serviceclient" "code.cloudfoundry.org/bbs/trace" + loggingclient "code.cloudfoundry.org/diego-logging-client" "code.cloudfoundry.org/lager/v3" "code.cloudfoundry.org/rep" "code.cloudfoundry.org/routing-info/internalroutes" "code.cloudfoundry.org/workpool" ) +const BbsLogSource = "DIEGO-API" + type DesiredLRPHandler struct { desiredLRPDB db.DesiredLRPDB actualLRPDB db.ActualLRPDB @@ -29,6 +35,7 @@ type DesiredLRPHandler struct { serviceClient serviceclient.ServiceClient updateWorkersCount int exitChan chan<- struct{} + metronClient loggingclient.IngressClient } func NewDesiredLRPHandler( @@ -42,6 +49,7 @@ func NewDesiredLRPHandler( repClientFactory rep.ClientFactory, serviceClient serviceclient.ServiceClient, exitChan chan<- struct{}, + metronClient loggingclient.IngressClient, ) *DesiredLRPHandler { return &DesiredLRPHandler{ desiredLRPDB: desiredLRPDB, @@ -54,6 +62,7 @@ func NewDesiredLRPHandler( serviceClient: serviceClient, updateWorkersCount: updateWorkersCount, exitChan: exitChan, + metronClient: metronClient, } } @@ -200,7 +209,11 @@ func (h *DesiredLRPHandler) DesireDesiredLRP(logger lager.Logger, w http.Respons err := parseRequest(logger, req, request) if err != nil { + logger.Error("failed-parsing-request", err) response.Error = models.ConvertError(err) + if err = h.logDesiredLrpParsingErrors(response.Error, request.GetDesiredLrp().GetProcessGuid()); err != nil { + logger.Error("failed-sending-app-logs", err) + } return } @@ -236,6 +249,9 @@ func (h *DesiredLRPHandler) UpdateDesiredLRP(logger lager.Logger, w http.Respons if err != nil { logger.Error("failed-parsing-request", err) response.Error = models.ConvertError(err) + if err = h.logDesiredLrpParsingErrors(response.Error, request.GetProcessGuid()); err != nil { + logger.Error("failed-sending-app-logs", err) + } return } @@ -489,3 +505,31 @@ func (h *DesiredLRPHandler) updateInstances(ctx context.Context, logger lager.Lo } } } + +func (h *DesiredLRPHandler) logDesiredLrpParsingErrors(err *models.Error, processGuid string) error { + appGuid := parseAppGuidFromProcessGuid(processGuid) + if appGuid == "" { + return errors.New("app guid is empty") + } + + tags := map[string]string{ + "source_id": appGuid, + } + + return h.metronClient.SendAppErrorLog( + fmt.Sprintf("Error parsing request for app with guid %s, %s, %s", appGuid, err.GetType(), err.GetMessage()), + BbsLogSource, + tags) +} + +// Parses a ProcessGuid which is in the format: 'UUID-UUID' and returns the first part which is the AppGuid +func parseAppGuidFromProcessGuid(processGuid string) string { + const uuidParts = 5 // a valid UUID contains 5 parts separated by '-' + + parts := strings.Split(processGuid, "-") + if len(parts) < uuidParts { + return "" + } + + return strings.Join(parts[:uuidParts], "-") +} diff --git a/handlers/desired_lrp_handlers_test.go b/handlers/desired_lrp_handlers_test.go index 837101da..cae32410 100644 --- a/handlers/desired_lrp_handlers_test.go +++ b/handlers/desired_lrp_handlers_test.go @@ -20,6 +20,7 @@ import ( "code.cloudfoundry.org/bbs/models" "code.cloudfoundry.org/bbs/models/test/model_helpers" . "code.cloudfoundry.org/bbs/test_helpers" + mfakes "code.cloudfoundry.org/diego-logging-client/testhelpers" "code.cloudfoundry.org/lager/v3" "code.cloudfoundry.org/lager/v3/lagertest" "code.cloudfoundry.org/rep" @@ -34,6 +35,7 @@ var _ = Describe("DesiredLRP Handlers", func() { fakeDesiredLRPDB *dbfakes.FakeDesiredLRPDB fakeActualLRPDB *dbfakes.FakeActualLRPDB fakeAuctioneerClient *auctioneerfakes.FakeClient + fakeMetronClient *mfakes.FakeIngressClient desiredHub *eventfakes.FakeHub actualHub *eventfakes.FakeHub actualLRPInstanceHub *eventfakes.FakeHub @@ -54,6 +56,7 @@ var _ = Describe("DesiredLRP Handlers", func() { fakeDesiredLRPDB = new(dbfakes.FakeDesiredLRPDB) fakeActualLRPDB = new(dbfakes.FakeActualLRPDB) fakeAuctioneerClient = new(auctioneerfakes.FakeClient) + fakeMetronClient = &mfakes.FakeIngressClient{} logger = lagertest.NewTestLogger("test") logger.RegisterSink(lager.NewWriterSink(GinkgoWriter, lager.DEBUG)) responseRecorder = httptest.NewRecorder() @@ -75,6 +78,7 @@ var _ = Describe("DesiredLRP Handlers", func() { fakeRepClientFactory, fakeServiceClient, exitCh, + fakeMetronClient, ) }) @@ -969,6 +973,38 @@ var _ = Describe("DesiredLRP Handlers", func() { handler.DesireDesiredLRP(logger, responseRecorder, request) }) + Context("when the DesiredLRP request fails validation", func() { + appGuid := "05e27b0a-003c-4aa4-bd0c-8d0ad82b426c" + + Context("with routes field exceeding the maximum size", func() { + BeforeEach(func() { + desiredLRP.ProcessGuid = fmt.Sprintf("%s-%s", appGuid, "6e0c1e62-dcad-4cca-99fe-db6b46b920be") + longRoutesJson := json.RawMessage(strings.Repeat("a", (128*1024)+1)) + desiredLRP.Routes = &models.Routes{ + "test_route": &longRoutesJson, + } + }) + + Context("when ProcessGuid is not in the valid format", func() { + BeforeEach(func() { + desiredLRP.ProcessGuid = "invalid_process_guid" + }) + + It("logs the error", func() { + Expect(logger).To(gbytes.Say("failed-sending-app-logs")) + }) + }) + + It("sends application log with the correct message", func() { + Expect(fakeMetronClient.SendAppErrorLogCallCount()).To(Equal(1)) + msg, source, tags := fakeMetronClient.SendAppErrorLogArgsForCall(0) + Expect(source).To(Equal(handlers.BbsLogSource)) + Expect(msg).To(Equal(fmt.Sprintf("Error parsing request for app with guid %s, InvalidRequest, Invalid field: routes", appGuid))) + Expect(tags).To(HaveKeyWithValue("source_id", appGuid)) + }) + }) + }) + Context("when creating desired lrp in DB succeeds", func() { var createdActualLRPs []*models.ActualLRP @@ -1175,20 +1211,42 @@ var _ = Describe("DesiredLRP Handlers", func() { update = &models.DesiredLRPUpdate{} update.SetAnnotation(someText) + }) + JustBeforeEach(func() { requestBody = &models.UpdateDesiredLRPRequest{ ProcessGuid: processGuid, Update: update, } - }) - JustBeforeEach(func() { request := newTestRequest(requestBody) request.Header.Set(lager.RequestIdHeader, requestIdHeader) handler.UpdateDesiredLRP(logger, responseRecorder, request) time.Sleep(100 * time.Millisecond) }) + Context("when the DesiredLRP request fails validation", func() { + appGuid := "05e27b0a-003c-4aa4-bd0c-8d0ad82b426c" + + Context("with routes field exceeding the maximum size", func() { + BeforeEach(func() { + processGuid = fmt.Sprintf("%s-%s", appGuid, "6e0c1e62-dcad-4cca-99fe-db6b46b920be") + longRoutesJson := json.RawMessage(strings.Repeat("a", (128*1024)+1)) + update.Routes = &models.Routes{ + "test_route": &longRoutesJson, + } + }) + + It("sends application log with the correct message", func() { + Expect(fakeMetronClient.SendAppErrorLogCallCount()).To(Equal(1)) + msg, source, tags := fakeMetronClient.SendAppErrorLogArgsForCall(0) + Expect(source).To(Equal(handlers.BbsLogSource)) + Expect(msg).To(Equal(fmt.Sprintf("Error parsing request for app with guid %s, InvalidRequest, Invalid field: routes", appGuid))) + Expect(tags).To(HaveKeyWithValue("source_id", appGuid)) + }) + }) + }) + Context("when updating desired lrp in DB succeeds", func() { BeforeEach(func() { fakeDesiredLRPDB.UpdateDesiredLRPReturns(beforeDesiredLRP, nil) diff --git a/handlers/handlers.go b/handlers/handlers.go index 1d565788..b907a8ec 100644 --- a/handlers/handlers.go +++ b/handlers/handlers.go @@ -15,6 +15,7 @@ import ( "code.cloudfoundry.org/bbs/models" "code.cloudfoundry.org/bbs/serviceclient" "code.cloudfoundry.org/bbs/taskworkpool" + loggingclient "code.cloudfoundry.org/diego-logging-client" "code.cloudfoundry.org/lager/v3" "code.cloudfoundry.org/rep" "github.com/gogo/protobuf/proto" @@ -37,6 +38,7 @@ func New( taskStatMetronNotifier metrics.TaskStatMetronNotifier, migrationsDone <-chan struct{}, exitChan chan struct{}, + metronClient loggingclient.IngressClient, ) http.Handler { pingHandler := NewPingHandler() domainHandler := NewDomainHandler(db, exitChan) @@ -57,7 +59,7 @@ func New( ) actualLRPLifecycleHandler := NewActualLRPLifecycleHandler(actualLRPController, exitChan) evacuationHandler := NewEvacuationHandler(evacuationController, exitChan) - desiredLRPHandler := NewDesiredLRPHandler(updateWorkers, db, db, desiredHub, actualHub, actualLRPInstanceHub, auctioneerClient, repClientFactory, serviceClient, exitChan) + desiredLRPHandler := NewDesiredLRPHandler(updateWorkers, db, db, desiredHub, actualHub, actualLRPInstanceHub, auctioneerClient, repClientFactory, serviceClient, exitChan, metronClient) taskController := controllers.NewTaskController(db, taskCompletionClient, auctioneerClient, serviceClient, repClientFactory, taskHub, taskStatMetronNotifier, maxTaskPlacementRetries) taskHandler := NewTaskHandler(taskController, exitChan) lrpGroupEventsHandler := NewLRPGroupEventsHandler(desiredHub, actualHub)