Add workflow logging

* Created new log configuration for pretty workflow output.
 * Since this config opt is used before importing
   executor.server, I include some refactor of unit tests.

Implements blueprint mistral-pretty-workflow-logging

Change-Id: Ia9b8b5d401afafe99d6133685a4d3abbcb8ba2e3

etc/wf_trace_logging.conf.example

@@ -0,0 +1,40 @@
+[loggers]
+keys=workflow_trace,root
+
+[handlers]
+keys=consoleHandler, prettyFileHandler, fileHandler
+
+[formatters]
+keys=simpleFormatter
+
+[logger_workflow_trace]
+level=INFO
+handlers=consoleHandler, fileHandler
+qualname=workflow_trace
+
+[logger_root]
+level=INFO
+handlers=fileHandler
+
+[handler_fileHandler]
+class=FileHandler
+level=INFO
+formatter=simpleFormatter
+args=("/tmp/mistral.log",)
+
+[handler_consoleHandler]
+class=StreamHandler
+level=INFO
+formatter=simpleFormatter
+args=(sys.stdout,)
+
+[handler_prettyFileHandler]
+class=FileHandler
+level=INFO
+formatter=simpleFormatter
+args=("/tmp/mistral_wf_trace.log",)
+
+
+[formatter_simpleFormatter]
+format=%(asctime)s - WF - %(message)s
+datefmt=%y-%m-%d %H:%M:%S

mistral/config.py

@@ -85,6 +85,12 @@ launch_opt = cfg.StrOpt(
     help='Specifies which mistral server to start by the launch script.'
 )
 
+
+wf_trace_log_name_opt = cfg.StrOpt('workflow_trace_log_name',
+                                   default='workflow_trace',
+                                   help='Logger name for pretty '
+                                   'workflow trace output.')
+
 CONF = cfg.CONF
 
 CONF.register_opts(api_opts, group='api')
@@ -94,6 +100,7 @@ CONF.register_opts(auth_token.opts, group='keystone')
 CONF.register_opts(db_opts, group='database')
 CONF.register_opts(rabbit_opts, group='rabbit')
 CONF.register_opts(executor_opts, group='executor')
+CONF.register_opt(wf_trace_log_name_opt)
 
 CONF.register_cli_opt(use_debugger)
 CONF.register_cli_opt(launch_opt)

mistral/engine/abstract_engine.py

@@ -17,6 +17,8 @@
 import abc
 import eventlet
 
+from oslo.config import cfg
+
 from mistral.openstack.common import log as logging
 from mistral.db import api as db_api
 from mistral import dsl_parser as parser
@@ -28,6 +30,7 @@ from mistral.engine import retry
 
 
 LOG = logging.getLogger(__name__)
+WORKFLOW_TRACE = logging.getLogger(cfg.CONF.workflow_trace_log_name)
 
 
 class AbstractEngine(object):
@@ -42,6 +45,9 @@ class AbstractEngine(object):
     def start_workflow_execution(cls, workbook_name, task_name, context):
         db_api.start_tx()
 
+        WORKFLOW_TRACE.info("New execution started - [workbook_name = '%s', "
+                            "task_name = '%s']" % (workbook_name, task_name))
+
         # Persist execution and tasks in DB.
         try:
             workbook = cls._get_workbook(workbook_name)
@@ -86,6 +92,13 @@ class AbstractEngine(object):
             #TODO(rakhmerov): validate state transition
             task = db_api.task_get(workbook_name, execution_id, task_id)
 
+            wf_trace_msg = "Task '%s', [%s -> %s" % (task['name'],
+                                                     task['state'], state)
+
+            wf_trace_msg += ']' if state == states.ERROR \
+                else ", result = %s]" % result
+            WORKFLOW_TRACE.info(wf_trace_msg)
+
             task_output = data_flow.get_task_output(task, result)
 
             # Update task state.
@@ -268,6 +281,11 @@ class AbstractEngine(object):
                 execution = db_api.execution_get(workbook_name, execution_id)
 
                 # Change state from DELAYED to IDLE to unblock processing.
