mistral speed between tasks

StackStorm / st2

StackStorm (aka "IFTTT for Ops") is event-driven automation for auto-remediation, incident responses, troubleshooting, deployments, and more for DevOps and SREs. Includes rules engine, workflow, 160 integration packs with 6000+ actions (see https://exchange.stackstorm.org) and ChatOps. Installer at https://docs.stackstorm.com/install/index.html

Apache License 2.0

6.07k stars 749 forks source link

Started: Tue, 08 Mar 2016 17:45:56 UTC Finished: Tue, 08 Mar 2016 17:45:58 UTC Started: Tue, 08 Mar 2016 17:46:08 UTC Finished: Tue, 08 Mar 2016 17:46:08 UTC Tue, 08 Mar 2016 17:46:18 UTC Finished: Tue, 08 Mar 2016 17:46:19 UTC

2016-03-08 17:57:24,255 61013040 AUDIT log [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=56df12838e326f5b09d5d023, ActionExecution.id=56df12848e326f5b09d5d024> (liveaction_db={'status': 'scheduled', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'runner_info': {}, 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'notify': None, 'result': {}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': u'e_int.mkhostlist', 'id': '56df12838e326f5b09d5d023', 'end_timestamp': None},action_execution_db={'status': 'scheduled', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parent': u'56df127c8e326f5b09d5d022', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'trigger_type': {}, 'runner': {u'runner_module': u'st2actions.runners.localrunner', u'description': u'A runner to execute local actions as a fixed user.', u'enabled': True, u'runner_parameters': {u'kwarg_op': {u'default': u'--', u'type': u'string', u'description': u'Operator to use in front of keyword args i.e. "--" or "-".'}, u'sudo': {u'default': False, u'type': u'boolean', u'description': u'The command will be executed with sudo.'}, u'cwd': {u'type': u'string', u'description': u'Working directory where the script will be executed in'}, u'timeout': {u'default': 60, u'type': u'integer', u'description': u"Action timeout in seconds. Action will get killed if it doesn't finish in timeout seconds."}, u'env': {u'type': u'object', u'description': u'Environment variables which will be available to the script(e.g. key1=val1,key2=val2)'}}, u'id': u'566748558e326f19361c7aa0', u'name': u'local-shell-script'}, 'rule': {}, 'children': [], 'trigger_instance': {}, 'trigger': {}, 'result': {}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': {u'name': u'mkhostlist', u'parameters': {u'debug': {u'default': False, u'required': False, u'type': u'boolean'}, u'hostlist': {u'required': True, u'type': u'string', u'description': u'A comma delimited string of a list of hosts to place into inventory'}, u'short': {u'default': False, u'required': False, u'type': u'boolean', u'description': u'If true, shorten fully qualified domain names to their hostnames'}, u'sudo': {u'default': False, u'type': u'boolean', u'immutable': True}, u'out': {u'default': u'array', u'type': u'string', u'description': u'array will produce array, string will produce flat string of all hosts (comma delimited)'}}, u'tags': [], u'description': u'Make a json hostlist', u'enabled': True, u'entry_point': u'mkhostlist.pl', u'notify': {}, u'uid': u'action:e_int:mkhostlist', u'pack': u'e_int', u'ref': u'e_int.mkhostlist', u'id': u'569903c48e326f3067f4d08b', u'runner_type': u'local-shell-script'}, 'liveaction': {'action': u'e_int.mkhostlist', 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'runner_info': {}, 'id': '56df12838e326f5b09d5d023', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}}, 'id': '56df12848e326f5b09d5d024', 'end_timestamp': None}) 2016-03-08 17:57:24,336 61013040 INFO log [-] The status of action execution is changed from requested to scheduled. <LiveAction.id=56df12838e326f5b09d5d023, ActionExecution.id=56df12848e326f5b09d5d024> 2016-03-08 17:57:24,425 63453616 AUDIT log [-] Launching action execution. (liveaction_db={'status': 'running', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'runner_info': {'hostname': 'st2.stack.qadev.corp', 'pid': 23043}, 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'notify': None, 'result': {}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': u'e_int.mkhostlist', 'id': '56df12838e326f5b09d5d023', 'end_timestamp': None},action_execution_db={'status': 'running', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parent': u'56df127c8e326f5b09d5d022', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'trigger_type': {}, 'runner': {u'runner_module': u'st2actions.runners.localrunner', u'description': u'A runner to execute local actions as a fixed user.', u'enabled': True, u'runner_parameters': {u'kwarg_op': {u'default': u'--', u'type': u'string', u'description': u'Operator to use in front of keyword args i.e. "--" or "-".'}, u'sudo': {u'default': False, u'type': u'boolean', u'description': u'The command will be executed with sudo.'}, u'cwd': {u'type': u'string', u'description': u'Working directory where the script will be executed in'}, u'timeout': {u'default': 60, u'type': u'integer', u'description': u"Action timeout in seconds. Action will get killed if it doesn't finish in timeout seconds."}, u'env': {u'type': u'object', u'description': u'Environment variables which will be available to the script(e.g. key1=val1,key2=val2)'}}, u'id': u'566748558e326f19361c7aa0', u'name': u'local-shell-script'}, 'rule': {}, 'children': [], 'trigger_instance': {}, 'trigger': {}, 'result': {}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': {u'name': u'mkhostlist', u'parameters': {u'debug': {u'default': False, u'required': False, u'type': u'boolean'}, u'hostlist': {u'required': True, u'type': u'string', u'description': u'A comma delimited string of a list of hosts to place into inventory'}, u'short': {u'default': False, u'required': False, u'type': u'boolean', u'description': u'If true, shorten fully qualified domain names to their hostnames'}, u'sudo': {u'default': False, u'type': u'boolean', u'immutable': True}, u'out': {u'default': u'array', u'type': u'string', u'description': u'array will produce array, string will produce flat string of all hosts (comma delimited)'}}, u'tags': [], u'description': u'Make a json hostlist', u'enabled': True, u'entry_point': u'mkhostlist.pl', u'notify': {}, u'uid': u'action:e_int:mkhostlist', u'pack': u'e_int', u'ref': u'e_int.mkhostlist', u'id': u'569903c48e326f3067f4d08b', u'runner_type': u'local-shell-script'}, 'liveaction': {'action': u'e_int.mkhostlist', 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'runner_info': {'hostname': 'st2.stack.qadev.corp', 'pid': 23043}, 'id': '56df12838e326f5b09d5d023', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}}, 'id': '56df12848e326f5b09d5d024', 'end_timestamp': None}) ^^^^^^^^ (2) action execution launched 2016-03-08 17:57:24,482 63453616 INFO log [-] Dispatched {~}action_execution: 56df12848e326f5b09d5d024 / {~}live_action: 56df12838e326f5b09d5d023 with "running" status. 2016-03-08 17:57:24,491 63453616 INFO log [-] Dispatching Action to a runner (liveaction_db={'status': 'running', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'runner_info': {'hostname': 'st2.stack.qadev.corp', 'pid': 23043}, 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'notify': None, 'result': {}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': u'e_int.mkhostlist', 'id': '56df12838e326f5b09d5d023', 'end_timestamp': None},runnertype_db={'runner_module': u'st2actions.runners.localrunner', 'description': u'A runner to execute local actions as a fixed user.', 'enabled': True, 'query_module': None, 'runner_parameters': {u'kwarg_op': {u'default': u'--', u'type': u'string', u'description': u'Operator to use in front of keyword args i.e. "--" or "-".'}, u'sudo': {u'default': False, u'type': u'boolean', u'description': u'The command will be executed with sudo.'}, u'cwd': {u'type': u'string', u'description': u'Working directory where the script will be executed in'}, u'timeout': {u'default': 60, u'type': u'integer', u'description': u"Action timeout in seconds. Action will get killed if it doesn't finish in timeout seconds."}, u'env': {u'type': u'object', u'description': u'Environment variables which will be available to the script(e.g. key1=val1,key2=val2)'}}, 'id': '566748558e326f19361c7aa0', 'name': u'local-shell-script'}) 2016-03-08 17:57:24,559 63453616 AUDIT log [-] Access granted to "icherkaev" with the token set to expire at "2016-03-09T17:57:24.554835Z". (username=u'icherkaev',token_expiration='2016-03-09T17:57:24.554835Z') 2016-03-08 17:57:24,570 63453616 INFO log [-] Executing action via LocalRunner: f9b86c1f-1b45-425e-bc3e-17e1e3f9177b 2016-03-08 17:57:24,570 63453616 INFO log [-] [Action info] name: mkhostlist, Id: 56df12838e326f5b09d5d023, command: chmod +x /opt/stackstorm/packs/e_int/actions/mkhostlist.pl ; sudo -E -H -u ansible -- bash -c '/opt/stackstorm/packs/e_int/actions/mkhostlist.pl --hostlist=testbld39.stack.qadev.corp --out=array --short', user: ansible, sudo: False 2016-03-08 17:57:24,815 63453616 INFO log [-] Sending callback to http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402 with data {'output': '{"failed": false, "stderr": "", "return_code": 0, "succeeded": true, "stdout": {"hostlist": ["testbld39"], "result": "success"}}', 'state': 'SUCCESS'}. ^^^^^^^^ (3) action execution completed and reported back to mistral 2016-03-08 17:57:24,822 63453616 INFO connectionpool [-] Starting new HTTP connection (1): 127.0.0.1 2016-03-08 17:57:34,757 63453616 AUDIT log [-] Liveaction completed (liveaction_db={'status': 'succeeded', 'start_timestamp': '2016-03-08 17:57:23.958859+00:00', 'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, 'runner_info': {u'hostname': u'st2.stack.qadev.corp', u'pid': 23043}, 'callback': {u'url': u'http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'source': u'mistral'}, 'notify': None, 'result': {'succeeded': True, 'failed': False, 'return_code': 0, 'stderr': '', 'stdout': {'hostlist': ['testbld39'], 'result': 'success'}}, 'context': {u'user': u'icherkaev', u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'mistral': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}}, 'action': u'e_int.mkhostlist', 'id': '56df12838e326f5b09d5d023', 'end_timestamp': '2016-03-08 17:57:24.737611+00:00'}) ^^^^^^^^ (9) finally it is considered finished after 10 seconds?

2016-03-08 17:57:03,912 67554032 INFO wf_trace [-] Execution of workflow 'epsilon.devqa.decom_vm' [RUNNING -> SUCCESS] (execution_id=32615029-23e8-4b23-b2af-91c9d151119d) 2016-03-08 17:57:03,955 57747728 INFO execution [-] Fetch execution [id=32615029-23e8-4b23-b2af-91c9d151119d] 2016-03-08 17:57:03,989 57747728 INFO task [-] Fetch tasks. 2016-03-08 17:57:17,167 57747728 INFO workflow [-] Fetch workflows. marker=None, limit=None, sort_keys=[u'created_at'], sort_dirs=[u'asc'], fields=[] 2016-03-08 17:57:17,169 57747728 WARNING utils [-] Id not in sort_keys; is sort_keys unique? 2016-03-08 17:57:17,484 57747728 INFO workflow [-] Fetch workflow [identifier=epsilon.devqa.decom_vm] 2016-03-08 17:57:17,514 57747728 INFO execution [-] Create execution [execution=Execution [id='Unset', workflow_name='epsilon.devqa.decom_vm', description='', params='{u'env': {u'st2_liveaction_id': u'56df127c8e326f5b09d5d021', u'st2_execution_id': u'56df127c8e326f5b09d5d022', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'f41b6911a8f943c8a2c3adca2f0b82bf', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}', task_execution_id='Unset', state='Unset', state_info='Unset', input='{u'rhn_password': u'****************', u'project': u'poc', u'dns_skip': True, u'rhn_user': u'****************', u'http_proxy': u'http://dc1udtlhkvm01.epsilon.com:3128', u'openstack_skip': True, u'hostlist': u'testbld39.stack.qadev.corp', u'ansible_dir': u'/etc/ansible', u'rhn_host': u'pc1ustsxrhs05.res.prod.global', u'vas_skip': True, u'rhn_skip': False}', output='Unset', created_at='Unset', updated_at='Unset']] 2016-03-08 17:57:17,532 68205456 INFO rpc [-] Received RPC request 'start_workflow'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, workflow_name=epsilon.devqa.decom_vm, workflow_input={u'rhn_password': u'****************', u'project': u'poc', u'dns_skip': True, u'rhn_user': u'****************', u'http_proxy': u'http://dc1udtlhkvm01.epsilon.com:3128', u'openstack_skip': True, u'hostlist': u'testbld39.stack.qadev.corp', u'ansible_dir': u'/etc/ansible', u'rhn_host': u'pc1ustsxrhs05.res.prod.global', u'vas_skip': True, u'rhn_skip': False}, description=, params={u'env': {u'st2_liveaction_id': u'56df127c8e326f5b09d5d021', u'st2_execution_id': u'56df127c8e326f5b09d5d022', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'f41b6911a8f943c8a2c3adca2f0b82bf', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}] 2016-03-08 17:57:18,597 68205456 INFO wf_trace [-] Starting workflow: 'epsilon.devqa.decom_vm' (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277) 2016-03-08 17:57:19,698 68205456 INFO wf_trace [-] Execution of workflow 'epsilon.devqa.decom_vm' [IDLE -> RUNNING] (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277) 2016-03-08 17:57:21,730 68205456 INFO wf_trace [-] Task 'prep_hostlist' is RUNNING [action_name = st2.action] (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277 task_id=44e872cd-464d-4354-9e65-5675740f83f6) 2016-03-08 17:57:23,829 63437072 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=9d8956c7-4d15-4a8f-a6d2-c41c87525402, action_class=st2mistral.actions.stackstorm.St2Action, attributes={}, params={u'ref': u'e_int.mkhostlist', u'st2_context': {u'auth_token': u'f41b6911a8f943c8a2c3adca2f0b82bf', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}, u'action_context': {u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}, u'parameters': {u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}}] ^^^^^^^^ (1) request to run the first action of the workflow 2016-03-08 17:57:23,831 63437072 INFO stackstorm [-] Running St2Action [action_context={u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}, ref=e_int.mkhostlist, parameters={u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}] 2016-03-08 17:57:23,832 63437072 INFO stackstorm [-] Sending HTTP request for St2Action [action_context={u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}, ref=e_int.mkhostlist, parameters={u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}] 2016-03-08 17:57:23,837 63437072 INFO connectionpool [-] Starting new HTTPS connection (1): st2.stack.qadev.corp 2016-03-08 17:57:24,224 63437072 INFO stackstorm [-] Received HTTP response for St2Action [action_context={u'action_execution_id': u'9d8956c7-4d15-4a8f-a6d2-c41c87525402', u'task_id': u'44e872cd-464d-4354-9e65-5675740f83f6', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402'}, ref=e_int.mkhostlist, parameters={u'hostlist': u'testbld39.stack.qadev.corp', u'short': True}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}]:201{"status": "requested", "start_timestamp": "2016-03-08T17:57:23.958859Z", "parent": "56df127c8e326f5b09d5d022", "parameters": {"hostlist": "testbld39.stack.qadev.corp", "short": true}, "runner": {"runner_module": "st2actions.runners.localrunner", "description": "A runner to execute local actions as a fixed user.", "enabled": true, "runner_parameters": {"kwarg_op": {"default": "--", "type": "string", "description": "Operator to use in front of keyword args i.e. \"--\" or \"-\"."}, "sudo": {"default": false, "type": "boolean", "description": "The command will be executed with sudo."}, "cwd": {"type": "string", "description": "Working directory where the script will be executed in"}, "timeout": {"default": 60, "type": "integer", "description": "Action timeout in seconds. Action will get killed if it doesn't finish in timeout seconds."}, "env": {"type": "object", "description": "Environment variables which will be available to the script(e.g. key1=val1,key2=val2)"}}, "id": "566748558e326f19361c7aa0", "name": "local-shell-script"}, "context": {"user": "icherkaev", "parent": {"trace_context": {"id_": "56df12408e326f5b09d5d018"}, "re-run": {"ref": "56df12408e326f5b09d5d017"}, "execution_id": "56df127c8e326f5b09d5d022", "user": "icherkaev"}, "mistral": {"action_execution_id": "9d8956c7-4d15-4a8f-a6d2-c41c87525402", "task_id": "44e872cd-464d-4354-9e65-5675740f83f6", "workflow_name": "epsilon.devqa.decom_vm", "workflow_execution_id": "74a81f3c-bf46-47fd-902b-fc3b715d4277", "task_tags": null, "task_name": "prep_hostlist", "callback_url": "/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402"}}, "action": {"name": "mkhostlist", "runner_type": "local-shell-script", "tags": [], "enabled": true, "pack": "e_int", "entry_point": "mkhostlist.pl", "notify": {}, "uid": "action:e_int:mkhostlist", "parameters": {"debug": {"default": false, "required": false, "type": "boolean"}, "hostlist": {"required": true, "type": "string", "description": "A comma delimited string of a list of hosts to place into inventory"}, "short": {"default": false, "required": false, "type": "boolean", "description": "If true, shorten fully qualified domain names to their hostnames"}, "sudo": {"default": false, "type": "boolean", "immutable": true}, "out": {"default": "array", "type": "string", "description": "array will produce array, string will produce flat string of all hosts (comma delimited)"}}, "ref": "e_int.mkhostlist", "id": "569903c48e326f3067f4d08b", "description": "Make a json hostlist"}, "liveaction": {"action": "e_int.mkhostlist", "callback": {"url": "http://127.0.0.1:8989/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402", "source": "mistral"}, "runner_info": {}, "id": "56df12838e326f5b09d5d023", "parameters": {"hostlist": "testbld39.stack.qadev.corp", "short": true}}, "id": "56df12848e326f5b09d5d024"} 2016-03-08 17:57:24,848 57747728 INFO action_execution [-] Update action_execution [id=9d8956c7-4d15-4a8f-a6d2-c41c87525402, action_execution=ActionExecution [id='Unset', workflow_name='Unset', task_name='Unset', task_execution_id='Unset', state='SUCCESS', state_info='Unset', tags='Unset', name='Unset', description='Unset', accepted='Unset', input='Unset', output='{u'succeeded': True, u'failed': False, u'return_code': 0, u'stderr': u'', u'stdout': {u'hostlist': [u'testbld39'], u'result': u'success'}}', created_at='Unset', updated_at='Unset', params='Unset']] ^^^^^^^^ (4) mistral received action's execution status 2016-03-08 17:57:24,872 68203056 INFO rpc [-] Received RPC request 'on_action_complete'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=9d8956c7-4d15-4a8f-a6d2-c41c87525402, result=Result [data={u'succeeded': True, u'failed': False, u'return_code': 0, u'stderr': u'', u'stdout': {u'hostlist': [u'testbld39'], u'result': u'success'}}, error=None]] 2016-03-08 17:57:26,063 68203056 INFO wf_trace [-] Action execution 'st2.action' [RUNNING -> SUCCESS, result = {u'succeeded': True, u'failed': False, u'return_code': 0, u'stderr': u'', u'stdout': {u'hostlist': [...] ^^^^^^^^ (5) 1.1 seconds pause? 2016-03-08 17:57:27,100 68203056 INFO wf_trace [-] Task execution 'prep_hostlist' [RUNNING -> SUCCESS] (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277) ^^^^^^^^ (6) 1 second more? 2016-03-08 17:57:31,445 68203056 INFO wf_trace [-] Task 'rhn_unreg' is RUNNING [action_name = st2.action] (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277 task_id=41eb6835-9a90-47b0-a256-bcb13759bed7) ^^^^^^^^ (7) 4 seconds pause? 'rhn_unreg' is the next action in the workflow 2016-03-08 17:57:33,624 68203056 INFO wf_trace [-] Task 'mk_temp_inv' is RUNNING [action_name = st2.action] (execution_id=74a81f3c-bf46-47fd-902b-fc3b715d4277 task_id=6e30fe58-e992-480b-a40e-404a3c3f2464) ^^^^^^^^ (8) plus 2 seconds here? 'mk_temp_int' is the next action in the workflow parallel to 'rhn_unreg' task 2016-03-08 17:57:34,758 57747728 INFO execution [-] Fetch execution [id=74a81f3c-bf46-47fd-902b-fc3b715d4277] 2016-03-08 17:57:34,808 57747728 INFO task [-] Fetch tasks. 2016-03-08 17:57:34,816 74864272 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=d8eaf728-b862-4367-817d-a6b4eb325cb4, action_class=st2mistral.actions.stackstorm.St2Action, attributes={}, params={u'ref': u'epsilon.rhn_unreg', u'st2_context': {u'auth_token': u'f41b6911a8f943c8a2c3adca2f0b82bf', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}, u'action_context': {u'action_execution_id': u'd8eaf728-b862-4367-817d-a6b4eb325cb4', u'task_id': u'41eb6835-9a90-47b0-a256-bcb13759bed7', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'rhn_unreg', u'callback_url': u'/v2/action_executions/d8eaf728-b862-4367-817d-a6b4eb325cb4'}, u'parameters': {u'rhn_password': u'****************', u'rhn_host': u'pc1ustsxrhs05.res.prod.global', u'domain': u'stack.qadev.corp', u'hostname': u'testbld39', u'rhn_user': u'****************'}}] ^^^^^^^^ (10) execution of the next action is requested 2016-03-08 17:57:34,817 74864272 INFO stackstorm [-] Running St2Action [action_context={u'action_execution_id': u'd8eaf728-b862-4367-817d-a6b4eb325cb4', u'task_id': u'41eb6835-9a90-47b0-a256-bcb13759bed7', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'rhn_unreg', u'callback_url': u'/v2/action_executions/d8eaf728-b862-4367-817d-a6b4eb325cb4'}, ref=epsilon.rhn_unreg, parameters={u'rhn_password': u'****************', u'rhn_host': u'pc1ustsxrhs05.res.prod.global', u'domain': u'stack.qadev.corp', u'hostname': u'testbld39', u'rhn_user': u'****************'}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}] 2016-03-08 17:57:34,818 74864272 INFO stackstorm [-] Sending HTTP request for St2Action [action_context={u'action_execution_id': u'd8eaf728-b862-4367-817d-a6b4eb325cb4', u'task_id': u'41eb6835-9a90-47b0-a256-bcb13759bed7', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'rhn_unreg', u'callback_url': u'/v2/action_executions/d8eaf728-b862-4367-817d-a6b4eb325cb4'}, ref=epsilon.rhn_unreg, parameters={u'rhn_password': u'****************', u'rhn_host': u'pc1ustsxrhs05.res.prod.global', u'domain': u'stack.qadev.corp', u'hostname': u'testbld39', u'rhn_user': u'****************'}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}] 2016-03-08 17:57:34,820 74864272 INFO connectionpool [-] Starting new HTTPS connection (1): st2.stack.qadev.corp 2016-03-08 17:57:35,135 64037904 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=ab7f5e5c-bc79-47f4-a1d4-6c78a8ce6f0e, action_class=st2mistral.actions.stackstorm.St2Action, attributes={}, params={u'ref': u'e_int.mktempinv', u'st2_context': {u'auth_token': u'f41b6911a8f943c8a2c3adca2f0b82bf', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'trace_context': {u'id_': u'56df12408e326f5b09d5d018'}, u're-run': {u'ref': u'56df12408e326f5b09d5d017'}, u'execution_id': u'56df127c8e326f5b09d5d022', u'user': u'icherkaev'}, u'skip_notify_tasks': []}, u'action_context': {u'action_execution_id': u'ab7f5e5c-bc79-47f4-a1d4-6c78a8ce6f0e', u'task_id': u'6e30fe58-e992-480b-a40e-404a3c3f2464', u'workflow_name': u'epsilon.devqa.decom_vm', u'workflow_execution_id': u'74a81f3c-bf46-47fd-902b-fc3b715d4277', u'task_tags': None, u'task_name': u'mk_temp_inv', u'callback_url': u'/v2/action_executions/ab7f5e5c-bc79-47f4-a1d4-6c78a8ce6f0e'}, u'parameters': {u'hostlist': u'testbld39.stack.qadev.corp'}}]

mistral=> select * from executions_v2 where task_execution_id='44e872cd-464d-4354-9e65-5675740f83f6'; -[ RECORD 1 ]---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- created_at | 2016-03-08 17:57:22.738223 updated_at | 2016-03-08 17:57:27.111425 ^^^^^^^^ 3 seconds after actual task completion scope | private project_id | <default-project> type | action_execution id | 9d8956c7-4d15-4a8f-a6d2-c41c87525402 name | st2.action description | workflow_name | epsilon.devqa.decom_vm spec | state | SUCCESS state_info | tags | runtime_context | {"with_items_index": 0} accepted | t input | {"ref": "e_int.mkhostlist", "st2_context": {"auth_token": "f41b6911a8f943c8a2c3adca2f0b82bf", "endpoint": "https://st2.stack.qadev.corp:9101/v1/actionexecutions", "notify": {}, "parent": {"trace_context": {"id_": "56df12408e326f5b09d5d018"}, "re-run": {"ref": "56df12408e326f5b09d5d017"}, "execution_id": "56df127c8e326f5b09d5d022", "user": "icherkaev"}, "skip_notify_tasks": []}, "action_context": {"action_execution_id": "9d8956c7-4d15-4a8f-a6d2-c41c87525402", "task_id": "44e872cd-464d-4354-9e65-5675740f83f6", "workflow_name": "epsilon.devqa.decom_vm", "workflow_execution_id": "74a81f3c-bf46-47fd-902b-fc3b715d4277", "task_tags": null, "task_name": "prep_hostlist", "callback_url": "/v2/action_executions/9d8956c7-4d15-4a8f-a6d2-c41c87525402"}, "parameters": {"hostlist": "testbld39.stack.qadev.corp", "short": true}} output | {"result": {"succeeded": true, "failed": false, "return_code": 0, "stderr": "", "stdout": {"hostlist": ["testbld39"], "result": "success"}}} params | context | action_spec | processed | f in_context | published | task_execution_id | 44e872cd-464d-4354-9e65-5675740f83f6 workflow_execution_id |

2016-03-10 14:54:18,272 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,273 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,273 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,274 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,309 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,309 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,310 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,311 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,322 59829456 DEBUG expressions [-] YAQL expression result: sgao:sotran:egalindo:icherkaev 2016-03-10 14:54:18,322 59829456 DEBUG expressions [-] Inline YAQL expression result: sgao:sotran:egalindo:icherkaev 2016-03-10 14:54:18,331 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls 2016-03-10 14:54:18,337 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2 2016-03-10 14:54:18,403 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,410 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,410 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,411 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,448 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,448 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,450 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,451 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,552 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,583 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,614 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:18,645 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:18,677 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,677 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,677 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,678 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,709 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,710 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:18,710 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:18,710 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:18,743 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:18,743 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:18,744 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:18,745 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:18,745 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:18,746 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:18,746 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:18,747 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:18,747 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:18,748 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:18,748 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:18,781 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:18,781 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:18,781 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:18,782 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:18,783 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:18,783 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:18,784 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:18,785 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:18,785 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:18,786 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:18,786 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:18,821 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,821 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:18,852 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,853 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:18,884 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,915 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:18,948 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,949 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:18,949 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:18,987 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:18,987 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:18,987 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:19,026 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,026 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:19,057 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,058 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:19,140 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,176 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,209 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:19,243 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:19,274 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,275 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:19,275 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:19,276 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:19,308 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,309 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:19,309 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:19,310 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:19,343 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:19,343 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:19,343 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:19,344 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:19,345 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:19,346 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:19,346 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:19,347 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,347 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,348 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,348 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,382 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:19,383 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:19,383 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:19,384 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:19,384 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:19,385 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:19,386 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:19,387 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,387 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,388 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,388 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,420 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,421 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:19,455 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,455 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:19,490 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,522 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,555 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,555 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:19,556 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:19,596 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,596 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:19,597 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:19,636 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,638 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:19,670 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,671 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:19,753 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,788 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:19,820 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:19,852 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:19,885 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,886 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:19,886 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:19,887 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:19,920 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:19,920 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:19,921 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:19,922 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:19,954 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:19,955 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:19,955 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:19,956 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:19,956 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:19,957 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:19,958 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:19,958 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,959 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,959 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:19,960 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:19,995 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:19,995 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:19,996 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:19,997 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:19,997 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:19,998 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:19,998 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:19,999 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,000 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,000 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,001 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,041 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,042 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:20,074 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,075 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:20,106 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,137 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,170 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,170 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:20,170 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:20,208 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,209 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:20,209 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:20,247 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,248 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:20,279 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,279 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:20,359 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,390 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,422 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:20,453 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:20,486 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,486 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:20,487 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:20,487 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:20,519 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,520 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:20,520 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:20,521 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:20,556 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:20,557 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:20,557 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:20,558 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:20,559 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:20,559 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:20,560 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:20,561 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,561 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,562 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,562 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,596 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:20,597 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:20,597 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:20,598 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:20,599 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:20,600 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:20,600 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:20,601 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,601 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,602 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:20,602 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:20,640 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,640 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:20,675 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,675 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:20,710 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,744 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,780 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,780 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:20,780 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:20,824 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:20,825 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:20,825 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:20,867 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,867 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:20,902 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:20,902 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:20,992 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,042 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,080 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:21,113 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:21,147 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,148 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:21,148 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:21,149 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:21,182 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,183 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:21,183 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:21,184 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:21,218 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:21,219 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:21,219 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:21,220 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:21,221 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:21,222 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:21,222 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:21,223 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,223 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,224 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,225 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,258 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:21,259 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:21,259 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:21,260 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:21,261 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:21,262 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:21,262 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:21,263 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,263 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,264 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,265 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,299 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,299 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:21,333 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,333 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:21,367 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,402 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,436 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,437 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:21,437 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:21,479 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,479 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:21,480 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:21,520 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,521 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:21,554 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,555 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:21,640 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,674 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,711 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:21,747 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:21,782 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,782 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:21,783 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:21,784 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:21,819 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:21,819 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:21,819 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:21,820 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:21,854 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:21,855 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:21,856 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:21,857 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:21,857 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:21,858 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:21,859 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:21,860 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,860 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,861 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,861 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,900 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:21,900 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:21,901 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:21,902 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:21,902 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:21,903 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:21,903 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:21,904 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,905 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,905 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:21,906 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:21,939 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,940 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:21,971 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:21,972 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:22,008 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,042 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,076 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,077 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:22,077 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:22,117 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,117 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:22,118 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:22,159 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,160 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:22,193 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,194 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:22,240 59829456 DEBUG direct_workflow [-] Found commands: [Run task [workflow=st2-epsibot.devqa.decom_vm, task=publish_data, waif_flag=False]] 2016-03-10 14:54:22,312 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,345 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,378 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:22,416 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:22,448 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,449 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:22,449 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:22,450 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:22,489 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,490 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:22,490 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:22,491 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:22,524 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:22,525 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:22,525 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:22,526 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:22,527 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:22,527 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:22,528 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:22,529 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:22,529 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:22,530 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:22,531 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:22,566 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:22,567 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:22,567 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:22,568 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:22,568 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:22,569 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:22,570 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:22,571 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:22,571 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:22,572 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:22,572 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:22,606 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,607 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:22,640 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,640 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:22,672 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,712 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,753 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,754 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:22,754 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:22,800 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:22,801 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:22,801 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:22,842 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,843 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:22,876 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:22,877 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:22,973 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,008 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,048 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:23,080 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='epsilon.devqa.decom_vm'] 2016-03-10 14:54:23,112 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:23,112 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:23,113 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:23,114 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:23,147 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:23,147 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.get_group_members.result %>'] 2016-03-10 14:54:23,147 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.get_group_members.result '] 2016-03-10 14:54:23,148 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='publish_data'] 2016-03-10 14:54:23,180 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:23,181 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:23,181 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:23,182 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:23,182 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:23,183 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:23,183 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:23,184 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:23,185 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:23,185 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:23,186 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:23,226 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop'] 2016-03-10 14:54:23,227 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.api_user %>'] 2016-03-10 14:54:23,227 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.api_user '] 2016-03-10 14:54:23,229 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.execution_id %>'] 2016-03-10 14:54:23,229 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.execution_id '] 2016-03-10 14:54:23,230 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% env().get('__actions').get('st2.action').st2_context.parent.source_channel %>'] 2016-03-10 14:54:23,231 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' env().get('__actions').get('st2.action').st2_context.parent.source_channel '] 2016-03-10 14:54:23,232 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:23,232 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:23,233 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='<% not $.chat_user in $.allowed_users.split(':') %>'] 2016-03-10 14:54:23,233 59829456 DEBUG expressions [-] Validating YAQL expression [expression=' not $.chat_user in $.allowed_users.split(':') '] 2016-03-10 14:54:23,270 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,270 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:23,306 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,306 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='wait_for_confirmation'] 2016-03-10 14:54:23,340 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,500 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,533 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:23,534 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:23,534 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:23,575 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='st2.kv.get'] 2016-03-10 14:54:23,575 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_confirmed'] 2016-03-10 14:54:23,575 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='post_not_confirmed'] 2016-03-10 14:54:23,615 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,616 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action'] 2016-03-10 14:54:23,647 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='chatops.post_message'] 2016-03-10 14:54:23,648 59829456 DEBUG expressions [-] Validating inline YAQL expression [expression='granted_action']

