From 0c1be89f2f0edb9502c765f258e76ded8087ad2e Mon Sep 17 00:00:00 2001
From: Alexander Tivelkov <ativelkov@mirantis.com>
Date: Thu, 1 Aug 2013 18:29:45 +0400
Subject: [PATCH] Conductor logging enhanced (MRN-713)

"Rule" tags have got additional parameter ("desc") which is supposed to contain
a human-readable description of the rule - i.e. which entities the rule should
match in the data (without it the rule can be identified only by its "match"
statement, which is absolutely unreadable).
Existing workflows have got some approximate descriptions in their Rules.

These desc's  are logged (at DEBUG level) when the rule is matched against some
data - the matched data is outputted as well.
Also, additional logging messages added in various locations to do some
excessive logging of conductor operations (setting context values, reporting,
state transitions, waiting for RMQ messages).

As the result, the conductor's log (if  HeatClient messages are grepped out)
should contain a detailed explanation of conductor's states and the execution
routines.

Change-Id: I8d4794f522d4218cf58206682cfc9c0ca0f4b102
---
 data/workflows/AD.xml                     | 29 +++++++++++++++--------
 data/workflows/AspNetApps.xml             | 18 +++++++++-----
 data/workflows/Common.xml                 |  6 ++---
 data/workflows/ExternalAD.xml.example     |  4 +++-
 data/workflows/Images.xml                 |  2 +-
 data/workflows/MsSqlServer.xml            | 12 ++++++----
 muranoconductor/app.py                    |  5 ++++
 muranoconductor/commands/windows_agent.py |  2 ++
 muranoconductor/reporting.py              |  5 +++-
 muranoconductor/workflow.py               | 24 ++++++++++++++-----
 10 files changed, 75 insertions(+), 32 deletions(-)

diff --git a/data/workflows/AD.xml b/data/workflows/AD.xml
index b325aee..ea2dcf3 100644
--- a/data/workflows/AD.xml
+++ b/data/workflows/AD.xml
@@ -1,11 +1,13 @@
 <workflow>
-	<rule match="$.services[?(@.type == 'activeDirectory' and @.domain)].units[?(not @.isMaster)]">
+	<rule match="$.services[?(@.type == 'activeDirectory' and @.domain)].units[?(not @.isMaster)]"
+          desc="Slave units of AD services">
 		<set path="domain">
 			<select path="::domain"/>
 		</set>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]">
+	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]"
+            desc="Units of AD services which have got hostname and image assigned, but instances not deployed yet">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating instance <select path="state.hostname"/> (<select path="name"/>)</parameter>
@@ -41,7 +43,8 @@
 		</update-cf-stack>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.instanceName and @.adminPassword and @.adminPassword != @.state.adminPassword)]">
+	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.instanceName and @.adminPassword and @.adminPassword != @.state.adminPassword)]"
+            desc="Units of AD services which have got instances deployed but the local admin passwords not set yet">
 		<send-command template="SetPassword">
 			<parameter name="unit">
 				<select path="id"/>
@@ -64,7 +67,8 @@
 		</send-command>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'activeDirectory' and @.adminPassword and @.adminPassword != @.state.domainAdminPassword)].units[?(@.state.instanceName and @.isMaster)]">
+	<rule match="$.services[?(@.type == 'activeDirectory' and @.adminPassword and @.adminPassword != @.state.domainAdminPassword)].units[?(@.state.instanceName and @.isMaster)]"
+            desc="Deployed master-units of AD services for which the domain admin password is not set yet">
 		<send-command template="SetPassword">
 			<parameter name="unit">
 				<select path="id"/>
@@ -87,7 +91,8 @@
 		</send-command>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'activeDirectory' and @.state.primaryDc is None)].units[?(@.state.instanceName and @.isMaster)]">
