Exception during message handling: _oslo_messaging_localcontext

[Kirill Izotov]

The task finishes successfully, but reporting its status as 'error'.

This bug appears to happen only when we're running our components with --use-debugger flag (which monkey_patches thread module to be greenthread-friendly).

To reproduce:
Run Mistral with --use-debugger flag and try to create an execution for a task with std.echo action.

Trace:
2014-06-30 15:13:23.731 54843 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: _oslo_messaging_localcontext_842079cebc2e4071b111d639037e9ef6
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 178, in _dispatch
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher localcontext.clear_local_context()
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/localcontext.py", line 55, in clear_local_context
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher delattr(_STORE, _KEY)
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher AttributeError: _oslo_messaging_localcontext_842079cebc2e4071b111d639037e9ef6
2014-06-30 15:13:23.731 54843 TRACE oslo.messaging.rpc.dispatcher
2014-06-30 15:13:23.731 54843 ERROR oslo.messaging._drivers.common [-] Returning exception _oslo_messaging_localcontext_842079cebc2e4071b111d639037e9ef6 to caller
2014-06-30 15:13:23.731 54843 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', ' File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 178, in _dispatch\n localcontext.clear_local_context()\n', ' File "/Users/enykeev/Developer/Work/Openstack/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/localcontext.py", line 55, in clear_local_context\n delattr(_STORE, _KEY)\n', 'AttributeError: _oslo_messaging_localcontext_842079cebc2e4071b111d639037e9ef6\n']

[Ray Chen (chenrano2002)]

I can reproduce this issue and want to fix it

[Ray Chen (chenrano2002)]

Here is one similar oslo.messaging bug: https://bugs.launchpad.net/oslo.messaging/+bug/1288878

monkey_patch thread is needed when using oslo.message. the behavior is unknown and in risk if thread is set to False.

In my local development, the task will run successfully and report state is SUCCESS. However, the oslo messaging exception can also be seen.

========

Workflow:
  tasks:
    task1:
      action: std.echo
      parameters:
        output: "Hello, World"

and test log:

2014-07-18 15:15:12.286 11358 INFO workflow_trace [-] New execution started - [workbook_name = 'myBook', task_name = 'task1']
2014-07-18 15:15:12.405 11358 INFO mistral.engine.drivers.default.engine [-] Submitted task for execution: 'e7fc79c4-a2cc-461f-a291-4ab04c536e76'
localhost.localdomain - - [18/Jul/2014 15:15:12] "POST /v1/workbooks/myBook/executions HTTP/1.1" 201 127
2014-07-18 15:15:12.427 11358 INFO mistral.actions.std_actions [-] Running echo action [output=Hello, World]
2014-07-18 15:15:12.466 11358 INFO workflow_trace [-] Task 'task1' [RUNNING -> SUCCESS, result = Hello, World]
2014-07-18 15:15:12.494 11358 DEBUG mistral.engine.workflow [-] Recieved task task1: SUCCESS find_tasks_after_completion /home/ray/git/mistral/mistral/engine/workflow.py:87
2014-07-18 15:15:12.499 11358 DEBUG mistral.engine.workflow [-] Found tasks: [] find_tasks_after_completion /home/ray/git/mistral/mistral/engine/workflow.py:104
2014-07-18 15:15:12.499 11358 DEBUG mistral.engine.workflow [-] Workflow tasks to schedule: [] find_tasks_after_completion /home/ray/git/mistral/mistral/engine/workflow.py:110
2014-07-18 15:15:12.507 11358 INFO workflow_trace [-] Execution 'c415b3f2-e3f9-44b0-808a-1eae5c127d8c' [RUNNING -> SUCCESS]
2014-07-18 15:15:12.511 11358 INFO mistral.engine [-] Changed execution state: {'workbook_name': u'myBook', 'task': u'task1', 'updated_at': None, 'id': u'c415b3f2-e3f9-44b0-808a-1eae5c127d8c', 'created_at': '2014-07-18 07:15:12.323775', 'state': 'SUCCESS', 'context': {}}
2014-07-18 15:15:12.548 11358 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: _oslo_messaging_localcontext_08abad06ee4d4a1dbe063092efdf276b
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher File "/home/ray/git/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher File "/home/ray/git/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 178, in _dispatch
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher localcontext.clear_local_context()
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher File "/home/ray/git/mistral/.tox/venv/lib/python2.7/site-packages/oslo/messaging/localcontext.py", line 55, in clear_local_context
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatcher delattr(_STORE, _KEY)
2014-07-18 15:15:12.548 11358 TRACE oslo.messaging.rpc.dispatche...

[Renat Akhmerov (rakhmerov)]

I fixed this bug in the tests:
https://review.openstack.org/#/c/148237/

It's related with the fact that monkey patching must be done before importing oslo.messaging. More information can be found at https://review.openstack.org/#/c/148237/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/148237
Committed: https://git.openstack.org/cgit/stackforge/mistral/commit/?id=95b4cd5e36c43e4468102a42362dcd59e28f9b22
Submitter: Jenkins
Branch: master

commit 95b4cd5e36c43e4468102a42362dcd59e28f9b22
Author: Renat Akhmerov <email address hidden>
Date: Mon Jan 19 18:35:41 2015 +0600

    Fixing environment tests

    * As a side effect the bug related to oslo.messaging (AttributeError: ...)
      was also fixed by moving monkey patching to mistral/__init__.py. Monkey
      patching has to be done before importing oslo.messaging. Details can be
      found at https://bugs.launchpad.net/oslo.messaging/+bug/1288878
    * Refactored environment engine tests
    * Refactored and fixed environment API tests (there was a number of
      fragile dict string representation comparisons)

    Closes-Bug: #1337705

    Change-Id: Id725570dfc7148f010647c4b2487882174b0c56e