+
+                WORKFLOW_TRACE.info("Task '%s' [%s -> %s]"
+                                    % (task['name'],
+                                       task['state'], states.IDLE))
+
                 db_task = db_api.task_update(workbook_name,
                                              execution_id,
                                              task['id'],

mistral/engine/retry.py

@@ -14,8 +14,14 @@
 #    See the License for the specific language governing permissions and
 #    limitations under the License.
 
+from oslo.config import cfg
+
 from mistral import expressions
 from mistral.engine import states
+from mistral.openstack.common import log as logging
+
+
+WORKFLOW_TRACE = logging.getLogger(cfg.CONF.workflow_trace_log_name)
 
 
 def get_task_runtime(task_spec, state=states.IDLE, outbound_context=None,
@@ -46,6 +52,8 @@ def get_task_runtime(task_spec, state=states.IDLE, outbound_context=None,
     if outbound_context is None:
         outbound_context = {}
 
+    wf_trace_msg = "Task '%s' [%s -> " % (task_spec.name, state)
+
     retry_no = -1
     if "retry_no" in task_runtime_context:
         retry_no = task_runtime_context["retry_no"]
@@ -59,6 +67,8 @@ def get_task_runtime(task_spec, state=states.IDLE, outbound_context=None,
         state = states.DELAYED if delay > 0 else states.IDLE
         retry_no += 1
 
+    WORKFLOW_TRACE.info(wf_trace_msg + "%s, delay = %s sec]" % (state, delay))
+
     task_runtime_context["retry_no"] = retry_no
 
     return state, task_runtime_context

mistral/engine/scalable/executor/server.py

@@ -14,6 +14,8 @@
 #    See the License for the specific language governing permissions and
 #    limitations under the License.
 
+from oslo.config import cfg
+
 from mistral.openstack.common import log as logging
 from mistral.db import api as db_api
 from mistral import exceptions as exc
@@ -23,6 +25,7 @@ from mistral.actions import action_factory as a_f
 
 
 LOG = logging.getLogger(__name__)
+WORKFLOW_TRACE = logging.getLogger(cfg.CONF.workflow_trace_log_name)
 
 
 class Executor(object):
@@ -119,6 +122,11 @@ class Executor(object):
             # Update the state to running before performing action. The
             # do_task_action assigns state to the task which is the appropriate
             # value to preserve.
+
+            WORKFLOW_TRACE.info("Task '%s' [%s -> %s]" % (db_task['name'],
+                                                          db_task['state'],
+                                                          states.RUNNING))
+
             db_api.task_update(task['workbook_name'],
                                task['execution_id'],
                                task['id'],

mistral/tests/base.py

@@ -14,23 +14,29 @@
 #    See the License for the specific language governing permissions and
 #    limitations under the License.
 
-import tempfile
-
-import unittest2
-import pkg_resources as pkg
 import os
-from mistral import version
-from mistral.db.sqlalchemy import api as db_api
-from mistral.openstack.common.db.sqlalchemy import session
+import tempfile
+import unittest2
 
-from stevedore import driver
-from oslo.config import cfg
 from oslo import messaging
+from oslo.config import cfg
 from oslo.messaging import transport
+import pkg_resources as pkg
+from stevedore import driver
 
+from mistral.openstack.common import importutils
+
+
+# We need to make sure that all configuration properties are registered.
+importutils.import_module("mistral.config")
+
+
+from mistral.db.sqlalchemy import api as db_api
 from mistral.engine import engine
 from mistral.engine.scalable.executor import server
 from mistral.engine.scalable import engine as concrete_engine
+from mistral.openstack.common.db.sqlalchemy import session
+from mistral import version
 
 
 RESOURCES_PATH = 'tests/resources/'

mistral/tests/unit/engine/scalable/test_engine.py

@@ -18,7 +18,6 @@ import mock
 from oslo.config import cfg
 
 from mistral.openstack.common import log as logging
-from mistral.openstack.common import importutils
 from mistral.db import api as db_api
 from mistral.actions import std_actions
 from mistral import expressions
@@ -26,8 +25,7 @@ from mistral.engine.scalable import engine
 from mistral.engine import states
 from mistral.tests import base
 
-# We need to make sure that all configuration properties are registered.
-importutils.import_module("mistral.config")
+
 LOG = logging.getLogger(__name__)
 
 WB_NAME = "my_workbook"

mistral/tests/unit/engine/test_data_flow.py

@@ -19,7 +19,6 @@ import mock
 from oslo.config import cfg
 
 from mistral.openstack.common import log as logging
-from mistral.openstack.common import importutils
 from mistral.tests import base
 from mistral.db import api as db_api
 from mistral.engine.scalable import engine
@@ -29,8 +28,7 @@ from mistral.utils.openstack import keystone
 
 # TODO(rakhmerov): add more tests
 
-# We need to make sure that all configuration properties are registered.
-importutils.import_module("mistral.config")
+
 LOG = logging.getLogger(__name__)
 
 TOKEN = "123ab"

mistral/tests/unit/engine/test_task_retry.py

@@ -22,7 +22,6 @@ from oslo.config import cfg
 
 from mistral import exceptions as exc
 from mistral.openstack.common import log as logging
-from mistral.openstack.common import importutils
 from mistral.tests import base
 from mistral.db import api as db_api
 from mistral.engine.scalable import engine
@@ -30,8 +29,6 @@ from mistral.actions import std_actions
 from mistral.engine import states
 from mistral import dsl_parser as parser
 
-# We need to make sure that all configuration properties are registered.
-importutils.import_module("mistral.config")
 
 LOG = logging.getLogger(__name__)
 

mistral/tests/unit/test_scheduler.py

@@ -20,7 +20,7 @@ from datetime import timedelta
 from mistral.openstack.common import timeutils
 
 from mistral.services import scheduler as s
-from mistral.tests import base as test_base
+from mistral.tests import base
 
 
 SAMPLE_TRIGGER = {
@@ -32,7 +32,7 @@ SAMPLE_TRIGGER = {
 }
 
 
-class SchedulerTest(test_base.DbTestCase):
+class SchedulerTest(base.DbTestCase):
     def setUp(self):
         super(SchedulerTest, self).setUp()
         self.wb_name = "My workbook"