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
cloudfoundry · Oct 16, 2024 · e04c7c1 · e04c7c1
1 parent 8f119d5
commit e04c7c1
Show file tree

Hide file tree

Showing 4 changed files with 108 additions and 3 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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)