Better logging when getting some nondeterministic behaviours (#1245)

* Added a better log message for nondeterministic errors

* Upped log level to Error as this is an error

* Created test for the logging update

* Fixed imports

Author: jakobht

internal/internal_task_handlers.go

@@ -944,13 +944,18 @@ ProcessEvents:
 				if isReplayTest {
 					// NOTE: we should do this regardless if it's in replay test or not
 					// but since previously we checked the wrong error type, it may break existing customers workflow
+					// the issue is that we change the error type and that we change the error message, the customers
+					// are checking the error string - we plan to wrap all errors to avoid this issue in client v2
 					nonDeterministicErr = panicErr
 				} else {
-					w.wth.logger.Warn("Ignored workflow panic error",
+					// Since we know there is an error, we do the replay check to give more context in the log
+					replayErr := matchReplayWithHistory(replayDecisions, respondEvents)
+					w.wth.logger.Error("Ignored workflow panic error",
 						zap.String(tagWorkflowType, task.WorkflowType.GetName()),
 						zap.String(tagWorkflowID, task.WorkflowExecution.GetWorkflowId()),
 						zap.String(tagRunID, task.WorkflowExecution.GetRunId()),
 						zap.Error(nonDeterministicErr),
+						zap.NamedError("ReplayError", replayErr),
 					)
 				}
 			}

internal/internal_task_handlers_test.go

@@ -39,7 +39,9 @@ import (
 	"github.com/stretchr/testify/suite"
 	"go.uber.org/goleak"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"go.uber.org/zap/zaptest"
+	"go.uber.org/zap/zaptest/observer"
 
 	"go.uber.org/cadence/.gen/go/cadence/workflowservicetest"
 	s "go.uber.org/cadence/.gen/go/shared"
@@ -826,6 +828,69 @@ func (t *TaskHandlersTestSuite) TestWorkflowTask_NondeterministicDetection() {
 	t.NotNil(request)
 }
 
+func (t *TaskHandlersTestSuite) TestWorkflowTask_NondeterministicLogNonexistingID() {
+	taskList := "taskList"
+	testEvents := []*s.HistoryEvent{
+		createTestEventWorkflowExecutionStarted(1, &s.WorkflowExecutionStartedEventAttributes{TaskList: &s.TaskList{Name: &taskList}}),
+		createTestEventDecisionTaskScheduled(2, &s.DecisionTaskScheduledEventAttributes{TaskList: &s.TaskList{Name: &taskList}}),
+		createTestEventDecisionTaskStarted(3),
+		createTestEventDecisionTaskCompleted(4, &s.DecisionTaskCompletedEventAttributes{ScheduledEventId: common.Int64Ptr(2)}),
+		createTestEventActivityTaskScheduled(5, &s.ActivityTaskScheduledEventAttributes{
+			// Insert an ID which does not exist
+			ActivityId:   common.StringPtr("NotAnActivityID"),
+			ActivityType: &s.ActivityType{Name: common.StringPtr("pkg.Greeter_Activity")},
+			TaskList:     &s.TaskList{Name: &taskList},
+		}),
+	}
+
+	obs, logs := observer.New(zap.ErrorLevel)
+	logger := zap.New(obs)
+
+	task := createWorkflowTask(testEvents, 3, "HelloWorld_Workflow")
+	stopC := make(chan struct{})
+	params := workerExecutionParameters{
+		TaskList: taskList,
+		WorkerOptions: WorkerOptions{
+			Identity: "test-id-1",
+			Logger:   logger,
+		},
+		WorkerStopChannel: stopC,
+	}
+
+	taskHandler := newWorkflowTaskHandler(testDomain, params, nil, t.registry)
+	request, err := taskHandler.ProcessWorkflowTask(&workflowTask{task: task}, nil)
+
+	t.NotNil(request)
+	response := request.(*s.RespondDecisionTaskFailedRequest)
+
+	// NOTE: we might acctually want to return an error
+	// but since previously we checked the wrong error type, it may break existing customers workflow
+	// The issue is that we change the error type and that we change the error message, the customers
+	// are checking the error string - we plan to wrap all errors to avoid this issue in client v2
+	t.NoError(err)
+	t.NotNil(response)
+
+	// Check that the error was logged
+	ignoredWorkflowLogs := logs.FilterMessage("Ignored workflow panic error")
+	require.Len(t.T(), ignoredWorkflowLogs.All(), 1)
+
+	// Find the ReplayError field
+	withField := ignoredWorkflowLogs.All()[0]
+	var replayErrorField *zapcore.Field
+	for _, field := range withField.Context {
+		if field.Key == "ReplayError" {
+			replayErrorField = &field
+		}
+	}
+	require.NotNil(t.T(), replayErrorField)
+	require.Equal(t.T(), zapcore.ErrorType, replayErrorField.Type)
+	require.ErrorContains(t.T(), replayErrorField.Interface.(error),
+		"nondeterministic workflow: "+
+			"history event is ActivityTaskScheduled: (ActivityId:NotAnActivityID, ActivityType:(Name:pkg.Greeter_Activity), TaskList:(Name:taskList), Input:[]), "+
+			"replay decision is ScheduleActivityTask: (ActivityId:0, ActivityType:(Name:Greeter_Activity), TaskList:(Name:taskList)")
+
+}
+
 func (t *TaskHandlersTestSuite) TestWorkflowTask_WorkflowReturnsPanicError() {
 	taskList := "taskList"
 	testEvents := []*s.HistoryEvent{