Actions stuck in scheduled for 15 minutes

[skiedude]

We are running Stackstorm on a Rocky8 VM.
The VM has 126gb of Memory, multiple cores. Server load never sits above .2

We are using a remote MongoDB cluster, and a remote RMQ cluster, and local Redis. Using the default of 10 action runners.

We have on a few occasions observed how actions are stuck in a scheduled state. (not always)

Looking at the RMQ cluster, I can see the one item in queue
st2.actionrunner.work 1

2024-03-13 09:09:02,886 140648024292688 INFO handler [-] [65f1cf9e7b9e07f37d3fb327] Retrieved item "65f1cf9e6df7dd826a3b02b8" from scheduling queue.
2024-03-13 09:09:02,899 140648019684864 INFO handler [-] [65f1cf9e7b9e07f37d3fb327] Scheduling Liveaction "65f1cf9e7b9e07f37d3fb326". (queue_item_id='65f1cf9e6df7dd826a3b02b8')
2024-03-13 09:09:02,904 140648019684864 INFO handler [-] [65f1cf9e7b9e07f37d3fb327] Liveaction "65f1cf9e7b9e07f37d3fb326" with status "requested" is updated to status "scheduled." (queue_item_id='65f1cf9e6df7dd826a3b02b8')
2024-03-13 09:09:02,908 140648019684864 DEBUG action_db [-] Updating ActionExection: "65f1cf9e7b9e07f37d3fb326" with status="scheduled" (liveaction_db={'action': 'custom_pack.restart_service', 'action_is_workflow': True, 'callback': {}, 'context': {'user': 'username', 'pack': 'custom_pack'}, 'delay': None, 'end_timestamp': None, 'id': '65f1cf9e7b9e07f37d3fb326', 'notify': None, 'parameters': {'prod_servers': ['server.name']}, 'result': {}, 'runner_info': {}, 'start_timestamp': '2024-03-13 16:09:02.746231+00:00', 'status': 'requested', 'task_execution': None, 'workflow_execution': None})
2024-03-13 09:09:02,944 140648019684864 DEBUG channel [-] using channel_id: 1
2024-03-13 09:09:02,946 140648019684864 DEBUG channel [-] Channel open
2024-03-13 09:09:02,948 140648019684864 DEBUG channel [-] Closed channel #1
2024-03-13 09:09:02,948 140648019684864 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'action': 'custom_pack.restart_service'', 'action_is_workflow': True, 'callback': {}, 'context': {'user': 'username', 'pack': 'custom_pack'}, 'delay': None, 'end_timestamp': None, 'id': '65f1cf9e7b9e07f37d3fb326', 'notify': None, 'parameters': {'prod_servers': ['server.name']}, 'result': {}, 'runner_info': {}, 'start_timestamp': '2024-03-13 16:09:02.746231+00:00', 'status': 'scheduled', 'task_execution': None, 'workflow_execution': None})
2024-03-13 09:09:02,976 140648019684864 DEBUG coordination [-] Using cached coordinator instance: <tooz.drivers.redis.RedisDriver object at 0x7feb2b7cee80>
2024-03-13 09:09:02,986 140648019684864 DEBUG channel [-] using channel_id: 1
2024-03-13 09:09:02,988 140648019684864 DEBUG channel [-] Channel open
2024-03-13 09:09:02,992 140648019684864 DEBUG channel [-] Closed channel #1
2024-03-13 09:09:02,993 140648019684864 AUDIT action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=65f1cf9e7b9e07f37d3fb326, ActionExecution.id=65f1cf9e7b9e07f37d3fb327> (action_execution_db={'action': {'tags': [], 'uid': 'action:adobe_sma:restart_opentsdb', 'metadata_file': 'actions/restart_service.meta.yaml', 'name': 'restart_service', 'ref': 'custom_pack.restart_service'', 'description': 'Action that restarts a service', 'enabled': True, 'entry_point': 'workflows/restart_service.yaml', 'pack': 'custom_pack', 'runner_type': 'orquesta', 'parameters': {'prod_servers': {'type': 'array', 'required': True}}, 'output_schema': {}, 'notify': {}, 'id': '65e23e7a48375de06dfb00e2'}, 'children': [], 'context': {'user': 'username', 'pack': 'custom_pack'}, 'delay': None, 'end_timestamp': None, 'id': '65f1cf9e7b9e07f37d3fb327', 'liveaction': {'action': 'custom_pack.restart_service'', 'action_is_workflow': True, 'parameters': {'prod_servers': ['server.name']}, 'callback': {}, 'runner_info': {}, 'id': '65f1cf9e7b9e07f37d3fb326'}, 'log': [{'timestamp': '2024-03-13T16:09:02.764000+00:00', 'status': 'requested'}, {'timestamp': '2024-03-13T16:09:02.977000+00:00', 'status': 'scheduled'}], 'parameters': {'prod_servers': ['server.name']}, 'parent': None, 'result': {}, 'result_size': 0, 'rule': {}, 'runner': {'name': 'orquesta', 'description': 'A runner for executing orquesta workflow.', 'uid': 'runner_type:orquesta', 'enabled': True, 'runner_package': 'orquesta_runner', 'runner_module': 'orquesta_runner', 'runner_parameters': {'notify': {'type': 'array', 'description': 'List of tasks to trigger notifications for.', 'uniqueItems': True, 'items': {'type': 'string', 'minLength': 1, 'pattern': '^\\w+$'}, 'default': []}}, 'output_key': 'output', 'output_schema': {'type': 'object', 'properties': {'errors': {'anyOf': [{'type': 'object'}, {'type': 'array'}]}, 'output': {'anyOf': [{'type': 'object'}, {'type': 'string'}, {'type': 'integer'}, {'type': 'number'}, {'type': 'boolean'}, {'type': 'array'}, {'type': 'null'}]}}, 'additionalProperties': False}, 'id': '65bab7b499012a21d4ac8a61'}, 'start_timestamp': '2024-03-13 16:09:02.746231+00:00', 'status': 'scheduled', 'task_execution': None, 'trigger': {}, 'trigger_instance': {}, 'trigger_type': {}, 'web_url': 'urlhere', 'workflow_execution': None},liveaction_db={'action': 'custom_pack.restart_service'', 'action_is_workflow': True, 'callback': {}, 'context': {'user': 'username', 'pack': 'custom_pack'}, 'delay': None, 'end_timestamp': None, 'id': '65f1cf9e7b9e07f37d3fb326', 'notify': None, 'parameters': {'prod_servers': ['server.name']}, 'result': {}, 'runner_info': {}, 'start_timestamp': '2024-03-13 16:09:02.746231+00:00', 'status': 'scheduled', 'task_execution': None, 'workflow_execution': None})
2024-03-13 09:09:03,030 140648019684864 INFO action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=65f1cf9e7b9e07f37d3fb326, ActionExecution.id=65f1cf9e7b9e07f37d3fb327>
2024-03-13 09:09:03,031 140648019684864 DEBUG channel [-] using channel_id: 1
2024-03-13 09:09:03,032 140648019684864 DEBUG channel [-] Channel open
2024-03-13 09:09:03,034 140648019684864 DEBUG channel [-] Closed channel #1

Then exactly 15 minutes later it picks it up and runs it

2024-03-13 09:24:41,207 140648024468992 DEBUG action_db [-] Updated status for LiveAction object. (liveaction_db={'action': 'custom_pack.multienv_remote_cmd', 'action_is_workflow': True, 'callback': {}, 'context': {'pack': 'custom_pack', 'user': '
username', 'parent': {'execution_id': '65f1cf9e7b9e07f37d3fb327', 'user': 'username', 'pack': 'custom_pack'}, 'orquesta': {'workflow_execution_id': '65f1d348528d7b7fe5ae9e70', 'task_execution_id': '65f1d3488e06e5769fc13f0a', 'task_name': 'restart_
service', 'task_id': 'restart_service', 'task_route': 0}}, 'delay': None, 'end_timestamp': None, 'id': '65f1d3498e06e5769fc13f0c', 'notify': None, 'parameters': {'sudo': True, 'command': 'command, 'prod_servers': ['server.name']}, 'result
': {}, 'runner_info': {}, 'start_timestamp': '2024-03-13 16:24:40.998616+00:00', 'status': 'scheduled', 'task_execution': '65f1d3488e06e5769fc13f0a', 'workflow_execution': '65f1d348528d7b7fe5ae9e70'})

Another instance of this from a few days ago shows another exact 15 minute break before running the action

2024-03-08 21:35:02,850 140294571610528 INFO action [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=65ebf5068e06e5769fc13cde, ActionExecution.id=65ebf5068e06e5769fc13cdf>
2024-03-08 21:35:02,850 140294571610528 DEBUG channel [-] using channel_id: 1
2024-03-08 21:35:02,852 140294571610528 DEBUG channel [-] Channel open
2024-03-08 21:35:02,854 140294571610528 DEBUG channel [-] Closed channel #1
2024-03-08 21:50:33,592 140294575119696 INFO handler [-] [65ebf8a98e06e5769fc13cef] Retrieved item "65ebf8a9f53625214d70acab" from scheduling queue.
2024-03-08 21:50:33,604 140294570937328 INFO handler [-] [65ebf8a98e06e5769fc13cef] Scheduling Liveaction "65ebf8a98e06e5769fc13cee". (queue_item_id='65ebf8a9f53625214d70acab')
2024-03-08 21:50:33,610 140294570937328 INFO handler [-] [65ebf8a98e06e5769fc13cef] Liveaction "65ebf8a98e06e5769fc13cee" with status "requested" is updated to status "scheduled." (queue_item_id='65ebf8a9f53625214d70acab')

Is there something that runs every 15 minutes to check for stuck jobs?

[skiedude]

I'm wondering if there is some setting where the scheduler/action runner go into some sort of sleep when a new action hasn't been submitted in an extended period of time?
Over the weekend we ran 0 jobs, and this morning (3 days later) I submitted a test job via a slack command.

It took 15 minutes between each task step to run. So a task that usually takes < 5 seconds took 30 minutes. Every action after that I continued to submit also just hung in a scheduled state.

I tried restarting individual components to see if any given component would get things going. Eventually I just did a full st2ctl restart and new actions after that were executing instantly.

While the tasks were hung I logged into the RMQ admin interface. I could see the message in queue, and that all the consumers were connected

At this point I'm just considering creating a scheduled task that does a core.local that runs once an hour to keep things moving and not have long breaks before executions....

[skiedude]

Also something interesting. Jobs that were stuck waiting for their 15 minutes to run, honored that 15 minutes even after the st2ctl restart was issued.

Newly submitted actions ran instantly, but already queued tasks waited their 15 minutes. The restart was issued at 11:38

[skiedude]

Seems my theory of it being the schedulers/action runners fell in inactive after long periods of no jobs is incorrect. I created a job that runs every 30 minutes and twice in the last 24 hours this job that usually takes 1 second, took 15minutes

[skiedude]

Upon trying a newer version of RMQ cluster the issue has disappeared.
The cluster we were using that had issues was RMQ: 3.6.6 and Erlang: 19.2.3

The new cluster that has run 4 days without issues is RMQ: 3.11.13 and Erlang: 25.3

[nzlosh]

Good to know you found the root cause @skiedude and thank you for sharing the solution to resolve the issue 👍 It may help others in the future who encounter the same problem.