For test purposes I created a simple two-action mistral workflow with core.noop actions:

---
version: '2.0'

e_playground.flow_test:
  type: direct
  input:
    - param1
  tasks:
    task1:
      # [341, 132]
      action: core.noop
      on-success:
        - task2
    task2:
      # [342, 272]
      action: core.noop

And the "pause" between the tasks went down to 5 seconds. Of course there still was that long running YAQL expression validation process:

2016-03-10 15:06:18,578 66205968 INFO workflow [-] Fetch workflows. marker=None, limit=None, sort_keys=[u'created_at'], sort_dirs=[u'asc'], fields=[]
2016-03-10 15:06:18,581 66205968 WARNING utils [-] Id not in sort_keys; is sort_keys unique?
2016-03-10 15:06:18,871 66205968 INFO workflow [-] Fetch workflow [identifier=e_playground.flow_test]
2016-03-10 15:06:18,879 66205968 DEBUG api [-] Client-side error: Workflow not found [workflow_identifier=e_playground.flow_test]
2016-03-10 15:06:18,891 66205968 INFO workbook [-] Delete workbook [name=e_playground.flow_test]
2016-03-10 15:06:18,902 66205968 DEBUG api [-] Client-side error: Workbook not found [workbook_name=e_playground.flow_test]
2016-03-10 15:06:18,912 66205968 INFO workflow [-] Create workflow(s) [definition=e_playground.flow_test:
  input:
  - param1
  tasks:
    task1:
      action: st2.action
      input:
        ref: core.noop
      on-success:
      - task2
    task2:
      action: st2.action
      input:
        ref: core.noop
  type: direct
version: '2.0'
]
2016-03-10 15:06:18,997 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:18,997 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,032 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,032 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,066 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,104 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,188 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,189 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,223 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,224 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,271 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,308 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,333 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls
2016-03-10 15:06:19,340 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2
2016-03-10 15:06:19,368 66205968 INFO execution [-] Create execution [execution=Execution [id='Unset', workflow_name='e_playground.flow_test', description='', params='{u'env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}', task_execution_id='Unset', state='Unset', state_info='Unset', input='{u'param1': u'1'}', output='Unset', created_at='Unset', updated_at='Unset']]
2016-03-10 15:06:19,370 66205968 DEBUG amqpdriver [-] CALL msg_id: a36591f17cbd4fe7b17ff0ec0f10ebd0 exchange 'openstack' topic 'mistral_engine'
2016-03-10 15:06:19,376 59925520 DEBUG amqpdriver [-] received message msg_id: a36591f17cbd4fe7b17ff0ec0f10ebd0 reply to reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:19,379 70329200 INFO rpc [-] Received RPC request 'start_workflow'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, workflow_name=e_playground.flow_test, workflow_input={u'param1': u'1'}, description=, params={u'env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,380 70329200 DEBUG __init__ [-] Called method [name=start_workflow, doc='None', params=[args=(<mistral.engine.default_engine.DefaultEngine object at 0x3ff31d0>, u'e_playground.flow_test', {u'param1': u'1'}, u''), kw={u'env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]]
2016-03-10 15:06:19,459 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,459 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,494 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,494 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,527 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,562 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,634 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,635 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,668 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,669 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,705 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,739 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,758 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='56e18d6a8e326f5b09d5d05d', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,759 70329200 DEBUG expressions [-] Inline YAQL expression result: 56e18d6a8e326f5b09d5d05d
2016-03-10 15:06:19,759 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='56e18d6a8e326f5b09d5d05e', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,760 70329200 DEBUG expressions [-] Inline YAQL expression result: 56e18d6a8e326f5b09d5d05e
2016-03-10 15:06:19,760 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='8a0494a2288044ffa11f029499f2c515', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,761 70329200 DEBUG expressions [-] Inline YAQL expression result: 8a0494a2288044ffa11f029499f2c515
2016-03-10 15:06:19,761 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='https://st2.stack.qadev.corp:9101/v1/actionexecutions', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,762 70329200 DEBUG expressions [-] Inline YAQL expression result: https://st2.stack.qadev.corp:9101/v1/actionexecutions
2016-03-10 15:06:19,762 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='icherkaev', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,763 70329200 DEBUG expressions [-] Inline YAQL expression result: icherkaev
2016-03-10 15:06:19,763 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='56e18d6a8e326f5b09d5d05e', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,763 70329200 DEBUG expressions [-] Inline YAQL expression result: 56e18d6a8e326f5b09d5d05e
2016-03-10 15:06:19,764 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='https://st2.stack.qadev.corp:9101/v1', context={'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}]
2016-03-10 15:06:19,764 70329200 DEBUG expressions [-] Inline YAQL expression result: https://st2.stack.qadev.corp:9101/v1
2016-03-10 15:06:19,765 70329200 INFO wf_trace [-] Starting workflow: 'e_playground.flow_test' (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43)
2016-03-10 15:06:19,856 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,856 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,893 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,895 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:19,939 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:19,974 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,049 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,050 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,082 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,082 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,114 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,149 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,162 70329200 INFO wf_trace [-] Execution of workflow 'e_playground.flow_test' [IDLE -> RUNNING] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43)
2016-03-10 15:06:20,228 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,229 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,267 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,268 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,308 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,339 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,410 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,410 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,443 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,444 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,489 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,536 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,626 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,627 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,689 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,689 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,723 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,756 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,829 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,829 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,861 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,861 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:20,894 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,926 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:20,943 70329200 DEBUG task_handler [-] Starting workflow task [workflow=e_playground.flow_test, task_spec=DirectWorkflowTaskSpec {u'name': u'task1', u'on-success': [u'task2'], u'version': '2.0', u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'type': u'direct'}, init_state=RUNNING]
2016-03-10 15:06:20,945 70329200 DEBUG expressions [-] Evaluating inline YAQL expression [expression='core.noop', context={'__tasks': {}, u'param1': u'1', u'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}, u'__execution': {u'input': {u'param1': u'1'}, u'params': {u'env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}, u'id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'spec': {u'input': [u'param1'], u'tasks': {u'task1': {u'name': u'task1', u'on-success': [u'task2'], u'version': u'2.0', u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'type': u'direct'}, u'task2': {u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'version': u'2.0', u'type': u'direct', u'name': u'task2'}}, u'type': u'direct', u'name': u'e_playground.flow_test', u'version': u'2.0'}}}]
2016-03-10 15:06:20,945 70329200 DEBUG expressions [-] Inline YAQL expression result: core.noop
2016-03-10 15:06:20,953 70329200 INFO wf_trace [-] Task 'task1' is RUNNING [action_name = st2.action] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43 task_id=42fdcd7e-72da-468f-a35d-b87c05f2b17f)
2016-03-10 15:06:21,016 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,017 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:21,050 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,051 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:21,083 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,116 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,190 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,191 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:21,224 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,224 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:21,256 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,287 70329200 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:21,332 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls
2016-03-10 15:06:21,345 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2
2016-03-10 15:06:21,363 70329200 DEBUG amqpdriver [-] sending reply msg_id: a36591f17cbd4fe7b17ff0ec0f10ebd0 reply queue: reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:21,364 68368176 DEBUG scheduler [-] Processing next delayed call: DelayedCall {'factory_method_path': None, 'serializers': None, 'method_arguments': {u'action_ex_id': u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', u'target': None}, 'execution_time': datetime.datetime(2016, 3, 10, 15, 6, 21, 320003), 'created_at': '2016-03-10 15:06:21.322422', 'processing': True, 'updated_at': None, 'auth_context': {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, 'target_method_name': u'mistral.engine.action_handler.run_existing_action', 'id': u'41f78631-9d2e-468a-8e8b-eab2cb51493f'}
2016-03-10 15:06:21,379 68368176 DEBUG amqpdriver [-] CAST unique_id: 5b69a27463a24ec4a94fa4d7f161eb14 exchange 'openstack' topic 'mistral_executor'
2016-03-10 15:06:21,386 70331440 DEBUG amqpdriver [-] received reply msg_id: a36591f17cbd4fe7b17ff0ec0f10ebd0
2016-03-10 15:06:21,392 59826256 DEBUG amqpdriver [-] received message msg_id: None reply to None
2016-03-10 15:06:21,397 75692784 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=e37c98f1-157d-4c69-b659-e6ba2a623fb2, action_class=st2mistral.actions.stackstorm.St2Action, attributes={}, params={u'ref': u'core.noop', u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}, u'action_context': {u'action_execution_id': u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', u'task_id': u'42fdcd7e-72da-468f-a35d-b87c05f2b17f', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2'}, u'parameters': None}]
2016-03-10 15:06:21,398 75692784 INFO stackstorm [-] Running St2Action [action_context={u'action_execution_id': u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', u'task_id': u'42fdcd7e-72da-468f-a35d-b87c05f2b17f', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]
2016-03-10 15:06:21,399 75692784 INFO stackstorm [-] Sending HTTP request for St2Action [action_context={u'action_execution_id': u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', u'task_id': u'42fdcd7e-72da-468f-a35d-b87c05f2b17f', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]
2016-03-10 15:06:21,402 75692784 INFO connectionpool [-] Starting new HTTPS connection (1): st2.stack.qadev.corp
2016-03-10 15:06:21,699 75692784 DEBUG connectionpool [-] "POST /v1/actionexecutions HTTP/1.1" 201 1359
2016-03-10 15:06:21,702 75692784 INFO stackstorm [-] Received HTTP response for St2Action [action_context={u'action_execution_id': u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', u'task_id': u'42fdcd7e-72da-468f-a35d-b87c05f2b17f', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]:
201
{"status": "requested", "start_timestamp": "2016-03-10T15:06:21.530126Z", "parent": "56e18d6a8e326f5b09d5d05e", "runner": {"runner_module": "st2actions.runners.nooprunner", "description": "A runner that returns a static response regardless of input parameters", "enabled": true, "runner_parameters": {}, "id": "566748568e326f19361c7ab0", "name": "noop"}, "context": {"user": "icherkaev", "parent": {"user": "icherkaev", "execution_id": "56e18d6a8e326f5b09d5d05e"}, "mistral": {"action_execution_id": "e37c98f1-157d-4c69-b659-e6ba2a623fb2", "task_id": "42fdcd7e-72da-468f-a35d-b87c05f2b17f", "workflow_name": "e_playground.flow_test", "workflow_execution_id": "033d0dee-00a4-4245-b45a-066597c9eb43", "task_tags": null, "task_name": "task1", "callback_url": "/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2"}}, "action": {"name": "noop", "runner_type": "noop", "tags": [], "enabled": true, "pack": "core", "entry_point": "", "notify": {}, "uid": "action:core:noop", "parameters": {}, "ref": "core.noop", "id": "566748568e326f19361c7ab7", "description": "Action that does nothing"}, "liveaction": {"action": "core.noop", "callback": {"url": "http://127.0.0.1:8989/v2/action_executions/e37c98f1-157d-4c69-b659-e6ba2a623fb2", "source": "mistral"}, "runner_info": {}, "id": "56e18d6d8e326f5b09d5d060", "parameters": {}}, "id": "56e18d6d8e326f5b09d5d061"}
2016-03-10 15:06:22,082 66205968 INFO action_execution [-] Update action_execution [id=e37c98f1-157d-4c69-b659-e6ba2a623fb2, action_execution=ActionExecution [id='Unset', workflow_name='Unset', task_name='Unset', task_execution_id='Unset', state='SUCCESS', state_info='Unset', tags='Unset', name='Unset', description='Unset', accepted='Unset', input='Unset', output='{u'failed': False, u'return_code': 0, u'succeeded': True}', created_at='Unset', updated_at='Unset', params='Unset']]
2016-03-10 15:06:22,084 66205968 DEBUG amqpdriver [-] CALL msg_id: e705af15f18b46fdaf9da864c9aca457 exchange 'openstack' topic 'mistral_engine'
2016-03-10 15:06:22,090 59925520 DEBUG amqpdriver [-] received message msg_id: e705af15f18b46fdaf9da864c9aca457 reply to reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:22,093 59830096 INFO rpc [-] Received RPC request 'on_action_complete'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=e37c98f1-157d-4c69-b659-e6ba2a623fb2, result=Result [data={u'failed': False, u'return_code': 0, u'succeeded': True}, error=None]]
2016-03-10 15:06:22,095 59830096 DEBUG __init__ [-] Called method [name=on_action_complete, doc='None', params=[args=(<mistral.engine.default_engine.DefaultEngine object at 0x3ff31d0>, u'e37c98f1-157d-4c69-b659-e6ba2a623fb2', Result [data={u'failed': False, u'return_code': 0, u'succeeded': True}, error=None]), kw={}]]
2016-03-10 15:06:22,160 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,161 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,194 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,194 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,264 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,265 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,301 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,302 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,333 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,364 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,436 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,436 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,467 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,467 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,499 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,530 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,547 59830096 INFO wf_trace [-] Action execution 'st2.action' [RUNNING -> SUCCESS, result = {u'failed': False, u'return_code': 0, u'succeeded': True}]
2016-03-10 15:06:22,617 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,618 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,652 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,652 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,690 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,725 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,802 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,802 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,836 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,837 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:22,869 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,908 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:22,920 59830096 INFO wf_trace [-] Task execution 'task1' [RUNNING -> SUCCESS] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43)
2016-03-10 15:06:22,935 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2
2016-03-10 15:06:22,956 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls
2016-03-10 15:06:23,024 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,024 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,056 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,056 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,128 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,129 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,160 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,161 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,192 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,223 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,293 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,293 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,325 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,325 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,362 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,393 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,465 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,465 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,496 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,496 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,528 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,559 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,630 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,630 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,662 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,662 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,694 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,725 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,806 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,807 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,847 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,847 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:23,888 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:23,922 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,009 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,010 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,043 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,043 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,076 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,107 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,128 59830096 DEBUG direct_workflow [-] Found commands: [Run task [workflow=e_playground.flow_test, task=task2, waif_flag=False]]
2016-03-10 15:06:24,206 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,207 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,240 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,241 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,279 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,312 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,382 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,382 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,414 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,414 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,446 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,477 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,495 59830096 DEBUG task_handler [-] Starting workflow task [workflow=e_playground.flow_test, task_spec=DirectWorkflowTaskSpec {u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'version': '2.0', u'type': u'direct', u'name': u'task2'}, init_state=RUNNING]
2016-03-10 15:06:24,498 59830096 DEBUG expressions [-] Evaluating inline YAQL expression [expression='core.noop', context={u'task1': TaskResultProxy [task_id = '42fdcd7e-72da-468f-a35d-b87c05f2b17f'], u'__tasks': {u'42fdcd7e-72da-468f-a35d-b87c05f2b17f': u'task1'}, u'param1': u'1', u'__env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}, u'__execution': {u'input': {u'param1': u'1'}, u'params': {u'env': {u'st2_liveaction_id': u'56e18d6a8e326f5b09d5d05d', u'st2_execution_id': u'56e18d6a8e326f5b09d5d05e', u'__actions': {u'st2.action': {u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}}}, u'st2_action_api_url': u'https://st2.stack.qadev.corp:9101/v1'}}, u'id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'spec': {u'input': [u'param1'], u'tasks': {u'task1': {u'name': u'task1', u'on-success': [u'task2'], u'version': u'2.0', u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'type': u'direct'}, u'task2': {u'action': u'st2.action', u'input': {u'ref': u'core.noop'}, u'version': u'2.0', u'type': u'direct', u'name': u'task2'}}, u'type': u'direct', u'name': u'e_playground.flow_test', u'version': u'2.0'}}}]
2016-03-10 15:06:24,498 59830096 DEBUG expressions [-] Inline YAQL expression result: core.noop
2016-03-10 15:06:24,508 59830096 INFO wf_trace [-] Task 'task2' is RUNNING [action_name = st2.action] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43 task_id=61b73275-a771-4a8b-8f10-53a1ad6720db)
2016-03-10 15:06:24,575 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,576 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,617 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,618 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,652 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,695 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,781 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,782 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,819 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,819 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:24,851 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,882 59830096 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:24,926 59830096 DEBUG amqpdriver [-] sending reply msg_id: e705af15f18b46fdaf9da864c9aca457 reply queue: reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:24,933 70331440 DEBUG amqpdriver [-] received reply msg_id: e705af15f18b46fdaf9da864c9aca457
2016-03-10 15:06:24,942 66205968 INFO execution [-] Fetch execution [id=033d0dee-00a4-4245-b45a-066597c9eb43]
2016-03-10 15:06:24,976 66205968 INFO task [-] Fetch tasks.
2016-03-10 15:06:25,032 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:25,033 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:25,068 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:25,069 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:25,113 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:25,148 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:25,931 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2
2016-03-10 15:06:25,949 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls
2016-03-10 15:06:25,964 68368176 DEBUG scheduler [-] Processing next delayed call: DelayedCall {'factory_method_path': None, 'serializers': None, 'method_arguments': {u'action_ex_id': u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', u'target': None}, 'execution_time': datetime.datetime(2016, 3, 10, 15, 6, 24, 907302), 'created_at': '2016-03-10 15:06:24.909186', 'processing': True, 'updated_at': None, 'auth_context': {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, 'target_method_name': u'mistral.engine.action_handler.run_existing_action', 'id': u'8f0b899f-4f6f-452d-8f4f-49b58e346dd7'}
2016-03-10 15:06:25,982 68368176 DEBUG amqpdriver [-] CAST unique_id: f491014b53574bf0b91e19ccf48bad4c exchange 'openstack' topic 'mistral_executor'
2016-03-10 15:06:25,998 59826256 DEBUG amqpdriver [-] received message msg_id: None reply to None
2016-03-10 15:06:26,000 59829616 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=75c0ccfa-a139-4e2f-867a-245dbb0413a2, action_class=st2mistral.actions.stackstorm.St2Action, attributes={}, params={u'ref': u'core.noop', u'st2_context': {u'auth_token': u'8a0494a2288044ffa11f029499f2c515', u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}, u'action_context': {u'action_execution_id': u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', u'task_id': u'61b73275-a771-4a8b-8f10-53a1ad6720db', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task2', u'callback_url': u'/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2'}, u'parameters': None}]
2016-03-10 15:06:26,001 59829616 INFO stackstorm [-] Running St2Action [action_context={u'action_execution_id': u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', u'task_id': u'61b73275-a771-4a8b-8f10-53a1ad6720db', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task2', u'callback_url': u'/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]
2016-03-10 15:06:26,002 59829616 INFO stackstorm [-] Sending HTTP request for St2Action [action_context={u'action_execution_id': u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', u'task_id': u'61b73275-a771-4a8b-8f10-53a1ad6720db', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task2', u'callback_url': u'/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]
2016-03-10 15:06:26,004 59829616 INFO connectionpool [-] Starting new HTTPS connection (1): st2.stack.qadev.corp
2016-03-10 15:06:26,301 59829616 DEBUG connectionpool [-] "POST /v1/actionexecutions HTTP/1.1" 201 1359
2016-03-10 15:06:26,304 59829616 INFO stackstorm [-] Received HTTP response for St2Action [action_context={u'action_execution_id': u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', u'task_id': u'61b73275-a771-4a8b-8f10-53a1ad6720db', u'workflow_name': u'e_playground.flow_test', u'workflow_execution_id': u'033d0dee-00a4-4245-b45a-066597c9eb43', u'task_tags': None, u'task_name': u'task2', u'callback_url': u'/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2'}, ref=core.noop, parameters=None, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {}, u'parent': {u'user': u'icherkaev', u'execution_id': u'56e18d6a8e326f5b09d5d05e'}, u'skip_notify_tasks': []}]:
201
{"status": "requested", "start_timestamp": "2016-03-10T15:06:26.103860Z", "parent": "56e18d6a8e326f5b09d5d05e", "runner": {"runner_module": "st2actions.runners.nooprunner", "description": "A runner that returns a static response regardless of input parameters", "enabled": true, "runner_parameters": {}, "id": "566748568e326f19361c7ab0", "name": "noop"}, "context": {"user": "icherkaev", "parent": {"user": "icherkaev", "execution_id": "56e18d6a8e326f5b09d5d05e"}, "mistral": {"action_execution_id": "75c0ccfa-a139-4e2f-867a-245dbb0413a2", "task_id": "61b73275-a771-4a8b-8f10-53a1ad6720db", "workflow_name": "e_playground.flow_test", "workflow_execution_id": "033d0dee-00a4-4245-b45a-066597c9eb43", "task_tags": null, "task_name": "task2", "callback_url": "/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2"}}, "action": {"name": "noop", "runner_type": "noop", "tags": [], "enabled": true, "pack": "core", "entry_point": "", "notify": {}, "uid": "action:core:noop", "parameters": {}, "ref": "core.noop", "id": "566748568e326f19361c7ab7", "description": "Action that does nothing"}, "liveaction": {"action": "core.noop", "callback": {"url": "http://127.0.0.1:8989/v2/action_executions/75c0ccfa-a139-4e2f-867a-245dbb0413a2", "source": "mistral"}, "runner_info": {}, "id": "56e18d728e326f5b09d5d062", "parameters": {}}, "id": "56e18d728e326f5b09d5d063"}
2016-03-10 15:06:26,694 66205968 INFO action_execution [-] Update action_execution [id=75c0ccfa-a139-4e2f-867a-245dbb0413a2, action_execution=ActionExecution [id='Unset', workflow_name='Unset', task_name='Unset', task_execution_id='Unset', state='SUCCESS', state_info='Unset', tags='Unset', name='Unset', description='Unset', accepted='Unset', input='Unset', output='{u'failed': False, u'return_code': 0, u'succeeded': True}', created_at='Unset', updated_at='Unset', params='Unset']]
2016-03-10 15:06:26,696 66205968 DEBUG amqpdriver [-] CALL msg_id: 409751ae63d646969f9cc9d4b2d962cf exchange 'openstack' topic 'mistral_engine'
2016-03-10 15:06:26,703 59925520 DEBUG amqpdriver [-] received message msg_id: 409751ae63d646969f9cc9d4b2d962cf reply to reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:26,706 59828656 INFO rpc [-] Received RPC request 'on_action_complete'[rpc_ctx=MistralContext {u'project_name': None, u'user_id': None, u'roles': [u''], u'auth_token': None, u'is_trust_scoped': False, u'service_catalog': None, u'project_id': None, u'user_name': None}, action_ex_id=75c0ccfa-a139-4e2f-867a-245dbb0413a2, result=Result [data={u'failed': False, u'return_code': 0, u'succeeded': True}, error=None]]
2016-03-10 15:06:26,706 59828656 DEBUG __init__ [-] Called method [name=on_action_complete, doc='None', params=[args=(<mistral.engine.default_engine.DefaultEngine object at 0x3ff31d0>, u'75c0ccfa-a139-4e2f-867a-245dbb0413a2', Result [data={u'failed': False, u'return_code': 0, u'succeeded': True}, error=None]), kw={}]]
2016-03-10 15:06:26,772 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:26,804 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:26,877 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:26,877 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:26,908 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:26,909 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:26,944 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:26,975 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,050 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,051 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,066 68368656 DEBUG periodic_task [-] Running periodic task MistralPeriodicTasks.process_cron_triggers_v2
2016-03-10 15:06:27,080 68368176 DEBUG periodic_task [-] Running periodic task CallScheduler.run_delayed_calls
2016-03-10 15:06:27,110 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,110 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,144 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,178 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,193 59828656 INFO wf_trace [-] Action execution 'st2.action' [RUNNING -> SUCCESS, result = {u'failed': False, u'return_code': 0, u'succeeded': True}]
2016-03-10 15:06:27,256 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,257 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,289 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,289 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,323 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,355 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,429 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,429 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,469 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,470 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,503 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,534 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,545 59828656 INFO wf_trace [-] Task execution 'task2' [RUNNING -> SUCCESS] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43)
2016-03-10 15:06:27,607 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,641 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,715 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,716 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,747 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,747 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,783 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,817 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,898 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,899 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,933 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:27,934 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:27,968 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,001 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,092 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,093 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,127 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,127 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,158 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,190 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,262 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,263 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,295 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,295 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,329 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,362 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,441 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,442 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,486 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,487 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,523 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,560 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,648 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,649 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,684 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,685 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,718 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,751 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,769 59828656 DEBUG direct_workflow [-] Found commands: []
2016-03-10 15:06:28,808 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,843 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,926 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,927 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:28,962 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:28,963 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:29,001 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,035 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,122 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,124 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:29,162 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,163 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:29,206 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,239 59828656 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,251 59828656 INFO wf_trace [-] Execution of workflow 'e_playground.flow_test' [RUNNING -> SUCCESS] (execution_id=033d0dee-00a4-4245-b45a-066597c9eb43)
2016-03-10 15:06:29,268 59828656 DEBUG amqpdriver [-] sending reply msg_id: 409751ae63d646969f9cc9d4b2d962cf reply queue: reply_31786326565e46a081614d0514944f46
2016-03-10 15:06:29,275 70331440 DEBUG amqpdriver [-] received reply msg_id: 409751ae63d646969f9cc9d4b2d962cf
2016-03-10 15:06:29,285 66205968 INFO execution [-] Fetch execution [id=033d0dee-00a4-4245-b45a-066597c9eb43]
2016-03-10 15:06:29,315 66205968 INFO task [-] Fetch tasks.
2016-03-10 15:06:29,367 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,368 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:29,401 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,402 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='task2']
2016-03-10 15:06:29,464 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']
2016-03-10 15:06:29,502 66205968 DEBUG expressions [-] Validating inline YAQL expression [expression='core.noop']

Is it normal? I believe now that this is the most time consuming operation, and the more complex the workflow is, the longer it takes to go from one task to another. Moreover, it looks like a bug that it validates same expressions over and over before/after the task is executed.

mistral=# select name, created_at, updated_at from executions_v2 where task_execution_id is null order by created_at; name | created_at | updated_at --------------+----------------------------+---------------------------- sandbox.noop | 2016-03-23 18:10:19.966629 | 2016-03-23 18:10:21.459897 task1 | 2016-03-23 18:10:19.990144 | 2016-03-23 18:10:20.584257 task2 | 2016-03-23 18:10:20.585799 | 2016-03-23 18:10:21.442507

mistral=# select name, created_at, updated_at from executions_v2 where task_execution_id is not null; name | created_at | updated_at ------------+----------------------------+---------------------------- st2.action | 2016-03-23 18:10:20.010093 | 2016-03-23 18:10:20.560874 st2.action | 2016-03-23 18:10:20.608526 | 2016-03-23 18:10:21.427766

mistral=> select name, created_at, updated_at from executions_v2 where task_execution_id is null and workflow_execution_id='e03c0408-51a4-45ce-a4d9-82d0dbea29eb' order by created_at; name | created_at | updated_at ----------------------+----------------------------+---------------------------- prep_hostlist | 2016-03-23 19:51:16.263338 | 2016-03-23 19:51:33.115266 prep_hostlist_string | 2016-03-23 19:51:33.118371 | 2016-03-23 19:51:51.357762 mk_temp_inv | 2016-03-23 19:51:51.359637 | 2016-03-23 19:52:09.766448 get_sys_info_before | 2016-03-23 19:52:09.776688 | 2016-03-23 19:53:54.607102 pb_patching | 2016-03-23 19:53:54.612406 | 2016-03-23 19:55:03.683054 pb_post_patching | 2016-03-23 19:55:03.686105 | 2016-03-23 19:55:44.456022 get_sys_info_after | 2016-03-23 19:55:44.462011 | 2016-03-23 19:56:10.057272 show_diff | 2016-03-23 19:56:10.061511 | 2016-03-23 19:56:57.538325 rm_temp_inv | 2016-03-23 19:56:57.540871 | 2016-03-23 19:57:14.850695 (9 rows)

2016-03-23 19:51:16,284 89982768 INFO wf_trace [-] Task 'prep_hostlist' is RUNNING [action_name = st2.action] (execution_id=e03c0408-51a4-45ce-a4d9-82d0dbea29eb task_id=58862794-3fc6-4fab-96dc-447a0bf67a93) 2016-03-23 19:51:18,421 83587152 INFO execution [-] Fetch execution [id=22de2def-0db5-427a-a3da-cadc17787235] 2016-03-23 19:51:18,464 83587152 INFO task [-] Fetch tasks. 2016-03-23 19:51:18,583 92316048 INFO rpc [-] Received RPC request 'run_action'[rpc_ctx=MistralContext ... 2016-03-23 19:51:18,590 92316048 INFO connectionpool [-] Starting new HTTPS connection (1): st2.stack.qadev.corp 2016-03-23 19:51:19,155 92316048 INFO stackstorm [-] Received HTTP response for St2Action [action_context={u'action_execution_id': u'33ef41d5-abc6-4b22-a7d7-a34c99cefb2e', u'task_id': u'58862794-3fc6-4fab-96dc-447a0bf67a93', u'workflow_name': u'epsilon.patch.main', u'workflow_execution_id': u'e03c0408-51a4-45ce-a4d9-82d0dbea29eb', u'task_tags': None, u'task_name': u'prep_hostlist', u'callback_url': u'/v2/action_executions/33ef41d5-abc6-4b22-a7d7-a34c99cefb2e'}, ref=e_int.mkhostlist, parameters={u'hostlist': u'dc1udtlhtst02'}, st2_context={u'endpoint': u'https://st2.stack.qadev.corp:9101/v1/actionexecutions', u'notify': {u'on-complete': {u'routes': [u'hubot']}}, u'parent': {u'execution_id': u'56f2f3aa8e326f132d3ccfad', u'user': u'ansible', u'parent': {u'action_alias_ref': {u'id': u'56940f4d8e326f4e8ff3b836', u'name': u'epsibot.patch'}, u'execution_id': u'56f2f3a58e326f132d3ccfaa', u'user': u'ansible', u'api_user': u'icherkaev', u'source_channel': u'56b3bd3f7a04d5547233cbd6'}, u'mistral': {u'action_execution_id': u'fa155f39-25c5-4473-baab-177b71004eba', u'task_id': u'a360df2a-6f7c-4c20-b136-13cd70affada', u'workflow_name': u'st2-epsibot.patch', u'workflow_execution_id': u'22de2def-0db5-427a-a3da-cadc17787235', u'task_tags': None, u'task_name': u'granted_action', u'callback_url': u'/v2/action_executions/fa155f39-25c5-4473-baab-177b71004eba'}}, u'skip_notify_tasks': []}]: 201 ... 2016-03-23 19:51:19,747 89969520 INFO rpc [-] Received RPC request 'on_action_complete'[rpc_ctx=MistralContext .. 2016-03-23 19:51:22,069 89969520 INFO wf_trace [-] Action execution 'st2.action' [RUNNING -> SUCCESS, result = {u'succeeded': True, u'failed': False, u'return_code': 0, u'stderr': u'', u'stdout': {u'hostlist': [...] 2016-03-23 19:51:24,280 89969520 INFO wf_trace [-] Task execution 'prep_hostlist' [RUNNING -> SUCCESS] (execution_id=e03c0408-51a4-45ce-a4d9-82d0dbea29eb) [WHAT'S GOING ON HERE FOR 9 SECONDS?] 2016-03-23 19:51:33,145 89969520 INFO wf_trace [-] Task 'prep_hostlist_string' is RUNNING [action_name = st2.action] (execution_id=e03c0408-51a4-45ce-a4d9-82d0dbea29eb task_id=15a65e0c-c77a-4120-b726-c1015aa5a766) 2016-03-23 19:51:35,522 83587152 INFO execution [-] Fetch execution [id=e03c0408-51a4-45ce-a4d9-82d0dbea29eb] 2016-03-23 19:51:35,541 83587152 INFO execution [-] Fetch execution [id=22de2def-0db5-427a-a3da-cadc17787235]

--- version: '2.0' e_playground.flow_test: type: direct input: - param1 tasks: task1: # [105, 26] action: core.noop on-success: - task2 task2: # [105, 128] action: core.noop on-success: - task3 task3: # [105, 230] action: core.noop on-success: - task4 task4: # [105, 332] action: core.noop on-success: - task5 task5: # [105, 434] action: core.noop on-success: - task6 task6: # [105, 536] action: core.noop on-success: - task7 task7: # [105, 638] action: core.noop on-success: - task8 task8: # [105, 740] action: core.noop on-success: - task9 task9: # [105, 842] action: core.noop on-success: - task10 task10: # [105, 944] action: core.noop on-success: - task11 task11: # [105, 1046] action: core.noop on-success: - task12 task12: # [105, 1148] action: core.noop on-success: - task13 task13: # [105, 1250] action: core.noop on-success: - task14 task14: # [105, 1352] action: core.noop on-success: - task15 task15: # [105, 1454] action: core.noop on-success: - task16 task16: # [105, 1556] action: core.noop on-success: - task17 task17: # [105, 1658] action: core.noop on-success: - task18 task18: # [105, 1760] action: core.noop

mistral=# select name, created_at, updated_at from executions_v2 where task_execution_id is null order by created_at; name | created_at | updated_at --------------+----------------------------+---------------------------- sandbox.noop | 2016-03-25 22:23:24.467681 | 2016-03-25 22:23:42.513958 task1 | 2016-03-25 22:23:24.488265 | 2016-03-25 22:23:25.190069 task2 | 2016-03-25 22:23:25.190729 | 2016-03-25 22:23:26.055155 task3 | 2016-03-25 22:23:26.056158 | 2016-03-25 22:23:27.085551 task4 | 2016-03-25 22:23:27.086131 | 2016-03-25 22:23:28.079776 task5 | 2016-03-25 22:23:28.081213 | 2016-03-25 22:23:29.105805 task6 | 2016-03-25 22:23:29.106497 | 2016-03-25 22:23:30.225479 task7 | 2016-03-25 22:23:30.226283 | 2016-03-25 22:23:31.203313 task8 | 2016-03-25 22:23:31.203884 | 2016-03-25 22:23:32.199727 task9 | 2016-03-25 22:23:32.200344 | 2016-03-25 22:23:33.239866 task10 | 2016-03-25 22:23:33.240537 | 2016-03-25 22:23:34.285053 task11 | 2016-03-25 22:23:34.285554 | 2016-03-25 22:23:35.360426 task12 | 2016-03-25 22:23:35.361547 | 2016-03-25 22:23:36.4242 task13 | 2016-03-25 22:23:36.425864 | 2016-03-25 22:23:37.428182 task14 | 2016-03-25 22:23:37.428994 | 2016-03-25 22:23:38.450216 task15 | 2016-03-25 22:23:38.45083 | 2016-03-25 22:23:39.417241 task16 | 2016-03-25 22:23:39.418314 | 2016-03-25 22:23:40.437875 task17 | 2016-03-25 22:23:40.438735 | 2016-03-25 22:23:41.46367 task18 | 2016-03-25 22:23:41.465146 | 2016-03-25 22:23:42.498322

StackStorm / st2

mistral speed between tasks #2564