Orquesta: Potential Race Condition in Nested Inquiries

SUMMARY

There appears to be a race condition in the way orquesta handles unpausing of a parent workflow when a child workflow has an inquiry which receives a response. After responding to the inquiry in the child workflow, the parent workflow can occasionally get "stuck" in a paused or a running state.

STACKSTORM VERSION

st2 3.1.0, on Python 2.7.6

OS, environment, install method

clean st2-docker installation

Steps to reproduce the problem

For a minimal reproduction, we require 2 workflows, as there needs to be a parent child relationship. The parent workflow will have only 1 task, whose action will be the child workflow. The child workflow will also have 1 task, which is an inquiry. The task transition logic in the child workflow is such that if a false response is sent to the inquiry, the child workflow will fail, causing the parent workflow to succeed. This is the expected behavior. This table shows the states of the parent and child workflows when the expected behavior is exhibited:

However if the inquiry response happens before the parent workflow can enter a paused state, it can cause unexpected behavior. Consider the following:

Here is a detailed set of steps you can follow to reproduce the issue:

1. Follow the instructions in the st2-docker repository to create a clean deployment of stackstorm.
2. install my report pack into the deployment. (Probably easiest to clone the repo in the packs.dev directory)
3. register the newly installed pack
4. First, we will run the workflow to see the expected behavior (the behavior shown in the first table above). On the stackstorm command line:

root@e2c8427e5731:~# st2 run bug.pause-parent
.
id: 5e4493ba0cdfc002b6689669
action.ref: bug.pause-parent
parameters: None
status: paused
start_timestamp: Thu, 13 Feb 2020 00:09:30 UTC
end_timestamp:
result:
  output: null
+-----------------------------+---------+-------+-----------------+-------------------------------+
| id                          | status  | task  | action          | start_timestamp               |
+-----------------------------+---------+-------+-----------------+-------------------------------+
| + 5e4493ba0cdfc0003a644e0d  | paused  | start | bug.pause-child | Thu, 13 Feb 2020 00:09:30 UTC |
|    5e4493bb0cdfc0003a644e10 | pending | wait  | core.ask        | Thu, 13 Feb 2020 00:09:31 UTC |
+-----------------------------+---------+-------+-----------------+-------------------------------+
root@e2c8427e5731:~# st2 inquiry respond 5e4493bb0cdfc0003a644e10
custom_inner_pause (boolean): False

Response accepted for inquiry 5e4493bb0cdfc0003a644e10.
root@e2c8427e5731:~# st2 execution get 5e4493ba0cdfc002b6689669
id: 5e4493ba0cdfc002b6689669
action.ref: bug.pause-parent
parameters: None
status: succeeded (14s elapsed)
start_timestamp: Thu, 13 Feb 2020 00:09:30 UTC
end_timestamp: Thu, 13 Feb 2020 00:09:44 UTC
result:
  output: null
+-----------------------------+-------------------------+-------+-----------------+-------------------------------+
| id                          | status                  | task  | action          | start_timestamp               |
+-----------------------------+-------------------------+-------+-----------------+-------------------------------+
| + 5e4493ba0cdfc0003a644e0d  | succeeded (14s elapsed) | start | bug.pause-child | Thu, 13 Feb 2020 00:09:30 UTC |
|    5e4493bb0cdfc0003a644e10 | succeeded (13s elapsed) | wait  | core.ask        | Thu, 13 Feb 2020 00:09:31 UTC |
+-----------------------------+-------------------------+-------+-----------------+-------------------------------+

As you can see, the workflow succeeded. This is the desired behavior
5. Now we will run a script which spam replies to inquiries, as to exhibit the race condition described above (the behavior shown in the second table above). The script is in the bin directory of the bug pack. Run it in the background (note that this will attempt to respond to all inquiries, so do not run this in a stackstorm environment where you have inquiries you want paused.)

root@e2c8427e5731:/opt/stackstorm/packs.dev/bug/bin# ./run.sh
./run.sh: line 3: ./autoresponder.py: No such file or directory
/opt/stackstorm/st2/local/lib/python2.7/site-packages/cryptography/hazmat/primitives/constant_time.py:26: CryptographyDeprecationWarning: Support for your Python version is deprecated. The next version of cryptography will remove support. Please upgrade to a 2.7.x release that supports hmac.compare_digest as soon as possible.
  utils.PersistentlyDeprecated2018,

This will hang, waiting for inquiries it can respond to.
6. In a new window, run the repro workflow again. The script should instantly respond to the new inquiry, and the repro workflow will be in a paused state, as opposed to succeeded:

root@e2c8427e5731:/# st2 run bug.pause-parent
..
id: 5e4496b00cdfc002b668966c
action.ref: bug.pause-parent
parameters: None
status: paused
start_timestamp: Thu, 13 Feb 2020 00:22:08 UTC
end_timestamp:
result:
  output: null
+-----------------------------+------------------------+-------+-----------------+-------------------------------+
| id                          | status                 | task  | action          | start_timestamp               |
+-----------------------------+------------------------+-------+-----------------+-------------------------------+
| + 5e4496b00cdfc0003a644e13  | paused                 | start | bug.pause-child | Thu, 13 Feb 2020 00:22:08 UTC |
|    5e4496b10cdfc0003a644e16 | succeeded (0s elapsed) | wait  | core.ask        | Thu, 13 Feb 2020 00:22:09 UTC |
+-----------------------------+------------------------+-------+-----------------+-------------------------------+

Expected Results

The workflow should always succeed, no matter the order in which the inquiry receives a response.

Actual Results

The workflow gets "stuck" in a paused state. I recognize that this appears to be a contrived example but as the complexity of the workflows/nesting grows, this issue becomes more and more prevalent. We see behavior like this nearly daily in some of our production workflows. We have built hacky workarounds to deal with this behavior but I believe it needs to be root caused. This is a minimal repro but I hope its illustrative.

Please let me know if there are any issues with the workflows/scripts, or if any further clarification is needed.