Logging API for MuranoPL

Add new API calls that will provide logging and can be
consumed by MuranoPL workflows. It will improve debuggability.
Application author can use logs to improve application quality.

Implements: blueprint logging-api-for-muranopl
Change-Id: I747cf7f5fca20960f2304605e1c7241f465f5dc1

etc/murano/logging.conf.sample

@@ -1,15 +1,20 @@
 [loggers]
-keys: root,murano
+keys: root,murano,applications
 
 [handlers]
-keys: watchedfile, stderr, stdout, null
+keys: watchedfile, applications, stderr, stdout, null
 
 [formatters]
 keys: context, default
 
 [logger_root]
 level = WARNING
-handlers = null
+handlers = watchedfile
+
+[logger_applications]
+level = DEBUG
+handlers = applications
+qualname = applications
 
 [logger_murano]
 level = INFO
@@ -64,11 +69,15 @@ class: handlers.WatchedFileHandler
 args: ('murano.log',)
 formatter: context
 
+[handler_applications]
+class: handlers.WatchedFileHandler
+args: ('applications.log',)
+formatter: context
+
 [formatter_default]
 format = %(message)s
-
 [formatter_context]
 class: oslo_log.formatters.ContextFormatter
 args: (datefmt=datefmt)
 format: %(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user)s %(tenant)s] %(instance)s%(message)s
-datefmt: %Y-%m-%d %H:%M:%S
+datefmt: %Y-%m-%d %H:%M:%S

meta/io.murano/Classes/system/Logger.yaml

@@ -0,0 +1,5 @@
+# Blank class for in-python system libraries, for caching purposes
+Namespaces:
+  =: io.murano.system
+
+Name: Logger

meta/io.murano/manifest.yaml

@@ -41,6 +41,7 @@ Classes:
   io.murano.system.HeatStack: system/HeatStack.yaml
   io.murano.system.Resources: system/Resources.yaml
   io.murano.system.InstanceNotifier: system/InstanceNotifier.yaml
+  io.murano.system.Logger: system/Logger.yaml
   io.murano.system.StatusReporter: system/StatusReporter.yaml
   io.murano.system.NetworkExplorer: system/NetworkExplorer.yaml
   io.murano.system.SecurityGroupManager: system/SecurityGroupManager.yaml

murano/dsl/yaql_functions.py

@@ -162,6 +162,15 @@ def not_equal(obj1, obj2):
     return obj1 is not obj2
 
 
+@specs.parameter('logger_name', yaqltypes.String(True))
+def logger(context, logger_name):
+    """Instantiate Logger"""
+    log = yaql_integration.call_func(
+        context, 'new', 'io.murano.system.Logger',
+        logger_name=logger_name)
+    return log
+
+
 def register(context):
     context.register_function(cast)
     context.register_function(new)
@@ -179,3 +188,4 @@ def register(context):
     context.register_function(ns_resolve)
     context.register_function(equal)
     context.register_function(not_equal)
+    context.register_function(logger)

murano/engine/system/logger.py

