diff --git a/etc/wf_trace_logging.conf.example b/etc/wf_trace_logging.conf.example new file mode 100644 index 000000000..f73d20c82 --- /dev/null +++ b/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 \ No newline at end of file diff --git a/mistral/config.py b/mistral/config.py index 50969da81..b3fdb509b 100644 --- a/mistral/config.py +++ b/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) diff --git a/mistral/engine/abstract_engine.py b/mistral/engine/abstract_engine.py index 101ac546d..b009a866c 100644 --- a/mistral/engine/abstract_engine.py +++ b/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'], diff --git a/mistral/engine/retry.py b/mistral/engine/retry.py index c7fbf8fdd..db20f4307 100644 --- a/mistral/engine/retry.py +++ b/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 diff --git a/mistral/engine/scalable/executor/server.py b/mistral/engine/scalable/executor/server.py index 7a4cee0c2..020083c38 100644 --- a/mistral/engine/scalable/executor/server.py +++ b/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'], diff --git a/mistral/tests/base.py b/mistral/tests/base.py index 14ba6a326..63a0da42c 100644 --- a/mistral/tests/base.py +++ b/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/' diff --git a/mistral/tests/unit/engine/scalable/test_engine.py b/mistral/tests/unit/engine/scalable/test_engine.py index 8330682b5..12c16fb0b 100644 --- a/mistral/tests/unit/engine/scalable/test_engine.py +++ b/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" diff --git a/mistral/tests/unit/engine/test_data_flow.py b/mistral/tests/unit/engine/test_data_flow.py index 455058ce5..b1a4ecb2d 100644 --- a/mistral/tests/unit/engine/test_data_flow.py +++ b/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" diff --git a/mistral/tests/unit/engine/test_task_retry.py b/mistral/tests/unit/engine/test_task_retry.py index 83b7fd195..1b73d47a1 100644 --- a/mistral/tests/unit/engine/test_task_retry.py +++ b/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__) diff --git a/mistral/tests/unit/test_scheduler.py b/mistral/tests/unit/test_scheduler.py index 1a878907c..d34670262 100644 --- a/mistral/tests/unit/test_scheduler.py +++ b/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"