+	<rule match="$.services[?(@.type == 'activeDirectory' and @.state.primaryDc is None)].units[?(@.state.instanceName and @.isMaster)]"
+            desc="Deployed master-units of AD services on which the Primary DC has not been installed yet ">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating Primary Domain Controller on unit <select path="state.hostname"/> (<select path="name"/>)</parameter>
@@ -119,7 +124,8 @@
 		</send-command>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'activeDirectory' and @.state.primaryDc and not @.state.primaryDcIp)].units[?(@.state.instanceName and @.isMaster)]">
+	<rule match="$.services[?(@.type == 'activeDirectory' and @.state.primaryDc and not @.state.primaryDcIp)].units[?(@.state.instanceName and @.isMaster)]"
+            desc="Master Units of AD services on which the Primary Domain Controller has been configured but DNS ip has not been asked for">
 		<send-command template="AskDnsIp" result="ip">
 			<parameter name="unit">
 				<select path="id"/>
@@ -135,7 +141,8 @@
 		</send-command>
 	</rule>
 
-    <rule match="$.services[?(@.type != 'activeDirectory')].units[?(@.state.domain and not @.domain)]">
+    <rule match="$.services[?(@.type != 'activeDirectory')].units[?(@.state.domain and not @.domain)]"
+            desc="Any non-AD services of the environment which has been part of the domain but needs to leave it">
         <send-command template="LeaveDomain">
             <parameter name="unit">
                 <select path="id" source="unit"/>
@@ -161,7 +168,8 @@
         </send-command>
     </rule>
 
-	<rule match="$..units[?(@.state.instanceName and @.domain and @.domain != @.state.domain)]">
+	<rule match="$..units[?(@.state.instanceName and @.domain and @.domain != @.state.domain)]"
+            desc="Any deployed unit which need to enter the domain">
 		<set path="#unit">
 			<select/>
 		</set>
@@ -170,7 +178,7 @@
 		</set>
 		<rule>
 			<parameter name="match">/$.services[?(@.type == 'activeDirectory' and @.domain == '<select path="domain"/>' and @.state.primaryDcIp)]</parameter>
-
+            <parameter name="desc">Domain controller exists with the assigned DNS IP</parameter>
 			<send-command template="JoinDomain">
 				<parameter name="unit">
 					<select path="id" source="unit"/>
@@ -208,7 +216,8 @@
 	</rule>
 
 
-	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.domain and not @.isMaster and not @.state.installed)]">
+	<rule match="$.services[?(@.type == 'activeDirectory')].units[?(@.state.domain and not @.isMaster and not @.state.installed)]"
+            desc="Slave units of AD services which has not got secondary DC installed yet">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating Secondary Domain Controller on unit <select path="state.hostname"/> (<select path="name"/>)</parameter>
diff --git a/data/workflows/AspNetApps.xml b/data/workflows/AspNetApps.xml
index e40efe2..1a209ef 100644
--- a/data/workflows/AspNetApps.xml
+++ b/data/workflows/AspNetApps.xml
@@ -1,11 +1,13 @@
 <workflow>
-	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm') and @.domain)].units[*]">
+	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm') and @.domain)].units[*]"
+          desc='Units of web services with domain'>
 		<set path="domain">
 			<select path="::domain"/>
 		</set>
 	</rule>
 
-	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm'))].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]">
+	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm'))].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]"
+          desc="Units of web services having hostname and image names assigned but without instances">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating instance <select path="state.hostname"/> (<select path="name"/>)</parameter>
@@ -41,7 +43,8 @@
 		</update-cf-stack>
 	</rule>
 
-	<rule match="$.services[?(@.type in ('webServerFarm', 'aspNetAppFarm'))].units[?(@.state.hostname and not @.state.registeredWithLB)]">
+	<rule match="$.services[?(@.type in ('webServerFarm', 'aspNetAppFarm'))].units[?(@.state.hostname and not @.state.registeredWithLB)]"
+          desc="Units of web-farms services which have a hostname assigned but are not registered with LB">
 		<update-cf-stack template="LoadBalancer" result="outputs">
 			<parameter name="mappings">
 				<map>
