refactor: standardize logging behavior for write operations

.ci/mockery_header.txt

@@ -0,0 +1,7 @@
+/*
+ * SPDX-FileCopyrightText: 2023 Siemens AG
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ *
+ * Author: Michael Adler <[email protected]>
+ */

.github/workflows/ci.yml

@@ -213,5 +213,8 @@ jobs:
       - run: apk add --no-cache py3-yaml git just bash go
       - name: Disable git security features
         run: git config --global safe.directory '*'
+      - uses: brokeyourbike/go-mockery-action@v0
+        with:
+          mockery-version: "2.36.0"
       - run: just generate
       - run: git diff --exit-code

.mockery.yaml

@@ -0,0 +1,19 @@
+with-expecter: True
+inpackage: True
+dir: "{{.InterfaceDir}}"
+mockname: "Mock{{.InterfaceName}}"
+outpkg: "{{.PackageName}}"
+filename: "mock_{{.InterfaceName}}.go"
+all: True
+
+boilerplate-file: .ci/mockery_header.txt
+# tags are currently broken, see vektra/mockery issue #691
+tags: testing
+
+packages:
+  github.com/siemens/wfx/persistence:
+    config:
+      tags: testing
+      recursive: True
+    interfaces:
+      Storage:

api/northbound.go

@@ -189,7 +189,9 @@ func NewNorthboundAPI(storage persistence.Storage) *operations.WorkflowExecutorA
 					err2.Message = err.Error()
 					return northbound.NewPostWorkflowsBadRequest().WithPayload(&model.ErrorResponse{Errors: []*model.Error{&err2}})
 				case ftag.AlreadyExists:
-					return northbound.NewPostWorkflowsBadRequest().WithPayload(&model.ErrorResponse{Errors: []*model.Error{&WorkflowNotUnique}})
+					err2 := WorkflowNotUnique
+					err2.Message = fmt.Sprintf("Workflow with name '%s' already exists", params.Workflow.Name)
+					return northbound.NewPostWorkflowsBadRequest().WithPayload(&model.ErrorResponse{Errors: []*model.Error{&err2}})
 				default:
 					return northbound.NewPostWorkflowsDefault(http.StatusInternalServerError)
 				}

codecov.yml

@@ -3,9 +3,14 @@
 # SPDX-License-Identifier: Apache-2.0
 #
 # Author: Michael Adler <[email protected]>
-
+#
 # This file can be validated as follows:
 # curl -X POST --data-binary @codecov.yml https://codecov.io/validate
+
+ignore:
+  # exclude mocks generated by mockery
+  - "**/mock_*.go"
+
 coverage:
   status:
     patch:

go.mod

