{"action":"created","issue":{"url":"https://api.github.com/repos/StackStorm/st2/issues/4135","repository_url":"https://api.github.com/repos/StackStorm/st2","labels_url":"https://api.github.com/repos/StackStorm/st2/issues/4135/labels{/name}","comments_url":"https://api.github.com/repos/StackStorm/st2/issues/4135/comments","events_url":"https://api.github.com/repos/StackStorm/st2/issues/4135/events","html_url":"https://github.com/StackStorm/st2/issues/4135","id":325086500,"number":4135,"title":"Inquiries should not be responded when parent workflow is still in pausing state","user":{"login":"shusugmt","id":463529,"avatar_url":"https://avatars1.githubusercontent.com/u/463529?v=4","gravatar_id":"","url":"https://api.github.com/users/shusugmt","html_url":"https://github.com/shusugmt","followers_url":"https://api.github.com/users/shusugmt/followers","following_url":"https://api.github.com/users/shusugmt/following{/other_user}","gists_url":"https://api.github.com/users/shusugmt/gists{/gist_id}","starred_url":"https://api.github.com/users/shusugmt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shusugmt/subscriptions","organizations_url":"https://api.github.com/users/shusugmt/orgs","repos_url":"https://api.github.com/users/shusugmt/repos","events_url":"https://api.github.com/users/shusugmt/events{/privacy}","received_events_url":"https://api.github.com/users/shusugmt/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2018-05-21T23:02:01Z","updated_at":"2018-05-22T04:56:37Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"##### ISSUE TYPE\r\n - Bug Report\r\n\r\n##### STACKSTORM VERSION\r\n```\r\nst2 2.7.2, on Python 2.7\r\n```\r\n\r\n##### OS / ENVIRONMENT / INSTALL METHOD\r\n- st2-docker\r\n\r\n##### SUMMARY\r\n\r\nI'm facing the issue that in the mistral workflow there is `core.ask` action, and when I respond that with `st2 inquiry respond` *too fast*, the parent workflow state is sometimes still in pausing state (that means it is still transitioning from running to pause), and it fails to resume the parent workflow saying `ERROR: 500 Server Error: Internal Server Error` but the inquiry itself is already in success state and you can't respond it again to resume the parent workflow.\r\n\r\nThe workaround is, wait 10 sec before you respond. Also if you face the above error, you can just `st2 execution resume` to resume the parent workflow, but this apparently is not the desired situation.\r\n\r\nRelevant code: https://github.com/StackStorm/st2/blob/master/st2api/st2api/controllers/exp/inquiries.py#L174\r\nhttps://github.com/StackStorm/st2/blob/master/st2common/st2common/services/action.py#L320\r\n\r\nHere's the log: you can see that LiveAction id `5b02dcfc069c4301d1f654ca` was in pausing state when the inquiry respond was trying to resume it.\r\n\r\n```2018-05-21 14:53:31,108 139685573276848 INFO logging [-] 128c4d50-cf1d-433a-bd07-3c26cdfa5b2a - PUT /exp/inquiries/5b02dd2e069c4301d1f654ea with query={} (remote_addr='127.0.0.1',method='PUT',request_id='128c4d50-cf1d-433a-bd07-3c26cdfa5b2a',query={},path='/exp/inquiries/5b02dd2e069c4301d1f654ea')\r\n2018-05-21 14:53:31,110 139685573276848 AUDIT auth [-] Token with id \"5b02cee5069c4301cdba1881\" is validated.\r\n2018-05-21 14:53:31,189 139685573276848 INFO loader [-] Reusing runner module \"/opt/stackstorm/runners/inquirer_runner/inquirer_runner/inquirer_runner.py\" from cache.\r\n2018-05-21 14:53:31,198 139685573276848 INFO loader [-] Reusing callback module \"/opt/stackstorm/runners/mistral_v2/callback/mistral_v2.py\" from cache.\r\n2018-05-21 14:53:31,198 139685573276848 INFO mistral_v2 [-] Sending callback to http://0.0.0.0:8989/v2/action_executions/ac37214c-2c2a-489b-82f4-4de74e5665d6 with data {'output': '{\"users\": [], \"roles\": [], \"route\": \"\", \"ttl\": 1440, \"response\": {\"continue\": true}, \"schema\": {\"type\": \"object\", \"properties\": {\"continue\": {\"required\": true, \"type\": \"boolean\", \"description\": \"Would you like to continue the workflow?\"}}, \"title\": \"response_data\"}}', 'state': 'SUCCESS'}.\r\n2018-05-21 14:53:31,309 139685573276848 ERROR router [-] Failed to call controller function \"put\" for operation \"st2api.controllers.exp.inquiries:inquiries_controller.put\": Unable to resume liveaction \"5b02dcfc069c4301d1f654ca\" because it is not in a paused state.\r\nTraceback (most recent call last):\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/router.py\", line 470, in __call__\r\n    resp = func(**kw)\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2api/controllers/exp/inquiries.py\", line 176, in put\r\n    requester_user\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/services/action.py\", line 323, in request_resume\r\n    % liveaction.id\r\nUnexpectedActionExecutionStatusError: Unable to resume liveaction \"5b02dcfc069c4301d1f654ca\" because it is not in a paused state.\r\n2018-05-21 14:53:31,309 139685573276848 ERROR error_handling [-] API call failed: Unable to resume liveaction \"5b02dcfc069c4301d1f654ca\" because it is not in a paused state.\r\nTraceback (most recent call last):\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/middleware/error_handling.py\", line 47, in __call__\r\n    return self.app(environ, start_response)\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/middleware/streaming.py\", line 48, in __call__\r\n    return self.app(environ, start_response)\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/router.py\", line 519, in as_wsgi\r\n    resp = self(req)\r\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/router.py\", line 474, in __call__\r\n    raise e\r\nUnexpectedActionExecutionStatusError: Unable to resume liveaction \"5b02dcfc069c4301d1f654ca\" because it is not in a paused state. (_exception_data={},_exception_class='UnexpectedActionExecutionStatusError',_exception_message='Unable to resume liveaction \"5b02dcfc069c4301d1f654ca\" because it is not in a paused state.')\r\n2018-05-21 14:53:31,310 139685573276848 INFO logging [-] 128c4d50-cf1d-433a-bd07-3c26cdfa5b2a - 500 46 202.513ms (content_length=46,request_id='128c4d50-cf1d-433a-bd07-3c26cdfa5b2a',runtime=202.513,remote_addr='127.0.0.1',status=500,method='PUT',path='/exp/inquiries/5b02dd2e069c4301d1f654ea')\r\n2018-05-21 14:53:31,407 139685573276848 INFO logging [-] 52742bd7-8e82-4519-9f69-8e9756d9e519 - PUT /v1/executions/5b02dcfc069c4301d1f654ce with query={} (remote_addr='127.0.0.1',method='PUT',request_id='52742bd7-8e82-4519-9f69-8e9756d9e519',query={},path='/v1/executions/5b02dcfc069c4301d1f654ce')\r\n2018-05-21 14:53:31,410 139685573276848 AUDIT auth [-] Token with id \"5b02dcfd069c43014e79ecf4\" is validated.\r\n2018-05-21 14:53:31,457 139685573276848 INFO logging [-] 52742bd7-8e82-4519-9f69-8e9756d9e519 - 200 8779 49.281ms (content_length=8779,request_id='52742bd7-8e82-4519-9f69-8e9756d9e519',runtime=49.281,remote_addr='127.0.0.1',status=200,method='PUT',path='/v1/executions/5b02dcfc069c4301d1f654ce')\r\n2018-05-21 14:53:31,489 139685573276848 INFO logging [-] 59ea2c74-7b6d-43a1-aad0-98ed27190391 - PUT /v1/executions/5b02dcfc069c4301d1f654cb with query={} (remote_addr='127.0.0.1',method='PUT',request_id='59ea2c74-7b6d-43a1-aad0-98ed27190391',query={},path='/v1/executions/5b02dcfc069c4301d1f654cb')\r\n2018-05-21 14:53:31,491 139685573276848 AUDIT auth [-] Token with id \"5b02dcfc069c430140a1b0e4\" is validated.\r\n2018-05-21 14:53:31,577 139685573276848 AUDIT action [-] The status of action execution is changed from pausing to paused. <LiveAction.id=5b02dcfc069c4301d1f654ca, ActionExecution.id=5b02dcfc069c4301d1f654cb> ...\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/StackStorm/st2/issues/comments/390862726","html_url":"https://github.com/StackStorm/st2/issues/4135#issuecomment-390862726","issue_url":"https://api.github.com/repos/StackStorm/st2/issues/4135","id":390862726,"user":{"login":"shusugmt","id":463529,"avatar_url":"https://avatars1.githubusercontent.com/u/463529?v=4","gravatar_id":"","url":"https://api.github.com/users/shusugmt","html_url":"https://github.com/shusugmt","followers_url":"https://api.github.com/users/shusugmt/followers","following_url":"https://api.github.com/users/shusugmt/following{/other_user}","gists_url":"https://api.github.com/users/shusugmt/gists{/gist_id}","starred_url":"https://api.github.com/users/shusugmt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shusugmt/subscriptions","organizations_url":"https://api.github.com/users/shusugmt/orgs","repos_url":"https://api.github.com/users/shusugmt/repos","events_url":"https://api.github.com/users/shusugmt/events{/privacy}","received_events_url":"https://api.github.com/users/shusugmt/received_events","type":"User","site_admin":false},"created_at":"2018-05-22T04:56:37Z","updated_at":"2018-05-22T04:56:37Z","author_association":"CONTRIBUTOR","body":"@kaishuu0123 This won't work since `liveaction_db` is not accessible where the line this check logic should be brought into. I'm looking at here before https://github.com/StackStorm/st2/blob/master/st2api/st2api/controllers/exp/inquiries.py#L135"}}
{"actor":{"display_login":"shusugmt"}}