Add caller information to Begin execute log entry

This patch adds a new caller information logged by executor when a new MuranoPL
function is started. This will help to reconstruct a calls flow for debugging. Also it can
be used to create a graphical execution trace.

Change-Id: If53634994b99b9bdf68dd1a020f61abbbf656d4e

murano/dsl/executor.py

@@ -29,6 +29,7 @@ import murano.dsl.helpers as helpers
 import murano.dsl.murano_method as murano_method
 import murano.dsl.murano_object as murano_object
 import murano.dsl.object_store as object_store
+import murano.dsl.principal_objects.stack_trace as trace
 import murano.dsl.yaql_functions as yaql_functions
 
 from murano.openstack.common import log as logging
@@ -128,10 +129,21 @@ class MuranoDslExecutor(object):
         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,
+        method_info = '{0}.{1} ({2})'.format(murano_class.name, method._name,
                                              hash((method_id, this_id)))
+        # Prepare caller information
+        caller_ctx = helpers.get_caller_context(context)
+        if caller_ctx:
+            caller_info = trace.compose_stack_frame(caller_ctx)
             LOG.debug(
-            "{0}: Begin execution: {1}".format(thread_marker, method_info))
+                '{0}: Begin execution: {1} called from {2}'.format(
+                    thread_marker, method_info, trace.format_frame(
+                        caller_info)))
+        else:
+            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)

murano/dsl/principal_objects/stack_trace.py

@@ -23,23 +23,14 @@ from murano.dsl import yaql_expression
 
 @murano_class.classname('io.murano.StackTrace')
 class StackTrace(murano_object.MuranoObject):
+
     def initialize(self, _context, includeNativeFrames=True):
         frames = []
         context = _context
         while True:
             if not context:
                 break
-            instruction = helpers.get_current_instruction(context)
+            frames.append(compose_stack_frame(context))
-            frames.append({
-                'instruction': None if instruction is None
-                else str(instruction),
-
-                'location': None if instruction is None
-                else instruction.source_file_position,
-
-                'method': helpers.get_current_method(context),
-                'class': helpers.get_type(context)
-            })
             context = helpers.get_caller_context(context)
         frames.pop()
         frames.reverse()
@@ -62,7 +53,25 @@ class StackTrace(murano_object.MuranoObject):
         self.set_property('frames', frames)
 
     def toString(self, prefix=''):
-        def format_frame(frame):
+        return '\n'.join([format_frame(t, prefix)for t in self.get_property(
+            'frames')])
+
+
+def compose_stack_frame(context):
+    instruction = helpers.get_current_instruction(context)
+    return {
+        'instruction': None if instruction is None
+        else str(instruction),
+
+        'location': None if instruction is None
+        else instruction.source_file_position,
+
+        'method': helpers.get_current_method(context),
+        'class': helpers.get_type(context)
+    }
+
+
+def format_frame(frame, prefix=''):
     instruction = frame['instruction']
     method = frame['method']
     murano_class = frame['class']
@@ -85,5 +94,3 @@ class StackTrace(murano_object.MuranoObject):
     else:
         return '{2}File <unknown> in method {0}\n{2}    {1}'.format(
             method, instruction, prefix)
-
-        return '\n'.join([format_frame(t)for t in self.get_property('frames')])