@@ -57,7 +60,8 @@
 		</update-cf-stack>
 	</rule>
 
-	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm') and @.adminPassword and @.adminPassword != @.state.adminPassword)].units[?(@.state.instanceName)]">
+	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm') and @.adminPassword and @.adminPassword != @.state.adminPassword)].units[?(@.state.instanceName)]"
+            desc="Units of web services which have got an instance deployed but has not got a correct admin password ">
 		<send-command template="SetPassword">
 			<parameter name="unit">
 				<select path="id"/>
@@ -81,7 +85,8 @@
 	</rule>
 
 
-	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm'))].units[?(@.state.instanceName and not @.state.iisInstalled)]">
+	<rule match="$.services[?(@.type in ('webServer', 'aspNetApp', 'webServerFarm', 'aspNetAppFarm'))].units[?(@.state.instanceName and not @.state.iisInstalled)]"
+            desc="Units of web services which have got an instance deployed but have not got an IIS installed">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating IIS Web Server on unit <select path="state.hostname"/> (<select path="name"/>)</parameter>
@@ -103,7 +108,8 @@
 		</send-command>
 	</rule>
 
-	<rule match="$.services[?(@.type in ('aspNetApp', 'aspNetAppFarm'))].units[?(@.state.iisInstalled and not @.state.webAppDeployed)]">
+	<rule match="$.services[?(@.type in ('aspNetApp', 'aspNetAppFarm'))].units[?(@.state.iisInstalled and not @.state.webAppDeployed)]"
+            desc="Units of ASP.NET app services which have got IIS installed but not the WebApplication deployed">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Deploying WebApp <select path="::name"/> on unit <select path="state.hostname"/> (<select path="name"/>)</parameter>
diff --git a/data/workflows/Common.xml b/data/workflows/Common.xml
index 561422c..814f466 100644
--- a/data/workflows/Common.xml
+++ b/data/workflows/Common.xml
@@ -1,6 +1,6 @@
 <workflow>
 
-	<rule match="$.services[*].units[?(@.state.hostname is None)]">
+	<rule match="$.services[*].units[?(@.state.hostname is None)]" desc="Units with no hostname">
 		<set path="state.hostname">
 			<generate-hostname>
 				<parameter name="pattern"><select path="::unitNamingPattern"/></parameter>
@@ -9,8 +9,8 @@
 		</set>
 	</rule>
 
-	<rule match="$[?(not @.state.deleted)]">
-		<rule match="$.services[*].units[*]">
+	<rule match="$[?(not @.state.deleted)]" desc="Search through all the environments..">
+		<rule match="$.services[*].units[*]" desc="If any units exists">
 			<empty>
 				<delete-cf-stack>
 					<success>
diff --git a/data/workflows/ExternalAD.xml.example b/data/workflows/ExternalAD.xml.example
index aba1a1b..bcd6aad 100644
--- a/data/workflows/ExternalAD.xml.example
+++ b/data/workflows/ExternalAD.xml.example
@@ -1,5 +1,6 @@
 <workflow>
-	<rule match="$.services[?(@.type != 'activeDirectory' and @.availabilityZone)].units[?(@.state.instanceName and @.state.hostname and not @.domain)]">
+	<rule match="$.services[?(@.type != 'activeDirectory' and @.availabilityZone)].units[?(@.state.instanceName and @.state.hostname and not @.domain)]"
+	      desc="Units of Non-AD services with availability zone specified which are deployed and are not part of the domain">
         <set path="#externalADmap">
             <map>
 
@@ -40,6 +41,7 @@
 		</set>
 		<rule>
 			<parameter name="match">$[?(@.state.domain != '<select path="domain" source="ad"/>')]</parameter>
+            <parameter name="desc">Units which are not part of the target domain but need to join</parameter>
 
 			<send-command template="JoinDomain">
 				<parameter name="unit">
