Fix a bug when the same method could be run concurrently by 2 threads

The problem was caused by the fact that the eventlet switching occurs 
not immediately when the event.send() is executed, but in some time 
afterwards (when some blocking operation is run). This time may be 
sufficient for the lock to be re-aquired by the same thread.

For example, imagine there are two green threads A and B attempting to 
simultaneously run a method M of the same object. Consider the following
scenario:
1) A is executed first and acquires the lock, then executes M
2) B detects that the lock is taken and awaits on the event.wait()
3) A is finished with M, releases the lock and calls event.send() to
   allow B to proceed
4) Switching does not happen immediately and A proceeds till some 
   blocking operation
5) Switching occurs, B is activated and acquires the lock on M

The problem happens because on the step (5) B assumes that the lock was
indeed released by A on step (3). However, as some actions may take 
place during (4), they may include requiring the lock again. B does not
recheck this, which causes the twin ownership of the lock.
To resolve this B needs to always recheck the lock after re-activating 
from wait, and, if the lock is still taken, wait again.

Closes-Bug: #1316551

Debugging and fixing of this issue required to add some logging, which 
may be useful for other debugging scenarios: the output contain the 
information about green-thread id, the method and the object it is run 
for.

So, this partially targets blueprint improve-engine-logging

Change-Id: I4613acf15df32fab038689b2552d4a5d9090d88e

muranoapi/dsl/executor.py

@@ -30,6 +30,10 @@ import muranoapi.dsl.murano_object as murano_object
 import muranoapi.dsl.object_store as object_store
 import muranoapi.dsl.yaql_functions as yaql_functions
 
+from muranoapi.openstack.common import log as logging
+
+LOG = logging.getLogger(__name__)
+
 
 class MuranoDslExecutor(object):
     def __init__(self, class_loader, environment=None):
@@ -111,20 +115,30 @@ class MuranoDslExecutor(object):
         method_id = id(body)
         this_id = this.object_id
 
-        event, marker = self._locks.get((method_id, this_id), (None, None))
-        if event:
-            if marker == thread_marker:
-                return self._invoke_method_implementation_gt(
-                    body, this, params, murano_class, context)
-            event.wait()
+        while True:
+            event, marker = self._locks.get((method_id, this_id), (None, None))
+            if event:
+                if marker == thread_marker:
+                    return self._invoke_method_implementation_gt(
+                        body, this, params, murano_class, context)
+                event.wait()
+            else:
+                break
 
         event = eventlet.event.Event()
         self._locks[(method_id, this_id)] = (event, thread_marker)
+        # noinspection PyProtectedMember
+        method_info = "{0}.{1} ({2})".format(murano_class.name, method._name,
+                                             hash((method_id, this_id)))
+        LOG.debug(
+            "{0}: Begin execution: {1}".format(thread_marker, method_info))
         gt = eventlet.spawn(self._invoke_method_implementation_gt, body,
                             this, params, murano_class, context,
                             thread_marker)
         result = gt.wait()
         del self._locks[(method_id, this_id)]
+        LOG.debug(
+            "{0}: End execution: {1}".format(thread_marker, method_info))
         event.send()
         return result