refactor: standardize logging behavior

- Log `Info()` for all operations modifying (create, update, delete) storage - Remove some redundant Debug log messages - Improve error message when workflow name is not unique Signed-off-by: Michael Adler <[email protected]>
siemens · Oct 27, 2023 · 57c23e2 · 57c23e2
1 parent 138671a
commit 57c23e2
Show file tree

Hide file tree

Showing 10 changed files with 93 additions and 34 deletions.
diff --git a/api/northbound.go b/api/northbound.go
@@ -9,6 +9,7 @@ package api
  */
 
 import (
+	"fmt"
 	"net/http"
 
 	"github.com/Southclaws/fault/ftag"
@@ -186,7 +187,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)
 				}

diff --git a/internal/handler/job/definition/update.go b/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)
 	}
 

diff --git a/internal/handler/job/delete.go b/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
 }
diff --git a/internal/handler/job/status/update.go b/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
 }
diff --git a/internal/handler/job/tags/add.go b/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
 }
diff --git a/internal/handler/job/tags/add_test.go b/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")

diff --git a/internal/handler/job/tags/delete.go b/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
 }
diff --git a/internal/handler/job/tags/delete_test.go b/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)
+}
diff --git a/internal/handler/workflow/create.go b/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 workfow")
 	return wf, nil
 }
diff --git a/internal/handler/workflow/delete.go b/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
 }