diff --git a/data/workflows/Images.xml b/data/workflows/Images.xml
index 77e2440..61430d6 100644
--- a/data/workflows/Images.xml
+++ b/data/workflows/Images.xml
@@ -1,5 +1,5 @@
 <workflow>
-	<rule match="$.services[*].units[?(not @.state.osImageName)]">
+	<rule match="$.services[*].units[?(not @.state.osImageName)]" desc="Units with no image">
         <set path="#osImageMap">
             <map>
 
diff --git a/data/workflows/MsSqlServer.xml b/data/workflows/MsSqlServer.xml
index f4f7eb2..e571d35 100644
--- a/data/workflows/MsSqlServer.xml
+++ b/data/workflows/MsSqlServer.xml
@@ -1,11 +1,13 @@
 <workflow>
-	<rule match="$.services[?(@.type == 'msSqlServer' and @.domain)].units[*]">
+	<rule match="$.services[?(@.type == 'msSqlServer' and @.domain)].units[*]"
+            desc="Units of SQL Server services which are part of the domain">
 		<set path="domain">
 			<select path="::domain"/>
 		</set>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'msSqlServer')].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]">
+	<rule match="$.services[?(@.type == 'msSqlServer')].units[?(@.state.hostname and @.state.osImageName and not @.state.instanceName)]"
+            desc="Units of SQLServer services having hostname and image names assigned but without instances">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating instance <select path="state.hostname"/> (<select path="name"/>)</parameter>
@@ -41,7 +43,8 @@
 		</update-cf-stack>
 	</rule>
 
-	<rule match="$.services[?(@.type == 'msSqlServer' and @.adminPassword and @.adminPassword != @.state.adminPassword)].units[?(@.state.instanceName)]">
+	<rule match="$.services[?(@.type == 'msSqlServer' and @.adminPassword and @.adminPassword != @.state.adminPassword)].units[?(@.state.instanceName)]"
+            desc="Units of SQLServer services which have got an instance deployed but has not got a correct admin password">
 		<send-command template="SetPassword">
 			<parameter name="unit">
 				<select path="id"/>
@@ -65,7 +68,8 @@
 	</rule>
 
 
-	<rule match="$.services[?(@.type == 'msSqlServer')].units[?(@.state.instanceName and not @.state.msSqlServerInstalled)]">
+	<rule match="$.services[?(@.type == 'msSqlServer')].units[?(@.state.instanceName and not @.state.msSqlServerInstalled)]"
+            desc="Units of SqlServer services which have got an instance deployed but have not got an SQL Server installed">
 		<report entity="unit">
 			<parameter name="id"><select path="id"/></parameter>
 			<parameter name="text">Creating MS SQL Server on unit <select path="state.hostname"/> (<select path="name"/>)</parameter>
diff --git a/muranoconductor/app.py b/muranoconductor/app.py
index f1d173f..a847cb6 100644
--- a/muranoconductor/app.py
+++ b/muranoconductor/app.py
@@ -104,8 +104,13 @@ class ConductorWorkflowService(service.Service):
                                 if workflow.execute():
                                     result = True
                             if not result:
+                                log.debug(
+                                    "No rules matched, "
+                                    "will now execute pending commands")
                                 break
                         if not command_dispatcher.execute_pending():
+                            log.debug("No pending commands found, "
+                                      "seems like we are done")
                             break
                     except Exception as ex:
                         log.exception(ex)
diff --git a/muranoconductor/commands/windows_agent.py b/muranoconductor/commands/windows_agent.py
index 140e732..a2ea159 100644
--- a/muranoconductor/commands/windows_agent.py
+++ b/muranoconductor/commands/windows_agent.py
@@ -49,6 +49,8 @@ class WindowsAgentExecutor(CommandBase):
 
         with self._rmqclient.open(self._results_queue) as subscription:
             while self.has_pending_commands():
+                log.debug("Waiting for responses to be returned by the agent. "
+                          "%i total responses remain", len(self._pending_list))
                 msg = subscription.get_message()
                 msg.ack()
                 msg_id = msg.id.lower()
