From 398836355964df572d04314c02d55a37852f1e05 Mon Sep 17 00:00:00 2001
From: Georgy Okrokvertskhov <gokrokvertskhov@mirantis.com>
Date: Tue, 29 Jul 2014 08:00:33 -0700
Subject: [PATCH] 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                      | 18 ++++-
 murano/dsl/principal_objects/stack_trace.py | 75 +++++++++++----------
 2 files changed, 56 insertions(+), 37 deletions(-)

diff --git a/murano/dsl/executor.py b/murano/dsl/executor.py
index fd06755e..c89e7ce4 100644
--- a/murano/dsl/executor.py
+++ b/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)))
-        LOG.debug(
-            "{0}: Begin execution: {1}".format(thread_marker, method_info))
+        # 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} 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)
diff --git a/murano/dsl/principal_objects/stack_trace.py b/murano/dsl/principal_objects/stack_trace.py
index 90f4e341..c18a8c1e 100644
--- a/murano/dsl/principal_objects/stack_trace.py
+++ b/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({
-                '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)
-            })
+            frames.append(compose_stack_frame(context))
             context = helpers.get_caller_context(context)
         frames.pop()
         frames.reverse()
@@ -62,28 +53,44 @@ class StackTrace(murano_object.MuranoObject):
         self.set_property('frames', frames)
 
     def toString(self, prefix=''):
-        def format_frame(frame):
-            instruction = frame['instruction']
-            method = frame['method']
-            murano_class = frame['class']
-            location = frame['location']
-            if murano_class:
-                method += ' of class ' + murano_class.name
+        return '\n'.join([format_frame(t, prefix)for t in self.get_property(
+            'frames')])
 
-            if location:
-                args = (
-                    os.path.abspath(location.file_path),
-                    location.start_line,
-                    ':' + str(location.start_column)
-                    if location.start_column >= 0 else '',
-                    method,
-                    instruction,
-                    prefix
-                )
-                return '{5}File "{0}", line {1}{2} in method {3}\n' \
-                       '{5}    {4}'.format(*args)
-            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')])
+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']
+    location = frame['location']
+    if murano_class:
+        method += ' of class ' + murano_class.name
+
+    if location:
+        args = (
+            os.path.abspath(location.file_path),
+            location.start_line,
+            ':' + str(location.start_column)
+            if location.start_column >= 0 else '',
+            method,
+            instruction,
+            prefix
+        )
+        return '{5}File "{0}", line {1}{2} in method {3}\n' \
+               '{5}    {4}'.format(*args)
+    else:
+        return '{2}File <unknown> in method {0}\n{2}    {1}'.format(
+            method, instruction, prefix)