Merge "Logging API for MuranoPL"

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

@@ -43,6 +43,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))