diff --git a/muranoconductor/reporting.py b/muranoconductor/reporting.py
index 4f68906..2463925 100644
--- a/muranoconductor/reporting.py
+++ b/muranoconductor/reporting.py
@@ -12,10 +12,12 @@
 # implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-
+from openstack.common import log as logging
 import xml_code_engine
 from muranocommon.messaging import Message
 
+log = logging.getLogger(__name__)
+
 
 class Reporter(object):
     def __init__(self, rmqclient, task_id, environment_id):
@@ -45,6 +47,7 @@ class Reporter(object):
         self._rmqclient.send(
             message=msg,
             key='task-reports')
+        log.debug("Reported '%s' to API", body)
 
 
 def _report_func(context, id, entity, text, **kwargs):
diff --git a/muranoconductor/workflow.py b/muranoconductor/workflow.py
index caefa38..fc3d33f 100644
--- a/muranoconductor/workflow.py
+++ b/muranoconductor/workflow.py
@@ -12,6 +12,7 @@
 # implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
+import logging
 
 import jsonpath
 import re
@@ -20,6 +21,8 @@ import types
 import function_context
 import xml_code_engine
 
+log = logging.getLogger(__name__)
+
 
 class Workflow(object):
     def __init__(self, filename, data, command_dispatcher, config, reporter):
@@ -123,13 +126,17 @@ class Workflow(object):
         if path.startswith('##'):
             raise RuntimeError('Cannot modify config from XML-code')
         elif path.startswith('#'):
-            context[':' + path[1:]] = body_data
+            context_path = ':' + path[1:]
+            log.debug(
+                "Setting context variable '{0}' to '{1}'".format(context_path,
+                                                                 body_data))
+            context[context_path] = body_data
             return
-
         if target:
             data = context[target]
             position = path.split('.')
             if Workflow._get_path(data, position) != body_data:
+                log.debug("Setting '{0}' to '{1}'".format(path, body_data))
                 Workflow._set_path(data, position, body_data)
                 context['/hasSideEffects'] = True
 
@@ -137,14 +144,18 @@ class Workflow(object):
             data = context['/dataSource']
             new_position = Workflow._correct_position(path, context)
             if Workflow._get_path(data, new_position) != body_data:
+                log.debug("Setting '{0}' to '{1}'".format(path, body_data))
                 Workflow._set_path(data, new_position, body_data)
                 context['/hasSideEffects'] = True
 
     @staticmethod
-    def _rule_func(match, context, body, engine, limit=0, name=None, **kwargs):
+    def _rule_func(match, context, body, engine, limit=0, name=None, desc=None,
+                   **kwargs):
         position = context['__dataSource_currentPosition'] or []
 
         position, match = Workflow._get_relative_position(match, context)
+        if not desc:
+            desc = match
         data = Workflow._get_path(context['/dataSource'], position)
         match = re.sub(r'@\.([\w.]+)',
                        r"Workflow._get_path(@, '\1'.split('.'))", match)
@@ -157,8 +168,9 @@ class Workflow(object):
             index += 1
             new_position = position + found_match[1:]
             context['__dataSource_currentPosition'] = new_position
-            context['__dataSource_currentObj'] = Workflow._get_path(
-                context['/dataSource'], new_position)
+            cur_obj = Workflow._get_path(context['/dataSource'], new_position)
+            context['__dataSource_currentObj'] = cur_obj
+            log.debug("Rule '{0}' matches on '{1}'".format(desc, cur_obj))
             for element in body:
                 if element.tag == 'empty':
                     continue
@@ -168,7 +180,7 @@ class Workflow(object):
         if not index:
             empty_handler = body.find('empty')
             if empty_handler is not None:
-
+                log.debug("Running empty handler for rule '{0}'".format(desc))
                 engine.evaluate_content(empty_handler, context)
 
     @staticmethod