Workflow stuck because VariableMessageQueueConsumer failed to process message

[GuiTeK]

SUMMARY

After a task failed, the workflow got stuck and didn't execute the next task. The workflow was still in running state but no task was running anymore (all tasks were either succeeded or failed, I checked with st2 execution get ID). The workflow stayed in this state 10 hours+ before I manually canceled it.

When checking st2workflowengine.log, I discovered this (the important line is the last one):

2019-06-04 15:58:28,387 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Publish task "comment_ticket_processing_failure", route "0", with status "succeeded" to conductor.
2019-06-04 15:58:33,330 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Identifying next set (0) of tasks after completion of task "comment_ticket_processing_failure", route "0".
2019-06-04 15:58:33,343 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Identified the following set of tasks to execute next: process_order (route 0)
2019-06-04 15:58:33,343 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Mark task "process_order", route "0", in conductor as running.
2019-06-04 15:58:36,275 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Requesting execution for task "process_order", route "0".
2019-06-04 15:58:36,276 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Processing task execution request for task "process_order", route "0".
2019-06-04 15:58:52,827 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Task execution "5cf69534ba584539159a5e31" created for task "process_order", route "0".
2019-06-04 15:58:56,105 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Action execution "5cf69540ba584539159a5e33" requested for task "process_order", route "0".
2019-06-04 15:58:59,145 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] Identifying next set (1) of tasks for workflow execution in status "running".
2019-06-04 15:58:59,151 140343041628752 INFO workflows [-] [5cf66aa2ba5845383247454d] No tasks identified to execute next.
2019-06-04 15:58:59,562 140343037586640 INFO workflows [-] [5cf66aa2ba5845383247454d] Action execution "5cf69540ba584539159a5e33" for task "process_order" is updated and in "scheduled" state.
2019-06-04 15:59:38,901 140343039628944 INFO workflows [-] [5cf66aa2ba5845383247454d] Action execution "5cf69540ba584539159a5e33" for task "process_order" is updated and in "failed" state.
2019-06-04 15:59:40,684 140343039628944 INFO workflows [-] [5cf66aa2ba5845383247454d] Handling completion of action execution "5cf69540ba584539159a5e33" in status "failed" for task "process_order", route "0".
2019-06-04 15:59:46,846 140343039628944 INFO workflows [-] [5cf66aa2ba5845383247454d] Publish task "process_order", route "0", with status "failed" to conductor.
2019-06-04 15:59:47,796 140343039628944 ERROR consumers [-] VariableMessageQueueConsumer failed to process message: ActionExecutionDB(action={...

After this, there is nothing in the logs for this workflow anymore.

Do you have an idea of what's the root cause/how we can prevent this from happening?

ISSUE TYPE

Bug Report

STACKSTORM VERSION

st2 3.0.1, on Python 2.7.12

OS / ENVIRONMENT / INSTALL METHOD

Custom HA install on Ubuntu 16.04

STEPS TO REPRODUCE

It's hard to reproduce as it doesn't happen everytime. However, it happened already 2 times to me. I think it can happen with any workflow.

EXPECTED RESULTS

If this error happens, it should retry/the workflow shouldn't get stuck.

ACTUAL RESULTS

When this error happens, the workflow gets stuck and we have to manually cancel it.

[GuiTeK]

To update you guys: I missed some important information in the log file. Here is a more complete version:

2019-06-05 11:10:40,566 140071121667248 INFO workflows [-] [5cf78bd8ba5845383247455e] Publish task "complete_order", route "0", with status "succeeded" to conductor.
2019-06-05 11:10:42,035 140071121667248 WARNING workflow [-] Determining if exception <class 'mongoengine.errors.OperationError'> should be retried.
2019-06-05 11:10:42,036 140071121667248 ERROR consumers [-] VariableMessageQueueConsumer failed to process message: ActionExecutionDB(action={...
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/transport/consumers.py", line 72, in _process_message
    self._handler.process(body)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2actions/workflows/workflows.py", line 83, in process
    handler_function(message)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2actions/workflows/workflows.py", line 61, in handle_action_execution_with_instrumentation
    return self.handle_action_execution(ac_ex_db=ac_ex_db)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2actions/workflows/workflows.py", line 134, in handle_action_execution
    wf_svc.handle_action_execution_completion(ac_ex_db)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/services/workflows.py", line 756, in handle_action_execution_completion
    ac_ex_ctx=ac_ex_db.context.get('orquesta')
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/retrying.py", line 49, in wrapped_f
    return Retrying(*dargs, **dkw).call(f, *args, **kw)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/retrying.py", line 206, in call
    return attempt.get(self._wrap_exception)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/retrying.py", line 247, in get
    six.reraise(self.value[0], self.value[1], self.value[2])
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/retrying.py", line 200, in call
    attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/services/workflows.py", line 816, in update_task_state
    pub_ac_ex=publish
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/services/workflows.py", line 1077, in update_execution_records
    wf_ex_db = wf_db_access.WorkflowExecution.update(wf_ex_db, publish=pub_wf_ex)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/persistence/base.py", line 219, in update
    cls._get_impl().update(model_object, **kwargs)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 571, in update
    return self.save(instance)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/db/__init__.py", line 580, in save
    instance.save(save_condition=save_condition, validate=validate)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/mongoengine/document.py", line 420, in save
    raise OperationError(message % six.text_type(err))
OperationError: Could not save document (Resulting document after update is larger than 16777216)

What happens is that our workflow is (very) verbose and it reaches the MongoDB document size limit of 16 MB. Then, StackStorm gets stuck.

Maybe it doesn't make sense to retry in that case, but at least make the workflow fail with an explicit error message.

What do you think?

[arm4b]

Yes, that's the different story and not a bug, but limitation on MongoDB side.

Catching and re-throwing a better error message from the StackStorm side would be nicer indeed 👍

[GuiTeK]

The "bug" for me is that StackStorm gets stuck. It doesn't do anything, even if it knows there is an error. And from the user side, either with st2 execution get ID or in the WebUI, you don't see anything/can't know what's going on.

Thanks!

[ericreeves]

Was this issue truly resolved? The current behavior is still quite vague to the end user in Stackstorm 3.4.

If by some mechanism an object of >16M is generated and the Mongo insert fails, the execution is perpetually stuck in the "running" state, until gc_max_idle_sec is reached, at which point it is simply "canceled".

When this happens, shouldn't Stackstorm immediately mark the execution as "failed"?