@@ -0,0 +1,105 @@
+# Copyright (c) 2015 Mirantis Inc.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#    http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
+# implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import exceptions
+
+from oslo_log import log as logging
+from yaql.language import specs
+from yaql.language import yaqltypes
+
+from murano.dsl import dsl
+
+LOG = logging.getLogger(__name__)
+NAME_TEMPLATE = 'applications.{0}'
+
+inject_format = specs.inject(
+    '_Logger__yaql_format_function',
+    yaqltypes.Delegate('format'))
+
+
+@dsl.name('io.murano.system.Logger')
+class Logger(object):
+    """Logger object for MuranoPL.
+    Instance of this object returned by 'logger' YAQL function
+    and should not be instantiated directly
+    """
+
+    def __init__(self, logger_name):
+        self._underlying_logger = logging.getLogger(
+            NAME_TEMPLATE.format(logger_name))
+
+    @inject_format
+    def trace(__self, __yaql_format_function, __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.trace,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def debug(__self, __yaql_format_function, __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.debug,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def info(__self, __yaql_format_function, __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.info,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def warning(__self, __yaql_format_function, __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.warning,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def error(__self, __yaql_format_function, __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.error,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def critical(__self, __yaql_format_function,
+                 __message, *args, **kwargs):
+        __self._log(__self._underlying_logger.critical,
+                    __yaql_format_function, __message, args, kwargs)
+
+    @inject_format
+    def exception(__self, __yaql_format_function,
+                  __exc, __message, *args, **kwargs):
+        """Print error message and stacktrace"""
+        stack_trace_message = '\n'.join([
+            __self._format_without_exceptions(
+                __yaql_format_function, __message, args, kwargs),
+            __exc['stackTrace']().toString()
+        ])
+        __self._underlying_logger.error(stack_trace_message)
+
+    def _format_without_exceptions(self, format_function,
+                                   message, args, kwargs):
+        """Wrap YAQL function "format" to suppress exceptions
+        whose may be raised when message cannot be formatted
+        due to invalid parameters provided
+        We do not want to break program workflow
+        even formatting parameters are incorrect
+        """
+        try:
+            message = format_function(message, *args, **kwargs)
+        except (exceptions.IndexError, exceptions.KeyError):
+            # NOTE(akhivin): we do not want break program workflow
+            # even formatting parameters are incorrect
+            self._underlying_logger.warning(
+                'Can not format string: {0}'.format(message))
+        return message
+
+    def _log(self, log_function, yaql_format_function, message, args, kwargs):
+        log_function(
+            self._format_without_exceptions(
+                yaql_format_function, message, args, kwargs))

murano/engine/system/system_objects.py

@@ -17,6 +17,7 @@ from murano.engine.system import agent
 from murano.engine.system import agent_listener
 from murano.engine.system import heat_stack
 from murano.engine.system import instance_reporter
+from murano.engine.system import logger
 from murano.engine.system import mistralclient
 from murano.engine.system import net_explorer
 from murano.engine.system import resource_manager
@@ -38,3 +39,4 @@ def register(class_loader, package_loader):
     class_loader.import_class(instance_reporter.InstanceReportNotifier)
     class_loader.import_class(status_reporter.StatusReporter)
     class_loader.import_class(net_explorer.NetworkExplorer)
+    class_loader.import_class(logger.Logger)

murano/tests/unit/dsl/meta/TestLogger.yaml

@@ -0,0 +1,101 @@
+
+Namespaces:
+  sys: io.murano.system
+
+Name: TestLogger
+
+Methods:
+  testCreate:
+    Body:
+      - Return: logger('name')
+
+  testDebug:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.debug('str')
+      - $log.debug('str', 1)
+      - $log.debug('str {0}', message)
+      - $log.debug('str {message}', message=>message)
+      - $log.debug('str {message}{0}')
+
+  testTrace:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.trace('str')
+      - $log.trace('str', 1)
+      - $log.trace('str {0}', message)
+      - $log.trace('str {message}', message=>message)
+      - $log.trace('str {message}{0}')
+
+  testInfo:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.info('str')
+      - $log.info('str', 1)
+      - $log.info('str {0}', message)
+      - $log.info('str {message}', message=>message)
+      - $log.info('str {message}{0}')
+
+  testWarning:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.warning('str')
+      - $log.warning('str', 1)
+      - $log.warning('str {0}', message)
+      - $log.warning('str {message}', message=>message)
+      - $log.warning('str {message}{0}')
+
+  testError:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.error('str')
+      - $log.error('str', 1)
+      - $log.error('str {0}', message)
+      - $log.error('str {message}', message=>message)
+      - $log.error('str {message}{0}')
+
+  testCritical:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      - $log.critical('str')
+      - $log.critical('str', 1)
+      - $log.critical('str {0}', message)
+      - $log.critical('str {message}', message=>message)
+      - $log.critical('str {message}{0}')
+
+  testException:
+    Arguments:
+      - log:
+          Contract: $.class(sys:Logger).notNull()
+    Body:
+      Try:
+        - $.doThrow()
+      Catch:
+        With: exceptionName
+        As: e
+        Do:
+          - $log.exception($e, 'str')
+          - $log.exception($e, 'str', 1)
+          - $log.exception($e, 'str {0}', message)
+          - $log.exception($e, 'str {message}', message=>message)
+          - $log.exception($e, 'str {message}{0}')
+      Finally:
+
+
+  doThrow:
+    Body:
+      - Throw: exceptionName
+        Message: exception message
+

murano/tests/unit/dsl/test_logger.py

@@ -0,0 +1,139 @@
+# Copyright (c) 2015 Mirantis, Inc.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+from mock import ANY
+from mock import MagicMock
+from mock.mock import call
+
+from murano.engine.system import logger
+from murano.tests.unit.dsl.foundation import object_model as om
+from murano.tests.unit.dsl.foundation import test_case
+
+
+class TestLogger(test_case.DslTestCase):
+
+    FORMAT_CALLS = [
+        call(ANY, 'str', (), {}),
+        call(ANY, 'str', (1,), {}),
+        call(ANY, 'str {0}', ('message',), {}),
+        call(ANY, 'str {message}', (), {'message': 'message'}),
+        call(ANY, 'str {message}{0}', (), {})]
+
+    LOG_CALLS = FORMAT_CALLS
+
+    def setUp(self):
+        super(TestLogger, self).setUp()
+        self._runner = self.new_runner(om.Object('TestLogger'))
+        self.class_loader.import_class(logger.Logger)
+
+    def test_create(self):
+        cls = self.class_loader.get_class('io.murano.system.Logger')
+        logger_instance = self._runner.testCreate()
+        self.assertTrue(
+            cls.is_compatible(logger_instance),
+            'Function should return io.murano.system.Logger instance')
+
+    def _create_logger_mock(self):
+        logger_instance = self._runner.testCreate()
+        logger_ext = logger_instance.extension
+
+        underlying_logger_mock = MagicMock()
+        logger_ext._underlying_logger = underlying_logger_mock
+        logger_ext._underlying_logger.return_value = None
+
+        format_mock = MagicMock(return_value='format_mock')
+        # do not verify number of conversions to string
+        format_mock.__str__ = MagicMock(return_value='format_mock')
+        format_mock.__unicode__ = MagicMock(return_value='format_mock')
+
+        logger_ext._format_without_exceptions = format_mock
+
+        return logger_instance, format_mock, underlying_logger_mock
+
+    def test_trace(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.trace = log_method
+        self._runner.testTrace(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))
+
+    def test_debug(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.debug = log_method
+        self._runner.testDebug(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))
+
+    def test_info(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.info = log_method
+        self._runner.testInfo(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))
+
+    def test_warning(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.warning = log_method
+        self._runner.testWarning(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))
+
+    def test_error(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.error = log_method
+        self._runner.testError(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.FORMAT_CALLS))
+
+    def test_critical(self):
+        logger_instance, format_mock, underlying_logger_mock \
+            = self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.critical = log_method
+        self._runner.testCritical(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))
+
+    def test_exception(self):
+        logger_instance, format_mock, underlying_logger_mock = \
+            self._create_logger_mock()
+        log_method = MagicMock()
+
+        underlying_logger_mock.error = log_method
+        self._runner.testException(logger_instance)
+
+        format_mock.assert_has_calls(self.FORMAT_CALLS, any_order=False)
+        self.assertEqual(log_method.call_count, len(self.LOG_CALLS))