@@ -98,6 +98,7 @@ require (
 	github.com/muesli/mango-pflag v0.1.0 // indirect
 	github.com/rogpeppe/go-internal v1.10.0 // indirect
 	github.com/rs/dnscache v0.0.0-20211102005908-e0241e321417 // indirect
+	github.com/stretchr/objx v0.5.0 // indirect
 	github.com/tsenart/go-tsz v0.0.0-20180814235614-0bd30b3df1c3 // indirect
 	github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e // indirect
 	go.mongodb.org/mongo-driver v1.11.6 // indirect

internal/handler/job/definition/update.go

@@ -23,11 +23,10 @@ import (
 func Update(ctx context.Context, storage persistence.Storage, jobID string, definition map[string]any) (map[string]any, error) {
 	log := logging.LoggerFromCtx(ctx)
 	contextLogger := log.With().Str("id", jobID).Logger()
-	contextLogger.Debug().Msg("Updating job definition")
 
 	job, err := storage.GetJob(ctx, jobID, persistence.FetchParams{History: false})
 	if err != nil {
-		contextLogger.Error().Err(err).Msg("Failed to fetch job from database")
+		contextLogger.Err(err).Msg("Failed to get job from storage")
 		return nil, fault.Wrap(err)
 	}
 
@@ -36,7 +35,7 @@ func Update(ctx context.Context, storage persistence.Storage, jobID string, defi
 
 	result, err := storage.UpdateJob(ctx, job, persistence.JobUpdate{Status: job.Status, Definition: &job.Definition})
 	if err != nil {
-		contextLogger.Error().Err(err).Msg("Failed to update job")
+		contextLogger.Err(err).Msg("Failed to update job")
 		return nil, fault.Wrap(err)
 	}
 

internal/handler/job/delete.go

@@ -18,6 +18,10 @@ import (
 
 func DeleteJob(ctx context.Context, storage persistence.Storage, jobID string) error {
 	log := logging.LoggerFromCtx(ctx)
-	log.Info().Str("id", jobID).Msg("Deleting job")
-	return fault.Wrap(storage.DeleteJob(ctx, jobID))
+	if err := storage.DeleteJob(ctx, jobID); err != nil {
+		log.Err(err).Str("id", jobID).Msg("Failed to delete job")
+		return fault.Wrap(err)
+	}
+	log.Info().Str("id", jobID).Msg("Deleted job")
+	return nil
 }

internal/handler/job/status/update.go

@@ -21,19 +21,14 @@ import (
 )
 
 func Update(ctx context.Context, storage persistence.Storage, jobID string, newStatus *model.JobStatus, actor model.EligibleEnum) (*model.JobStatus, error) {
-	log := logging.LoggerFromCtx(ctx)
-	contextLogger := log.With().
-		Str("id", jobID).
-		Str("actor", string(actor)).
-		Logger()
+	contextLogger := logging.LoggerFromCtx(ctx).With().Str("id", jobID).Str("actor", string(actor)).Logger()
 
 	job, err := storage.GetJob(ctx, jobID, persistence.FetchParams{History: false})
 	if err != nil {
 		return nil, fault.Wrap(err)
 	}
 
 	from := job.Status.State
-	contextLogger.Debug().Str("from", from).Msg("Updating job")
 
 	// update status
 	to := newStatus.State
@@ -57,38 +52,32 @@ func Update(ctx context.Context, storage persistence.Storage, jobID string, newS
 	}
 	if !isAllowed {
 		if !foundTransition {
-			contextLogger.Info().Msg("Transition does not exist")
+			contextLogger.Warn().Msg("Transition does not exist")
 			return nil, fault.Wrap(fmt.Errorf("transition from '%s' to '%s' does not exist", from, to), ftag.With(ftag.InvalidArgument))
 		}
-		contextLogger.Info().Msg("Transition exists but actor is not allowed to trigger it")
+		contextLogger.Warn().Msg("Transition exists but actor is not allowed to trigger it")
 		return nil, fault.Wrap(fmt.Errorf("transition from '%s' to '%s' is not allowed for actor '%s'", from, to, actor), ftag.With(ftag.InvalidArgument))
 	}
 
 	// transition is allowed, now apply wfx transitions
 	newTo := workflow.FollowImmediateTransitions(job.Workflow, to)
 	if newTo != to {
-		log.Debug().Str("to", to).Str("newTo", newTo).Msg("Resetting state since we moved the transition forward")
+		contextLogger.Debug().Str("to", to).Str("newTo", newTo).Msg("Resetting state since we moved the transition forward")
 		newStatus = &model.JobStatus{}
 	}
 	newStatus.State = newTo
 	// override any definitionHash provided by client
 	newStatus.DefinitionHash = job.Status.DefinitionHash
 
-	log.Debug().
-		Str("message", job.Status.Message).
-		Str("state", job.Status.State).
-		Msg("Updating job")
-
 	result, err := storage.UpdateJob(ctx, job, persistence.JobUpdate{Status: newStatus})
 	if err != nil {
-		log.Error().Err(err).Msg("Failed to persist job update")
+		contextLogger.Err(err).Msg("Failed to persist job update")
 		return nil, fault.Wrap(err)
 	}
 
-	if from != to {
-		contextLogger.Info().Msg("Updated job status")
-	} else {
-		contextLogger.Debug().Msg("Updated job status")
-	}
+	contextLogger.Info().
+		Str("from", from).
+		Str("to", newStatus.State).
+		Msg("Updated job status")
 	return result.Status, nil
 }

internal/handler/job/tags/add.go

@@ -18,19 +18,20 @@ import (
 
 func Add(ctx context.Context, storage persistence.Storage, jobID string, tags []string) ([]string, error) {
 	log := logging.LoggerFromCtx(ctx)
-	contextLogger := log.With().Str("id", jobID).Logger()
-	contextLogger.Debug().Strs("tags", tags).Msg("Adding tags")
+	contextLogger := log.With().Str("id", jobID).Strs("tags", tags).Logger()
 
 	job, err := storage.GetJob(ctx, jobID, persistence.FetchParams{History: false})
 	if err != nil {
+		contextLogger.Err(err).Msg("Failed to get job from storage")
 		return nil, fault.Wrap(err)
 	}
 
 	updatedJob, err := storage.UpdateJob(ctx, job, persistence.JobUpdate{AddTags: &tags})
 	if err != nil {
+		contextLogger.Err(err).Msg("Failed to add tags to job")
 		return nil, fault.Wrap(err)
 	}
 
-	contextLogger.Info().Msg("Updated job tags")
+	contextLogger.Info().Msg("Added job tags")
 	return updatedJob.Tags, nil
 }

internal/handler/job/tags/add_test.go

@@ -10,6 +10,7 @@ package tags
 
 import (
 	"context"
+	"errors"
 	"testing"
 
 	"github.com/siemens/wfx/generated/model"
@@ -38,6 +39,33 @@ func TestAdd(t *testing.T) {
 	assert.Equal(t, []string{"bar", "foo"}, actual)
 }
 
+func TestAdd_FaultyStorageGet(t *testing.T) {
+	db := persistence.NewMockStorage(t)
+	ctx := context.Background()
+	expectedErr := errors.New("mock error")
+	db.On("GetJob", ctx, "1", persistence.FetchParams{History: false}).Return(nil, expectedErr)
+
+	tags, err := Add(ctx, db, "1", []string{"foo", "bar"})
+	assert.Nil(t, tags)
+	assert.NotNil(t, err)
+}
+
+func TestAdd_FaultyStorageUpdate(t *testing.T) {
+	db := persistence.NewMockStorage(t)
+	ctx := context.Background()
+
+	expectedErr := errors.New("mock error")
+	dummyJob := model.Job{ID: "1"}
+	tags := []string{"foo", "bar"}
+
+	db.On("GetJob", ctx, "1", persistence.FetchParams{History: false}).Return(&dummyJob, nil)
+	db.On("UpdateJob", ctx, &dummyJob, persistence.JobUpdate{AddTags: &tags}).Return(nil, expectedErr)
+
+	tags, err := Add(ctx, db, "1", tags)
+	assert.Nil(t, tags)
+	assert.NotNil(t, err)
+}
+
 func newInMemoryDB(t *testing.T) persistence.Storage {
 	db := &entgo.SQLite{}
 	err := db.Initialize(context.Background(), "file:wfx?mode=memory&cache=shared&_fk=1")

internal/handler/job/tags/delete.go

@@ -18,18 +18,19 @@ import (
 
 func Delete(ctx context.Context, storage persistence.Storage, jobID string, tags []string) ([]string, error) {
 	log := logging.LoggerFromCtx(ctx)
-	contextLogger := log.With().Str("id", jobID).Logger()
-	contextLogger.Debug().Strs("tags", tags).Msg("Deleting tags")
+	contextLogger := log.With().Str("id", jobID).Strs("tags", tags).Logger()
 
 	job, err := storage.GetJob(ctx, jobID, persistence.FetchParams{History: false})
 	if err != nil {
+		contextLogger.Err(err).Msg("Failed to get job from storage")
 		return nil, fault.Wrap(err)
 	}
 
 	updatedJob, err := storage.UpdateJob(ctx, job, persistence.JobUpdate{DelTags: &tags})
 	if err != nil {
+		contextLogger.Err(err).Msg("Failed to delete tags to job")
 		return nil, fault.Wrap(err)
 	}
-	contextLogger.Debug().Msg("Deleted tags")
+	contextLogger.Info().Msg("Deleted job tags")
 	return updatedJob.Tags, nil
 }

internal/handler/job/tags/delete_test.go

@@ -10,9 +10,11 @@ package tags
 
 import (
 	"context"
+	"errors"
 	"testing"
 
 	"github.com/siemens/wfx/generated/model"
+	"github.com/siemens/wfx/persistence"
 	"github.com/siemens/wfx/workflow/dau"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -35,3 +37,30 @@ func TestDelete(t *testing.T) {
 	require.NoError(t, err)
 	assert.Equal(t, []string{"bar"}, tags)
 }
+
+func TestDelete_FaultyStorageGet(t *testing.T) {
+	db := persistence.NewMockStorage(t)
+	ctx := context.Background()
+	expectedErr := errors.New("mock error")
+	db.On("GetJob", ctx, "1", persistence.FetchParams{History: false}).Return(nil, expectedErr)
+
+	tags, err := Delete(ctx, db, "1", []string{"foo", "bar"})
+	assert.Nil(t, tags)
+	assert.NotNil(t, err)
+}
+
+func TestDelete_FaultyStorageUpdate(t *testing.T) {
+	db := persistence.NewMockStorage(t)
+	ctx := context.Background()
+
+	expectedErr := errors.New("mock error")
+	dummyJob := model.Job{ID: "1"}
+	tags := []string{"foo", "bar"}
+
+	db.On("GetJob", ctx, "1", persistence.FetchParams{History: false}).Return(&dummyJob, nil)
+	db.On("UpdateJob", ctx, &dummyJob, persistence.JobUpdate{DelTags: &tags}).Return(nil, expectedErr)
+
+	tags, err := Delete(ctx, db, "1", tags)
+	assert.Nil(t, tags)
+	assert.NotNil(t, err)
+}

internal/handler/workflow/create.go

@@ -28,5 +28,6 @@ func CreateWorkflow(ctx context.Context, storage persistence.Storage, wf *model.
 		log.Error().Err(err).Msg("Failed to create workflow")
 		return nil, fault.Wrap(err)
 	}
+	log.Info().Str("name", wf.Name).Msg("Created new workflow")
 	return wf, nil
 }

internal/handler/workflow/delete.go

@@ -18,6 +18,10 @@ import (
 
 func DeleteWorkflow(ctx context.Context, storage persistence.Storage, name string) error {
 	log := logging.LoggerFromCtx(ctx)
-	log.Debug().Str("name", name).Msg("Deleting workflow")
-	return fault.Wrap(storage.DeleteWorkflow(ctx, name))
+	if err := storage.DeleteWorkflow(ctx, name); err != nil {
+		log.Err(err).Str("name", name).Msg("Failed to delete workflow")
+		return fault.Wrap(err)
+	}
+	log.Info().Str("name", name).Msg("Deleted workflow")
+	return nil
 }

justfile

@@ -112,8 +112,11 @@ _generate-ent:
 
          // Code generated by ent, DO NOT EDIT." --feature sql/execquery,sql/versioned-migration ./schema
 
+_generate-mockery:
+    mockery --all
+
 # Generate code
-generate: _generate-swagger _generate-ent
+generate: _generate-swagger _generate-ent _generate-mockery
 
 # Start PostgreSQL container
 postgres-start VERSION="15":

persistence/.mockery.yaml

@@ -0,0 +1,19 @@
+with-expecter: True
+inpackage: True
+dir: "{{.InterfaceDir}}"
+mockname: "Mock{{.InterfaceName}}"
+outpkg: "{{.PackageName}}"
+filename: "mock_{{.InterfaceName}}.go"
+all: True
+
+boilerplate-file: .ci/mockery_header.txt
+# tags are currently broken, see vektra/mockery issue #691
+tags: testing
+
+packages:
+  github.com/siemens/wfx/persistence:
+    config:
+      tags: testing
+      recursive: True
+    interfaces:
+      Storage: