Activity is scheduled but does not start

Community Support
1

Hi all,

Last night our team initiated a set of seven workflows, two of which did not commence their activity task, and instead have been hanging at ActivityTaskScheduled since their workflows begun. All the others’ history is similar, but the ActivityTaskScheduled event is immediately followed by an ActivityTaskStarted event and they execute as normal. Any idea as to why this is occurring? I’ve included a history json below of one of the hanging workflows:

[
  {
    "eventTime": "2021-03-31T07:34:24.000Z",
    "eventType": "WorkflowExecutionStarted",
    "eventId": "1",
    "details": {
      "workflowType": {
        "name": "SingerWorkflowInterface"
      },
      "parentWorkflowNamespace": "",
      "parentWorkflowExecution": null,
      "parentInitiatedEventId": "0",
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "input": {
        "payloads": [
          "something_not_important",
          ""
        ]
      },
      "workflowExecutionTimeout": {
        "duration": 864000000
      },
      "workflowRunTimeout": {
        "duration": 864000000
      },
      "workflowTaskTimeout": {
        "duration": 10
      },
      "continuedExecutionRunId": "",
      "initiator": "Unspecified",
      "continuedFailure": null,
      "lastCompletionResult": null,
      "originalExecutionRunId": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
      "identity": "pod_name",
      "firstExecutionRunId": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
      "retryPolicy": null,
      "attempt": 1,
      "workflowExecutionExpirationTime": "2048-08-16T07:34:24.000Z",
      "cronSchedule": "",
      "firstWorkflowTaskBackoff": {
        "duration": 0
      },
      "memo": null,
      "searchAttributes": null,
      "prevAutoResetPoints": null,
      "header": null,
      "eventId": "1",
      "eventType": "WorkflowExecutionStarted",
      "kvps": [
        {
          "key": "eventTime",
          "value": "Mar 31st 3:34:24 am"
        },
        {
          "key": "eventId",
          "value": "1"
        },
        {
          "key": "workflowType.name",
          "value": "SingerWorkflowInterface"
        },
        {
          "key": "parentWorkflowNamespace",
          "value": ""
        },
        {
          "key": "parentInitiatedEventId",
          "value": "0"
        },
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            ""
          ]
        },
        {
          "key": "workflowExecutionTimeout",
          "value": "240000h"
        },
        {
          "key": "workflowRunTimeout",
          "value": "240000h"
        },
        {
          "key": "workflowTaskTimeout",
          "value": "10s"
        },
        {
          "key": "continuedExecutionRunId",
          "value": ""
        },
        {
          "key": "initiator",
          "value": "Unspecified"
        },
        {
          "key": "originalExecutionRunId",
          "value": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "firstExecutionRunId",
          "value": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1"
        },
        {
          "key": "attempt",
          "value": 1
        },
        {
          "key": "workflowExecutionExpirationTime",
          "value": "2048-08-16T07:34:24.000Z"
        },
        {
          "key": "cronSchedule",
          "value": ""
        },
        {
          "key": "firstWorkflowTaskBackoff",
          "value": ""
        }
      ],
      "eventTime": "Mar 31st 3:34:24 am"
    },
    "eventTimeDisplay": "Mar 31st 3:34:24 am",
    "timeElapsedDisplay": "Mar 31st 3:34:24 am",
    "eventSummary": {
      "Close Timeout": "240000h",
      "identity": "pod_name",
      "input": {
        "payloads": [
          "something_not_important",
          ""
        ]
      },
      "Workflow": "SingerWorkflowInterface",
      "eventId": "1",
      "eventType": "WorkflowExecutionStarted",
      "kvps": [
        {
          "key": "Close Timeout",
          "value": "240000h"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            ""
          ]
        },
        {
          "key": "Workflow",
          "value": "SingerWorkflowInterface"
        }
      ]
    },
    "eventFullDetails": {
      "workflowType": {
        "name": "SingerWorkflowInterface"
      },
      "parentWorkflowNamespace": "",
      "parentWorkflowExecution": null,
      "parentInitiatedEventId": "0",
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "input": {
        "payloads": [
          "something_not_important",
          ""
        ]
      },
      "workflowExecutionTimeout": {
        "duration": 864000000
      },
      "workflowRunTimeout": {
        "duration": 864000000
      },
      "workflowTaskTimeout": {
        "duration": 10
      },
      "continuedExecutionRunId": "",
      "initiator": "Unspecified",
      "continuedFailure": null,
      "lastCompletionResult": null,
      "originalExecutionRunId": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
      "identity": "pod_name",
      "firstExecutionRunId": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
      "retryPolicy": null,
      "attempt": 1,
      "workflowExecutionExpirationTime": "2048-08-16T07:34:24.000Z",
      "cronSchedule": "",
      "firstWorkflowTaskBackoff": {
        "duration": 0
      },
      "memo": null,
      "searchAttributes": null,
      "prevAutoResetPoints": null,
      "header": null,
      "eventId": "1",
      "eventType": "WorkflowExecutionStarted",
      "kvps": [
        {
          "key": "workflowType.name",
          "value": "SingerWorkflowInterface"
        },
        {
          "key": "parentWorkflowNamespace",
          "value": ""
        },
        {
          "key": "parentInitiatedEventId",
          "value": "0"
        },
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            ""
          ]
        },
        {
          "key": "workflowExecutionTimeout",
          "value": "240000h"
        },
        {
          "key": "workflowRunTimeout",
          "value": "240000h"
        },
        {
          "key": "workflowTaskTimeout",
          "value": "10s"
        },
        {
          "key": "continuedExecutionRunId",
          "value": ""
        },
        {
          "key": "initiator",
          "value": "Unspecified"
        },
        {
          "key": "originalExecutionRunId",
          "value": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "firstExecutionRunId",
          "value": "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1"
        },
        {
          "key": "attempt",
          "value": 1
        },
        {
          "key": "workflowExecutionExpirationTime",
          "value": "2048-08-16T07:34:24.000Z"
        },
        {
          "key": "cronSchedule",
          "value": ""
        },
        {
          "key": "firstWorkflowTaskBackoff",
          "value": ""
        }
      ]
    }
  },
  {
    "eventTime": "2021-03-31T07:34:24.000Z",
    "eventType": "WorkflowTaskScheduled",
    "eventId": "2",
    "details": {
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "startToCloseTimeout": {
        "duration": 10
      },
      "attempt": 1,
      "eventId": "2",
      "eventType": "WorkflowTaskScheduled",
      "kvps": [
        {
          "key": "eventTime",
          "value": "Mar 31st 3:34:24 am"
        },
        {
          "key": "eventId",
          "value": "2"
        },
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "startToCloseTimeout",
          "value": "10s"
        },
        {
          "key": "attempt",
          "value": 1
        }
      ],
      "eventTime": "Mar 31st 3:34:24 am"
    },
    "eventTimeDisplay": "Mar 31st 3:34:24 am",
    "timeElapsedDisplay": "",
    "eventSummary": {
      "Taskqueue": "singer-activity-task-list",
      "Timeout": "10s",
      "eventId": "2",
      "eventType": "WorkflowTaskScheduled",
      "kvps": [
        {
          "key": "Taskqueue",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "Timeout",
          "value": "10s"
        }
      ]
    },
    "eventFullDetails": {
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "startToCloseTimeout": {
        "duration": 10
      },
      "attempt": 1,
      "eventId": "2",
      "eventType": "WorkflowTaskScheduled",
      "kvps": [
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "startToCloseTimeout",
          "value": "10s"
        },
        {
          "key": "attempt",
          "value": 1
        }
      ]
    }
  },
  {
    "eventTime": "2021-03-31T07:34:24.000Z",
    "eventType": "WorkflowTaskStarted",
    "eventId": "3",
    "details": {
      "scheduledEventId": "2",
      "identity": "pod_name",
      "requestId": "bccc108c-7699-4ffe-8eb1-407a5c96f69a",
      "eventId": "3",
      "eventType": "WorkflowTaskStarted",
      "kvps": [
        {
          "key": "eventTime",
          "value": "Mar 31st 3:34:24 am"
        },
        {
          "key": "eventId",
          "value": "3"
        },
        {
          "key": "scheduledEventId",
          "value": "2"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "requestId",
          "value": "bccc108c-7699-4ffe-8eb1-407a5c96f69a"
        }
      ],
      "eventTime": "Mar 31st 3:34:24 am"
    },
    "eventTimeDisplay": "Mar 31st 3:34:24 am",
    "timeElapsedDisplay": "",
    "eventSummary": {
      "requestId": "bccc108c-7699-4ffe-8eb1-407a5c96f69a",
      "eventId": "3",
      "eventType": "WorkflowTaskStarted",
      "kvps": [
        {
          "key": "requestId",
          "value": "bccc108c-7699-4ffe-8eb1-407a5c96f69a"
        }
      ]
    },
    "eventFullDetails": {
      "scheduledEventId": "2",
      "identity": "pod_name",
      "requestId": "bccc108c-7699-4ffe-8eb1-407a5c96f69a",
      "eventId": "3",
      "eventType": "WorkflowTaskStarted",
      "kvps": [
        {
          "key": "scheduledEventId",
          "value": "2"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "requestId",
          "value": "bccc108c-7699-4ffe-8eb1-407a5c96f69a"
        }
      ]
    }
  },
  {
    "eventTime": "2021-03-31T07:34:24.000Z",
    "eventType": "WorkflowTaskCompleted",
    "eventId": "4",
    "details": {
      "scheduledEventId": "2",
      "startedEventId": "3",
      "identity": "pod_name",
      "binaryChecksum": "",
      "eventId": "4",
      "eventType": "WorkflowTaskCompleted",
      "kvps": [
        {
          "key": "eventTime",
          "value": "Mar 31st 3:34:24 am"
        },
        {
          "key": "eventId",
          "value": "4"
        },
        {
          "key": "scheduledEventId",
          "value": "2"
        },
        {
          "key": "startedEventId",
          "value": "3"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "binaryChecksum",
          "value": ""
        }
      ],
      "eventTime": "Mar 31st 3:34:24 am"
    },
    "eventTimeDisplay": "Mar 31st 3:34:24 am",
    "timeElapsedDisplay": "",
    "eventSummary": {
      "identity": "pod_name",
      "eventId": "4",
      "eventType": "WorkflowTaskCompleted",
      "kvps": [
        {
          "key": "identity",
          "value": "pod_name"
        }
      ]
    },
    "eventFullDetails": {
      "scheduledEventId": "2",
      "startedEventId": "3",
      "identity": "pod_name",
      "binaryChecksum": "",
      "eventId": "4",
      "eventType": "WorkflowTaskCompleted",
      "kvps": [
        {
          "key": "scheduledEventId",
          "value": "2"
        },
        {
          "key": "startedEventId",
          "value": "3"
        },
        {
          "key": "identity",
          "value": "pod_name"
        },
        {
          "key": "binaryChecksum",
          "value": ""
        }
      ]
    }
  },
  {
    "eventTime": "2021-03-31T07:34:24.000Z",
    "eventType": "ActivityTaskScheduled",
    "eventId": "5",
    "details": {
      "activityId": "7fc451ab-3b05-346a-9ed4-390fb054186d",
      "activityType": {
        "name": "TapToTarget"
      },
      "namespace": "",
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "header": {
        "fields": {}
      },
      "input": {
        "payloads": [
          "something_not_important",
          "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
          "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
          ""
        ]
      },
      "scheduleToCloseTimeout": {
        "duration": 172800
      },
      "scheduleToStartTimeout": {
        "duration": 172800
      },
      "startToCloseTimeout": {
        "duration": 172800
      },
      "heartbeatTimeout": {
        "duration": 0
      },
      "workflowTaskCompletedEventId": "4",
      "retryPolicy": {
        "nonRetryableErrorTypes": [],
        "initialInterval": {
          "duration": 1
        },
        "backoffCoefficient": 2,
        "maximumInterval": {
          "duration": 10
        },
        "maximumAttempts": 3
      },
      "eventId": "5",
      "eventType": "ActivityTaskScheduled",
      "kvps": [
        {
          "key": "eventTime",
          "value": "Mar 31st 3:34:24 am"
        },
        {
          "key": "eventId",
          "value": "5"
        },
        {
          "key": "activityId",
          "value": "7fc451ab-3b05-346a-9ed4-390fb054186d"
        },
        {
          "key": "activityType.name",
          "value": "TapToTarget"
        },
        {
          "key": "namespace",
          "value": ""
        },
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
            "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
            ""
          ]
        },
        {
          "key": "scheduleToCloseTimeout",
          "value": "48h"
        },
        {
          "key": "scheduleToStartTimeout",
          "value": "48h"
        },
        {
          "key": "startToCloseTimeout",
          "value": "48h"
        },
        {
          "key": "heartbeatTimeout",
          "value": ""
        },
        {
          "key": "workflowTaskCompletedEventId",
          "value": "4"
        },
        {
          "key": "retryPolicy.initialInterval",
          "value": "1s"
        },
        {
          "key": "retryPolicy.backoffCoefficient",
          "value": 2
        },
        {
          "key": "retryPolicy.maximumInterval",
          "value": "10s"
        },
        {
          "key": "retryPolicy.maximumAttempts",
          "value": 3
        }
      ],
      "eventTime": "Mar 31st 3:34:24 am"
    },
    "eventTimeDisplay": "Mar 31st 3:34:24 am",
    "timeElapsedDisplay": "",
    "eventSummary": {
      "Close Timeout": "48h",
      "Id": "7fc451ab-3b05-346a-9ed4-390fb054186d",
      "input": {
        "payloads": [
          "something_not_important",
          "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
          "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
          ""
        ]
      },
      "Name": "TapToTarget",
      "eventId": "5",
      "eventType": "ActivityTaskScheduled",
      "kvps": [
        {
          "key": "Close Timeout",
          "value": "48h"
        },
        {
          "key": "Id",
          "value": "7fc451ab-3b05-346a-9ed4-390fb054186d"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
            "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
            ""
          ]
        },
        {
          "key": "Name",
          "value": "TapToTarget"
        }
      ]
    },
    "eventFullDetails": {
      "activityId": "7fc451ab-3b05-346a-9ed4-390fb054186d",
      "activityType": {
        "name": "TapToTarget"
      },
      "namespace": "",
      "taskQueue": {
        "name": "singer-activity-task-list",
        "kind": "Normal"
      },
      "header": {
        "fields": {}
      },
      "input": {
        "payloads": [
          "something_not_important",
          "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
          "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
          ""
        ]
      },
      "scheduleToCloseTimeout": {
        "duration": 172800
      },
      "scheduleToStartTimeout": {
        "duration": 172800
      },
      "startToCloseTimeout": {
        "duration": 172800
      },
      "heartbeatTimeout": {
        "duration": 0
      },
      "workflowTaskCompletedEventId": "4",
      "retryPolicy": {
        "nonRetryableErrorTypes": [],
        "initialInterval": {
          "duration": 1
        },
        "backoffCoefficient": 2,
        "maximumInterval": {
          "duration": 10
        },
        "maximumAttempts": 3
      },
      "eventId": "5",
      "eventType": "ActivityTaskScheduled",
      "kvps": [
        {
          "key": "activityId",
          "value": "7fc451ab-3b05-346a-9ed4-390fb054186d"
        },
        {
          "key": "activityType.name",
          "value": "TapToTarget"
        },
        {
          "key": "namespace",
          "value": ""
        },
        {
          "key": "taskQueue.name",
          "routeLink": {
            "name": "task-queue",
            "params": {
              "taskQueue": "singer-activity-task-list"
            }
          },
          "value": "singer-activity-task-list"
        },
        {
          "key": "taskQueue.kind",
          "value": "Normal"
        },
        {
          "key": "input",
          "value": [
            "something_not_important",
            "00138-7d09f-32cf5d69babb8c81ce536f8e03648557",
            "57c89a92-84fb-46aa-9f81-9e0faaf4d5b1",
            ""
          ]
        },
        {
          "key": "scheduleToCloseTimeout",
          "value": "48h"
        },
        {
          "key": "scheduleToStartTimeout",
          "value": "48h"
        },
        {
          "key": "startToCloseTimeout",
          "value": "48h"
        },
        {
          "key": "heartbeatTimeout",
          "value": ""
        },
        {
          "key": "workflowTaskCompletedEventId",
          "value": "4"
        },
        {
          "key": "retryPolicy.initialInterval",
          "value": "1s"
        },
        {
          "key": "retryPolicy.backoffCoefficient",
          "value": 2
        },
        {
          "key": "retryPolicy.maximumInterval",
          "value": "10s"
        },
        {
          "key": "retryPolicy.maximumAttempts",
          "value": 3
        }
      ]
    }
  }
]

Thanks!

2

activity task started will only appear if activity is finished (completed / timeout / failed)
you can get the current activity info by using the web UI summary page or tctl --namespace <your namespace> workflow describe -w <workflow ID> -r <run ID>

3

Currently the workflows on the ui say they have a pending activity with state PENDING_ACTIVITY_STATE_STARTED

4

What is the value of attempts in the describe output?

The activity timeouts you configured are very high. So if anything happens to the activity worker the timeout will be delivered to the workflow only after 2 days. Is it intentional? Is this activity indeed expected to run for 2 days?

5

Here is the value from tctl describe:
{
“executionConfig”: {
“taskQueue”: {
“name”: “singer-activity-task-list”,
“kind”: “Normal”
},
“workflowExecutionTimeout”: “864000000s”,
“workflowRunTimeout”: “864000000s”,
“defaultWorkflowTaskTimeout”: “10s”
},
“workflowExecutionInfo”: {
“execution”: {
“workflowId”: “00138-7d09f-32cf5d69babb8c81ce536f8e03648557”,
“runId”: “57c89a92-84fb-46aa-9f81-9e0faaf4d5b1”
},
“type”: {
“name”: “SingerWorkflowInterface”
},
“startTime”: “2021-03-31T07:34:24.151516778Z”,
“status”: “Running”,
“historyLength”: “5”,
“memo”: {
​
},
“autoResetPoints”: {
​
}
},
“pendingActivities”: [
{
“activityId”: “7fc451ab-3b05-346a-9ed4-390fb054186d”,
“activityType”: {
“name”: “TapToTarget”
},
“state”: “Started”,
“lastHeartbeatTime”: “2021-03-31T07:34:24.241618751Z”,
“lastStartedTime”: “2021-03-31T07:34:24.241618751Z”,
“attempt”: 1,
“maximumAttempts”: 3,
“expirationTime”: “2021-04-02T07:34:24.216715334Z”
}
]
}

It is intentional, as our activities may run for 48 hours in exceptional scenarios - is there a way to do this more flexibly? To both allow for outliers to run for long periods but have knowledge of their failure before the maximum time?

6

So it looks like your activity failed and the service is waiting for it to be retried in 48 hours after a timeout.

It is intentional, as our activities may run for 48 hours in exceptional scenarios - is there a way to do this more flexibly? To both allow for outliers to run for long periods but have knowledge of their failure before the maximum time?

Yes, specify a short heartbeat timeout and change your activity implementation to heartbeat.

7

Thanks @maxim, we will have to look into that. Could this be the result of restarting the worker during activity execution w/ no heartbeating? That seems to be the possibility we are looking into now. Would temporal report an activity failure in that case?

8 
      "heartbeatTimeout": {
        "duration": 0
      },

try to configure a heartbeat timeout value, and within your activity do periodically heartbeat to prevent timeout

Could this be the result of restarting the worker during activity execution w/ no 
heartbeating?

yes

1 Like