ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed

Community Support
1

Hi All,

I am trying to understand Temporal’s retry mechanism. Here’s is my retry policy setup on activity level.

ao := workflow.ActivityOptions{
		ScheduleToStartTimeout: time.Minute * 2,
		StartToCloseTimeout:    time.Minute * 10,
		HeartbeatTimeout:       time.Second * 10,
		RetryPolicy: &temporal.RetryPolicy{
			InitialInterval:    time.Second,
			BackoffCoefficient: 2.0,
			MaximumInterval:    time.Minute,
			MaximumAttempts:    5,
		},
	}

I have an activity that is basically making an API call. The response from the API will be either 403 or 500.

The behaviour I am seeing is that:

  • For certain run, there is one attempt (Attempt 1) and the workflow completes as expected (of course with 403 or 500 API response).

  • And for certain run, i get below and the Temporal makes 5 attempts as specified in the policy. Surprisingly - all these 5 attempts, i get the same API response. In other words, teamporal just keeps making all 5 attempts.

INFO  Task processing failed with error Namespace default TaskQueue new_provide WorkerID 26612@hostname@ WorkerType ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed

May i ask what’s actually happening and based on what condition Temporal is deciding to make this 5 new attempts?

Here are the run logs for two seperate workflow trigger, if helps to understand:

---> Starter Trigger
2021/09/19 09:48:50 INFO  Create ProductOrder Workflow started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_64ad19ef-9ea3-46a1-92ef-3789c310acb0 RunID 305bff0
e-78c5-4d56-823b-65728459dd74 Attempt 1
2021/09/19 09:48:50 DEBUG ExecuteActivity Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_64ad19ef-9ea3-46a1-92ef-3789c310acb0 RunID 305bff0e-78c5-4d56-823b-65728
459dd74 Attempt 1 ActivityID 5 ActivityType StepZeroActivity
2021/09/19 09:48:50 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 1 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_64ad19ef-9ea3-46a1-92ef-3789c310acb0 RunID 305bff0e-78c5-4d56-823b-65728459dd74
2021/09/19 09:49:01 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 2 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_64ad19ef-9ea3-46a1-92ef-3789c310acb0 RunID 305bff0e-78c5-4d56-823b-65728459dd74
2021/09/19 09:49:01 Status Code: ->  403
2021/09/19 09:49:01
2021/09/19 09:49:01 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 2 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_64ad19ef-9ea3-46a
1-92ef-3789c310acb0 RunID 305bff0e-78c5-4d56-823b-65728459dd74


---> Starter Trigger
2021/09/19 09:49:26 INFO  Create ProductOrder Workflow started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343
d-8667-403f-9699-6ecd16c13e51 Attempt 1
2021/09/19 09:49:26 DEBUG ExecuteActivity Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd1
6c13e51 Attempt 1 ActivityID 5 ActivityType StepZeroActivity
2021/09/19 09:49:26 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 1 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:49:37 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 2 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:49:39 Status Code: ->  500

2021/09/19 09:49:39 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 1 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4db
c-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:49:39 INFO  Task processing failed with error Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkerType ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed
2021/09/19 09:49:48 Status Code: ->  500

2021/09/19 09:49:48 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 2 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4db
c-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:49:48 INFO  Task processing failed with error Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkerType ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed
2021/09/19 09:49:49 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 3 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:50:01 Status Code: ->  500

2021/09/19 09:50:01 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 3 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4db
c-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:50:01 INFO  Task processing failed with error Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkerType ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed
2021/09/19 09:50:03 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 4 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:50:15 Status Code: ->  500

2021/09/19 09:50:15 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 4 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4db
c-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:50:15 INFO  Task processing failed with error Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ WorkerType ActivityWorker Error invalid activityID or activity already timed out or invoking workflow is completed
2021/09/19 09:50:21 INFO  Create Product Order: Activity Execution started. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 5 WorkflowType WorkflowCreateProductOrder Workflow
ID TestWorks_22e63441-d0a3-4dbc-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51
2021/09/19 09:50:29 Status Code: ->  500

2021/09/19 09:50:29 INFO  Activity succeed. Namespace default TaskQueue TestWorks WorkerID 26612@Hostname@ ActivityID 5 ActivityType StepZeroActivity Attempt 5 WorkflowType WorkflowCreateProductOrder WorkflowID TestWorks_22e63441-d0a3-4db
c-ace7-b0b60e75206a RunID 50cc343d-8667-403f-9699-6ecd16c13e51

Thanks
/Raihan

2

I think your activity is retried due to activity heartbeat timeout. If activity execution takes longer than the heartbeat timeout (10 seconds in your case) and the activity doesn’t heartbeat within this timeout, it fails. The “invalid activityID or activity already timed out or invoking workflow is completed” error is logged when activity reports its completion after the activity is already timed out by the service.

3

Thanks Maxim.