Any workflows are not executed if you use PostgreSQL

[Vitalii Solodilov]

This bug affected the pike 5.2.0 release.
I guess the problem arose after this commit https://github.com/openstack/mistral/commit/dbad9d3cdbb0f3a6d835ba38fcbb86dd2191a43d
Execution context is not inserted to the database.
It is not reproduced if you use MySQL or SQLite.
Stack-trace:

2017-12-07 03:00:17.256 5542 INFO mistral.api.controllers.v2.execution [req-31d44276-4084-41ac-860a-e0eb5d3d1f5b - - - - -] Create execution [execution=Execution [id='Unset', workflow_name='wf', workflow_namespace='Unset', workflow_id='Unset', description='Unset', params='Unset', task_execution_id='Unset', root_execution_id='Unset', state='Unset', state_info='Unset', input='Unset', output='Unset', created_at='Unset', updated_at='Unset', project_id='Unset']]
2017-12-07 03:00:17.284 5531 INFO mistral.engine.engine_server [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Received RPC request 'start_workflow'[workflow_identifier=wf, workflow_input={}, description=, params={}]
2017-12-07 03:00:17.303 5531 INFO workflow_trace [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Starting workflow [name=wf, input={}]
2017-12-07 03:00:17.309 5531 INFO workflow_trace [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Workflow 'wf' [IDLE -> RUNNING, msg=None] (execution_id=ecc6513c-57c1-481c-aebf-d1600e113efc)
2017-12-07 03:00:17.309 5531 WARNING oslo_db.sqlalchemy.utils [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Unique keys not in sort_keys. The sorting order may be unstable.
2017-12-07 03:00:17.386 5531 INFO mistral.executors.executor_server [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Received RPC request 'run_action'[action_ex_id=03ff857a-009a-4ac0-be0f-7e09bf58fffb, action_cls_str=mistral.actions.std_actions.NoOpAction, action_cls_attrs={}, params={}]
2017-12-07 03:00:17.386 5531 INFO mistral.actions.std_actions [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Running no-op action
2017-12-07 03:00:17.388 5531 INFO mistral.engine.engine_server [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Received RPC request 'on_action_complete'[action_ex_id=03ff857a-009a-4ac0-be0f-7e09bf58fffb, result=Result [data=None, error=None, cancel=False]]
2017-12-07 03:00:17.395 5531 INFO workflow_trace [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Action 'std.noop' (03ff857a-009a-4ac0-be0f-7e09bf58fffb)(task=task1) [RUNNING -> SUCCESS, result = None]
2017-12-07 03:00:17.406 5531 INFO workflow_trace [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Task 'task1' (37a487fb-dd4b-4805-beae-2ba5f4363b3f) [RUNNING -> SUCCESS, msg=None] (execution_id=ecc6513c-57c1-481c-aebf-d1600e113efc)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server [req-5a5b7f2e-22a9-481e-8a26-f0f0b436e435 - - - - -] Exception during message handling: TypeError: argument of type 'NoneType' is not iterable
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/engine_server.py", line 154, in on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return self.engine.on_action_complete(action_ex_id, result, wf_action)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/db/utils.py", line 75, in decorate
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return _with_auth_context(auth_ctx, func, *args, **kw)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/tenacity/__init__.py", line 199, in wrapped_f
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return self.call(f, *args, **kw)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/tenacity/__init__.py", line 276, in call
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server start_time=start_time)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/tenacity/__init__.py", line 237, in iter
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return fut.result()
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/usr/lib/python3.6/concurrent/futures/_base.py", line 425, in result
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return self.__get_result()
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server raise self._exception
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/tenacity/__init__.py", line 279, in call
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = fn(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/db/utils.py", line 48, in _with_auth_context
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return func(*args, **kw)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/action_queue.py", line 92, in decorate
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server res = func(*args, **kw)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/osprofiler/profiler.py", line 157, in wrapper
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/default_engine.py", line 119, in on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server action_handler.on_action_complete(action_ex, result)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/osprofiler/profiler.py", line 157, in wrapper
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/action_handler.py", line 54, in on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server task_handler.schedule_on_action_complete(action_ex)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/task_handler.py", line 437, in schedule_on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server _on_action_complete(action_ex)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/osprofiler/profiler.py", line 157, in wrapper
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/task_handler.py", line 110, in _on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server task.on_action_complete(action_ex)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/osprofiler/profiler.py", line 157, in wrapper
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/tasks.py", line 325, in on_action_complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server self.complete(state, state_info)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral_master/lib/python3.6/site-packages/osprofiler/profiler.py", line 157, in wrapper
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/engine/tasks.py", line 191, in complete
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server data_flow.publish_variables(self.task_ex, self.task_spec)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/workflow/data_flow.py", line 195, in publish_variables
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server if task_ex.name in expr_ctx:
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/workflow/data_flow.py", line 69, in __contains__
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return any(key in d for d in self.dicts)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server File "/home/mcdoker18/PycharmProjects/mistral/mistral/workflow/data_flow.py", line 69, in <genexpr>
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server return any(key in d for d in self.dicts)
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server TypeError: argument of type 'NoneType' is not iterable
2017-12-07 03:00:17.408 5531 ERROR oslo_messaging.rpc.server

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/536256

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/536256
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=05252da83572fb487054d03453da7494f3077f02
Submitter: Zuul
Branch: master

commit 05252da83572fb487054d03453da7494f3077f02
Author: Renat Akhmerov <email address hidden>
Date: Mon Jan 22 15:50:09 2018 +0700

    Added session.flush() before update_on_match()

    * It turns out that update_on_match() from oslo_db breaks fields
      of a persistent object (attached to the session) in some cases.
      For example, when we use PostgreSQL as a DB it doesn't properly
      merge fields of the given specimen onto the fields of the object
      attached to the SQLAlchemy session. For some reason, it cleans up
      the history of ORM events registered before this operation so
      that if some update took place in this session and they are not
      flushed yet to DB they simply get lost. Hence adding flush()
      on the session right before this operation helps.
    * NOTE: this is rather a workaround than a fix of the root cause.
      Root cause still needs to be found.

    Change-Id: I546badd8b1c96b68567287fc9d38b07738272503
    Closes-Bug: #1736821

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/536692

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/536692
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=886bc2c858bf4c1ff799b452f02458568c42387c
Submitter: Zuul
Branch: stable/pike

commit 886bc2c858bf4c1ff799b452f02458568c42387c
Author: Renat Akhmerov <email address hidden>
Date: Mon Jan 22 15:50:09 2018 +0700

    Added session.flush() before update_on_match()

    * It turns out that update_on_match() from oslo_db breaks fields
      of a persistent object (attached to the session) in some cases.
      For example, when we use PostgreSQL as a DB it doesn't properly
      merge fields of the given specimen onto the fields of the object
      attached to the SQLAlchemy session. For some reason, it cleans up
      the history of ORM events registered before this operation so
      that if some update took place in this session and they are not
      flushed yet to DB they simply get lost. Hence adding flush()
      on the session right before this operation helps.
    * NOTE: this is rather a workaround than a fix of the root cause.
      Root cause still needs to be found.

    Change-Id: I546badd8b1c96b68567287fc9d38b07738272503
    Closes-Bug: #1736821
    (cherry picked from commit 05252da83572fb487054d03453da7494f3077f02)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/mistral 6.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/542876
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=13497ae3e1ec94e47faa16fa781aa96c2e411fe9
Submitter: Zuul
Branch: stable/pike

commit 13497ae3e1ec94e47faa16fa781aa96c2e411fe9
Author: Vitalii Solodilov <email address hidden>
Date: Mon Jan 8 21:17:36 2018 +0400

    Fixed integration of the unit tests with PosrgeSQL

    * Corrected the path to the mistral config file in a unit test
    * Minor improvement in the run_tests.sh script
    * Fixed unstable the `test_rerun_join_with_branch_errors` and
    test_rerun_on_join_task test. task3 id is properly passed now
    * Removed unused `insert_or_ignore` api and tests. This api
    broke the test in PostgreSQL case
    * Passed correct value to the filter in
    `test_filter_action_definitions_by_has_filter` test

    Closes-Bug: #1736821
    Change-Id: I2ce3d2e1be001d9c0c76ebe5293b2bf578a7160b
    Signed-off-by: Vitalii Solodilov <email address hidden>
    (cherry picked from commit cf0484ad2e0ee80f8ae7d09961dd6fe2b62d9010)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/mistral 5.2.1 release.