From d7937b22d811ad0973f0d32775d226576b8b03bc Mon Sep 17 00:00:00 2001 From: Marcela Campo Date: Wed, 27 Mar 2024 15:11:30 +0000 Subject: [PATCH] feat: log the error message when an async operation fails When doing a provision/update/delete/../etc operation, if it fails for any reason, we update last operation status and message. However we only return an error from the last_operation endpoing under the certain circumpstances (see [OSBAPI spec](https://github.com/openservicebrokerapi/servicebroker/blob/master/spec.md#polling-last-operation-for-service-instances). All other circumpstances the return code is OK and we only log the operation status (failed), but not the message (brokerapi does this for us). With that into consideration, we need to log any error messages that ocurr in our application to improve troubleshooting. This change logs the error message that will be saved into the last operation message whenever last operation is updated with a failed state. [#187292596](https://www.pivotaltracker.com/story/show/187292596) --- cmd/tf.go | 2 +- pkg/providers/tf/definition.go | 2 +- pkg/providers/tf/deployment_manager.go | 15 ++++++++--- pkg/providers/tf/deployment_manager_test.go | 28 +++++++++++++++------ 4 files changed, 34 insertions(+), 13 deletions(-) diff --git a/cmd/tf.go b/cmd/tf.go index d7ea15722..a8ba80426 100644 --- a/cmd/tf.go +++ b/cmd/tf.go @@ -53,7 +53,7 @@ func init() { invoker.NewTerraformInvokerFactory(executor.NewExecutorFactory("", nil, nil), "", map[string]string{}), logger, tf.TfServiceDefinitionV1{}, - tf.NewDeploymentManager(store), + tf.NewDeploymentManager(store, logger), ) return nil }, diff --git a/pkg/providers/tf/definition.go b/pkg/providers/tf/definition.go index 3b63566bb..9c479690a 100644 --- a/pkg/providers/tf/definition.go +++ b/pkg/providers/tf/definition.go @@ -293,7 +293,7 @@ func (tfb *TfServiceDefinitionV1) ToService(tfBinContext executor.TFBinariesCont Examples: tfb.Examples, ProviderBuilder: func(logger lager.Logger, store broker.ServiceProviderStorage) broker.ServiceProvider { executorFactory := executor.NewExecutorFactory(tfBinContext.Dir, tfBinContext.Params, envVars) - return NewTerraformProvider(tfBinContext, invoker.NewTerraformInvokerFactory(executorFactory, tfBinContext.Dir, tfBinContext.ProviderReplacements), logger, constDefn, NewDeploymentManager(store)) + return NewTerraformProvider(tfBinContext, invoker.NewTerraformInvokerFactory(executorFactory, tfBinContext.Dir, tfBinContext.ProviderReplacements), logger, constDefn, NewDeploymentManager(store, logger)) }, }, nil } diff --git a/pkg/providers/tf/deployment_manager.go b/pkg/providers/tf/deployment_manager.go index 48cbf6043..5ce41c137 100644 --- a/pkg/providers/tf/deployment_manager.go +++ b/pkg/providers/tf/deployment_manager.go @@ -4,6 +4,8 @@ import ( "errors" "fmt" + "code.cloudfoundry.org/lager/v3" + "github.com/cloudfoundry/cloud-service-broker/internal/storage" "github.com/cloudfoundry/cloud-service-broker/pkg/broker" "github.com/cloudfoundry/cloud-service-broker/pkg/featureflags" @@ -11,12 +13,14 @@ import ( ) type DeploymentManager struct { - store broker.ServiceProviderStorage + store broker.ServiceProviderStorage + logger lager.Logger } -func NewDeploymentManager(store broker.ServiceProviderStorage) *DeploymentManager { +func NewDeploymentManager(store broker.ServiceProviderStorage, logger lager.Logger) *DeploymentManager { return &DeploymentManager{ - store: store, + store: store, + logger: logger, } } @@ -64,6 +68,11 @@ func (d *DeploymentManager) MarkOperationFinished(deployment *storage.TerraformD } else { deployment.LastOperationState = Failed deployment.LastOperationMessage = fmt.Sprintf("%s %s: %s", deployment.LastOperationType, Failed, err) + d.logger.Error("operation-failed", err, lager.Data{ + "deploymentID": deployment.ID, + "message": deployment.LastOperationMessage, + }) + } return d.store.StoreTerraformDeployment(*deployment) diff --git a/pkg/providers/tf/deployment_manager_test.go b/pkg/providers/tf/deployment_manager_test.go index 623142c31..637a6ac14 100644 --- a/pkg/providers/tf/deployment_manager_test.go +++ b/pkg/providers/tf/deployment_manager_test.go @@ -3,6 +3,8 @@ package tf_test import ( "errors" + "code.cloudfoundry.org/lager/v3/lagertest" + "github.com/cloudfoundry/cloud-service-broker/internal/storage" "github.com/cloudfoundry/cloud-service-broker/pkg/broker" "github.com/cloudfoundry/cloud-service-broker/pkg/broker/brokerfakes" @@ -26,7 +28,7 @@ var _ = Describe("DeploymentManager", func() { BeforeEach(func() { fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + deploymentManager = tf.NewDeploymentManager(&fakeStore, lagertest.NewTestLogger("test")) ws = &workspace.TerraformWorkspace{ Modules: []workspace.ModuleDefinition{{ Name: "fake module name", @@ -116,7 +118,7 @@ var _ = Describe("DeploymentManager", func() { BeforeEach(func() { fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + deploymentManager = tf.NewDeploymentManager(&fakeStore, lagertest.NewTestLogger("test")) existingDeployment = storage.TerraformDeployment{ ID: "tf:instance:binding", Workspace: &workspace.TerraformWorkspace{ @@ -155,6 +157,7 @@ var _ = Describe("DeploymentManager", func() { var ( fakeStore brokerfakes.FakeServiceProviderStorage deploymentManager *tf.DeploymentManager + fakeLogger *lagertest.TestLogger existingDeployment storage.TerraformDeployment fakeWorkspace *workspacefakes.FakeWorkspace ) @@ -171,7 +174,8 @@ var _ = Describe("DeploymentManager", func() { LastOperationMessage: "test", } fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + fakeLogger = lagertest.NewTestLogger("broker") + deploymentManager = tf.NewDeploymentManager(&fakeStore, fakeLogger) }) When("operation finished successfully", func() { @@ -187,6 +191,7 @@ var _ = Describe("DeploymentManager", func() { Expect(storedDeployment.LastOperationType).To(Equal(existingDeployment.LastOperationType)) Expect(storedDeployment.LastOperationState).To(Equal("succeeded")) Expect(storedDeployment.LastOperationMessage).To(Equal("provision succeeded")) + Expect(fakeLogger.Errors).To(BeEmpty()) }) It("sets the last operation message from the TF output status", func() { @@ -200,11 +205,12 @@ var _ = Describe("DeploymentManager", func() { storedDeployment := fakeStore.StoreTerraformDeploymentArgsForCall(0) Expect(storedDeployment.LastOperationState).To(Equal("succeeded")) Expect(storedDeployment.LastOperationMessage).To(Equal("provision succeeded: apply completed successfully")) + Expect(fakeLogger.Logs()).To(BeEmpty()) }) }) When("operation finished with an error", func() { - It("sets operation state to failed and stores the error", func() { + It("sets operation state to failed, logs and stores the error", func() { err := deploymentManager.MarkOperationFinished(&existingDeployment, errors.New("operation failed dramatically")) Expect(err).NotTo(HaveOccurred()) @@ -216,6 +222,12 @@ var _ = Describe("DeploymentManager", func() { Expect(storedDeployment.LastOperationType).To(Equal(existingDeployment.LastOperationType)) Expect(storedDeployment.LastOperationState).To(Equal("failed")) Expect(storedDeployment.LastOperationMessage).To(Equal("provision failed: operation failed dramatically")) + Expect(fakeLogger.Logs()).To(HaveLen(1)) + Expect(fakeLogger.Logs()[0].Message).To(ContainSubstring("operation-failed")) + Expect(fakeLogger.Logs()[0].Data).To(HaveKeyWithValue("error", Equal("operation failed dramatically"))) + Expect(fakeLogger.Logs()[0].Data).To(HaveKeyWithValue("message", Equal("provision failed: operation failed dramatically"))) + Expect(fakeLogger.Logs()[0].Data).To(HaveKeyWithValue("deploymentID", Equal(existingDeployment.ID))) + }) }) }) @@ -231,7 +243,7 @@ var _ = Describe("DeploymentManager", func() { BeforeEach(func() { fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + deploymentManager = tf.NewDeploymentManager(&fakeStore, lagertest.NewTestLogger("test")) }) When("last operation has succeeded", func() { @@ -333,7 +345,7 @@ var _ = Describe("DeploymentManager", func() { By("setting up fakes", func() { viper.Reset() store = &brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(store) + deploymentManager = tf.NewDeploymentManager(store, lagertest.NewTestLogger("test")) templateVars = map[string]any{} }) @@ -566,7 +578,7 @@ var _ = Describe("DeploymentManager", func() { BeforeEach(func() { fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + deploymentManager = tf.NewDeploymentManager(&fakeStore, lagertest.NewTestLogger("test")) existingDeployment = storage.TerraformDeployment{ ID: existingDeploymentID, LastOperationType: "validation", @@ -601,7 +613,7 @@ var _ = Describe("DeploymentManager", func() { BeforeEach(func() { fakeStore = brokerfakes.FakeServiceProviderStorage{} - deploymentManager = tf.NewDeploymentManager(&fakeStore) + deploymentManager = tf.NewDeploymentManager(&fakeStore, lagertest.NewTestLogger("test")) }) It("gets all binding deployments for a service instance", func() {