Add common logging and notification.

This code is migrated from Nova, and will soon replace it.

Change-Id: I2dacac3ef251d419c7049154f6aaf0c18fdb9bb4

4 files changed, 553 insertions, 0 deletions

diff --git a/tests/unit/notifier/__init__.py b/tests/unit/notifier/__init__.py
new file mode 100644
index 0000000..482d54e
--- /dev/null
+++ b/tests/unit/notifier/__init__.py
@@ -0,0 +1,14 @@
+# Copyright 2011 OpenStack LLC.
+# All Rights Reserved.
+#
+#    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.
diff --git a/tests/unit/notifier/test_list_notifier.py b/tests/unit/notifier/test_list_notifier.py
new file mode 100644
index 0000000..5708a43
--- /dev/null
+++ b/tests/unit/notifier/test_list_notifier.py
@@ -0,0 +1,135 @@
+# Copyright 2011 OpenStack LLC.
+# All Rights Reserved.
+#
+#    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 openstack.common import log as logging
+from openstack.common.notifier import api
+from openstack.common.notifier import list_notifier
+from openstack.common.notifier import log_notifier
+from openstack.common.notifier import no_op_notifier
+from tests import utils as test_utils
+
+
+class SimpleNotifier(object):
+    def __init__(self):
+        self.notified = False
+
+    def notify(self, *args):
+        self.notified = True
+
+
+class NotifierListTestCase(test_utils.BaseTestCase):
+    """Test case for notifications"""
+
+    def setUp(self):
+        super(NotifierListTestCase, self).setUp()
+        list_notifier._reset_drivers()
+        # Mock log to add one to exception_count when log.exception is called
+
+        def mock_exception(cls, *args):
+            self.exception_count += 1
+
+        self.exception_count = 0
+        list_notifier_log = logging.getLogger(
+                            'openstack.common.notifier.list_notifier')
+        self.stubs.Set(list_notifier_log, "exception", mock_exception)
+        # Mock no_op notifier to add one to notify_count when called.
+
+        def mock_notify(cls, *args):
+            self.notify_count += 1
+
+        self.notify_count = 0
+        self.stubs.Set(no_op_notifier, 'notify', mock_notify)
+        # Mock log_notifier to raise RuntimeError when called.
+
+        def mock_notify2(cls, *args):
+            raise RuntimeError("Bad notifier.")
+
+        self.stubs.Set(log_notifier, 'notify', mock_notify2)
+
+    def tearDown(self):
+        list_notifier._reset_drivers()
+        super(NotifierListTestCase, self).tearDown()
+
+    def test_send_notifications_successfully(self):
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.list_notifier',
+                   list_notifier_drivers=[
+                       'openstack.common.notifier.no_op_notifier',
+                       'openstack.common.notifier.no_op_notifier'])
+        api.notify('contextarg', 'publisher_id', 'event_type',
+                api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 2)
+        self.assertEqual(self.exception_count, 0)
+
+    def test_send_notifications_with_errors(self):
+
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.list_notifier',
+                   list_notifier_drivers=[
+                       'openstack.common.notifier.no_op_notifier',
+                       'openstack.common.notifier.log_notifier'])
+        api.notify('contextarg', 'publisher_id',
+                'event_type', api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 1)
+        self.assertEqual(self.exception_count, 1)
+
+    def test_when_driver_fails_to_import(self):
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.list_notifier',
+                   list_notifier_drivers=[
+                       'openstack.common.notifier.no_op_notifier',
+                       'openstack.common.notifier.logo_notifier',
+                       'fdsjgsdfhjkhgsfkj'])
+        api.notify('contextarg', 'publisher_id',
+                'event_type', api.WARN, dict(a=3))
+        self.assertEqual(self.exception_count, 2)
+        self.assertEqual(self.notify_count, 1)
+
+    def test_adding_and_removing_notifier_object(self):
+        self.notifier_object = SimpleNotifier()
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.list_notifier',
+                   list_notifier_drivers=[
+                       'openstack.common.notifier.no_op_notifier'])
+
+        list_notifier.add_driver(self.notifier_object)
+        api.notify(None, 'publisher_id', 'event_type',
+                api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 1)
+        self.assertTrue(self.notifier_object.notified)
+
+        self.notifier_object.notified = False
+        list_notifier.remove_driver(self.notifier_object)
+
+        api.notify(None, 'publisher_id', 'event_type',
+                api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 2)
+        self.assertFalse(self.notifier_object.notified)
+
+    def test_adding_and_removing_notifier_module(self):
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.list_notifier',
+                   list_notifier_drivers=[])
+
+        list_notifier.add_driver('openstack.common.notifier.no_op_notifier')
+        api.notify(None, 'publisher_id', 'event_type',
+                api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 1)
+
+        list_notifier.remove_driver('openstack.common.notifier.no_op_notifier')
+
+        api.notify(None, 'publisher_id', 'event_type',
+                api.WARN, dict(a=3))
+        self.assertEqual(self.notify_count, 1)
diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py
new file mode 100644
index 0000000..f417db5
--- /dev/null
+++ b/tests/unit/test_log.py
@@ -0,0 +1,218 @@
+import cStringIO
+import json
+import logging
+import sys
+
+from openstack.common import context
+from openstack.common import cfg
+from openstack.common import log
+from openstack.common.notifier import api as notifier
+from openstack.common.notifier import list_notifier
+from tests import utils as test_utils
+
+CONF = cfg.CONF
+
+
+def _fake_context():
+    return context.RequestContext(1, 1)
+
+
+class LoggerTestCase(test_utils.BaseTestCase):
+    def setUp(self):
+        super(LoggerTestCase, self).setUp()
+        self.log = log.getLogger()
+
+    def test_handlers_have_legacy_formatter(self):
+        formatters = []
+        for h in self.log.logger.handlers:
+            f = h.formatter
+            if isinstance(f, log.LegacyFormatter):
+                formatters.append(f)
+        self.assert_(formatters)
+        self.assertEqual(len(formatters), len(self.log.logger.handlers))
+
+    def test_handles_context_kwarg(self):
+        self.log.info("foo", context=_fake_context())
+        self.assert_(True)  # didn't raise exception
+
+    def test_audit_handles_context_arg(self):
+        self.log.audit("foo", context=_fake_context())
+        self.assert_(True)  # didn't raise exception
+
+    def test_will_be_verbose_if_verbose_flag_set(self):
+        self.config(verbose=True)
+        log.setup()
+        self.assertEqual(logging.DEBUG, self.log.logger.getEffectiveLevel())
+
+    def test_will_not_be_verbose_if_verbose_flag_not_set(self):
+        self.config(verbose=False)
+        log.setup()
+        self.assertEqual(logging.INFO, self.log.logger.getEffectiveLevel())
+
+    def test_no_logging_via_module(self):
+        for func in ('critical', 'error', 'exception', 'warning', 'warn',
+                     'info', 'debug', 'log', 'audit'):
+            self.assertRaises(AttributeError, getattr, log, func)
+
+
+class LogHandlerTestCase(test_utils.BaseTestCase):
+    def test_log_path_logdir(self):
+        self.config(logdir='/some/path', logfile=None)
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
+                         '/some/path/foo-bar.log')
+
+    def test_log_path_logfile(self):
+        self.config(logfile='/some/path/foo-bar.log')
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
+                         '/some/path/foo-bar.log')
+
+    def test_log_path_none(self):
+        self.config(logdir=None, logfile=None)
+        self.assertTrue(log._get_log_file_path(binary='foo-bar') is None)
+
+    def test_log_path_logfile_overrides_logdir(self):
+        self.config(logdir='/some/other/path',
+                   logfile='/some/path/foo-bar.log')
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
+                         '/some/path/foo-bar.log')
+
+
+class PublishErrorsHandlerTestCase(test_utils.BaseTestCase):
+    """Tests for log.PublishErrorsHandler"""
+    def setUp(self):
+        super(PublishErrorsHandlerTestCase, self).setUp()
+        self.publiserrorshandler = log.PublishErrorsHandler(logging.ERROR)
+
+    def test_emit_cfg_list_notifier_drivers_in_flags(self):
+        self.stub_flg = False
+
+        def fake_notifier(*args, **kwargs):
+            self.stub_flg = True
+
+        self.stubs.Set(notifier, 'notify', fake_notifier)
+        logrecord = logging.LogRecord('name', 'WARN', '/tmp', 1,
+                                      'Message', None, None)
+        self.publiserrorshandler.emit(logrecord)
+        self.assertTrue(self.stub_flg)
+
+    def test_emit_cfg_log_notifier_in_list_notifier_drivers(self):
+        self.config(list_notifier_drivers=[
+            'openstack.common.notifier.rabbit_notifier',
+            'openstack.common.notifier.log_notifier'])
+        self.stub_flg = True
+
+        def fake_notifier(*args, **kwargs):
+            self.stub_flg = False
+
+        self.stubs.Set(notifier, 'notify', fake_notifier)
+        logrecord = logging.LogRecord('name', 'WARN', '/tmp', 1,
+                                      'Message', None, None)
+        self.publiserrorshandler.emit(logrecord)
+        self.assertTrue(self.stub_flg)
+
+
+class LoggerTestCase(test_utils.BaseTestCase):
+    def setUp(self):
+        super(LoggerTestCase, self).setUp()
+        levels = CONF.default_log_levels
+        levels.append("nova-test=AUDIT")
+        self.config(default_log_levels=levels,
+                   verbose=True)
+        log.setup('testing')
+        self.log = log.getLogger('nova-test')
+
+    def test_has_level_from_flags(self):
+        self.assertEqual(logging.AUDIT, self.log.logger.getEffectiveLevel())
+
+    def test_child_log_has_level_of_parent_flag(self):
+        l = log.getLogger('nova-test.foo')
+        self.assertEqual(logging.AUDIT, l.logger.getEffectiveLevel())
+
+
+class JSONFormatterTestCase(test_utils.BaseTestCase):
+    def setUp(self):
+        super(JSONFormatterTestCase, self).setUp()
+        self.log = log.getLogger('test-json')
+        self.stream = cStringIO.StringIO()
+        handler = logging.StreamHandler(self.stream)
+        handler.setFormatter(log.JSONFormatter())
+        self.log.logger.addHandler(handler)
+        self.log.logger.setLevel(logging.DEBUG)
+
+    def test_json(self):
+        test_msg = 'This is a %(test)s line'
+        test_data = {'test': 'log'}
+        self.log.debug(test_msg, test_data)
+
+        data = json.loads(self.stream.getvalue())
+        self.assertTrue(data)
+        self.assertTrue('extra' in data)
+        self.assertEqual('test-json', data['name'])
+
+        self.assertEqual(test_msg % test_data, data['message'])
+        self.assertEqual(test_msg, data['msg'])
+        self.assertEqual(test_data, data['args'])
+
+        self.assertEqual('test_log.py', data['filename'])
+        self.assertEqual('test_json', data['funcname'])
+
+        self.assertEqual('DEBUG', data['levelname'])
+        self.assertEqual(logging.DEBUG, data['levelno'])
+        self.assertFalse(data['traceback'])
+
+    def test_json_exception(self):
+        test_msg = 'This is %s'
+        test_data = 'exceptional'
+        try:
+            raise Exception('This is exceptional')
+        except Exception:
+            self.log.exception(test_msg, test_data)
+
+        data = json.loads(self.stream.getvalue())
+        self.assertTrue(data)
+        self.assertTrue('extra' in data)
+        self.assertEqual('test-json', data['name'])
+
+        self.assertEqual(test_msg % test_data, data['message'])
+        self.assertEqual(test_msg, data['msg'])
+        self.assertEqual([test_data], data['args'])
+
+        self.assertEqual('ERROR', data['levelname'])
+        self.assertEqual(logging.ERROR, data['levelno'])
+        self.assertTrue(data['traceback'])
+
+
+class LegacyFormatterTestCase(test_utils.BaseTestCase):
+    def setUp(self):
+        super(LegacyFormatterTestCase, self).setUp()
+        self.config(logging_context_format_string="HAS CONTEXT "
+                                                  "[%(request_id)s]: "
+                                                  "%(message)s",
+                    logging_default_format_string="NOCTXT: %(message)s",
+                    logging_debug_format_suffix="--DBG")
+        self.log = log.getLogger()
+        self.stream = cStringIO.StringIO()
+        self.handler = logging.StreamHandler(self.stream)
+        self.handler.setFormatter(log.LegacyFormatter())
+        self.log.logger.addHandler(self.handler)
+        self.level = self.log.logger.getEffectiveLevel()
+        self.log.logger.setLevel(logging.DEBUG)
+
+    def tearDown(self):
+        self.log.logger.setLevel(self.level)
+        self.log.logger.removeHandler(self.handler)
+        super(LegacyFormatterTestCase, self).tearDown()
+
+    def test_uncontextualized_log(self):
+        self.log.info("foo")
+        self.assertEqual("NOCTXT: foo\n", self.stream.getvalue())
+
+    def test_contextualized_log(self):
+        ctxt = _fake_context()
+        self.log.info("bar", context=ctxt)
+        expected = "HAS CONTEXT [%s]: bar\n" % ctxt.request_id
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_debugging_log(self):
+        self.log.debug("baz")
+        self.assertEqual("NOCTXT: baz --DBG\n", self.stream.getvalue())
diff --git a/tests/unit/test_notifier.py b/tests/unit/test_notifier.py
new file mode 100644
index 0000000..4e1c812
--- /dev/null
+++ b/tests/unit/test_notifier.py
@@ -0,0 +1,186 @@
+# Copyright 2011 OpenStack LLC.
+# All Rights Reserved.
+#
+#    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 openstack.common import cfg
+from openstack.common import context
+from openstack.common import log
+from openstack.common.notifier import api as notifier_api
+from openstack.common.notifier import no_op_notifier
+from openstack.common.notifier import rabbit_notifier
+from openstack.common import rpc
+from tests import utils as test_utils
+
+
+ctxt = context.get_admin_context()
+ctxt2 = context.get_admin_context()
+
+
+class NotifierTestCase(test_utils.BaseTestCase):
+    """Test case for notifications"""
+    def setUp(self):
+        super(NotifierTestCase, self).setUp()
+        self.config(notification_driver='openstack.common.'
+                                        'notifier.no_op_notifier')
+        self.config(default_publisher_id='publisher')
+
+    def test_send_notification(self):
+        self.notify_called = False
+
+        def mock_notify(cls, *args):
+            self.notify_called = True
+
+        self.stubs.Set(no_op_notifier, 'notify',
+                mock_notify)
+
+        notifier_api.notify(ctxt, 'publisher_id', 'event_type',
+                            notifier_api.WARN, dict(a=3))
+        self.assertEqual(self.notify_called, True)
+
+    def test_verify_message_format(self):
+        """A test to ensure changing the message format is prohibitively
+        annoying"""
+
+        def message_assert(context, message):
+            fields = [('publisher_id', 'publisher_id'),
+                      ('event_type', 'event_type'),
+                      ('priority', 'WARN'),
+                      ('payload', dict(a=3))]
+            for k, v in fields:
+                self.assertEqual(message[k], v)
+            self.assertTrue(len(message['message_id']) > 0)
+            self.assertTrue(len(message['timestamp']) > 0)
+            self.assertEqual(context, ctxt)
+
+        self.stubs.Set(no_op_notifier, 'notify',
+                message_assert)
+        notifier_api.notify(ctxt, 'publisher_id', 'event_type',
+                            notifier_api.WARN, dict(a=3))
+
+    def test_send_rabbit_notification(self):
+        self.stubs.Set(cfg.CONF, 'notification_driver',
+                'openstack.common.notifier.rabbit_notifier')
+        self.mock_notify = False
+
+        def mock_notify(cls, *args):
+            self.mock_notify = True
+
+        self.stubs.Set(rpc, 'notify', mock_notify)
+        notifier_api.notify(ctxt, 'publisher_id', 'event_type',
+                            notifier_api.WARN, dict(a=3))
+
+        self.assertEqual(self.mock_notify, True)
+
+    def test_invalid_priority(self):
+        self.assertRaises(notifier_api.BadPriorityException,
+                notifier_api.notify, ctxt, 'publisher_id',
+                'event_type', 'not a priority', dict(a=3))
+
+    def test_rabbit_priority_queue(self):
+        self.stubs.Set(cfg.CONF, 'notification_driver',
+                'openstack.common.notifier.rabbit_notifier')
+        self.stubs.Set(cfg.CONF, 'notification_topics',
+                       ['testnotify', ])
+
+        self.test_topic = None
+
+        def mock_notify(context, topic, msg):
+            self.test_topic = topic
+
+        self.stubs.Set(rpc, 'notify', mock_notify)
+        notifier_api.notify(ctxt, 'publisher_id',
+                            'event_type', 'DEBUG', dict(a=3))
+        self.assertEqual(self.test_topic, 'testnotify.debug')
+
+    def test_error_notification(self):
+        self.stubs.Set(cfg.CONF, 'notification_driver',
+            'openstack.common.notifier.rabbit_notifier')
+        self.stubs.Set(cfg.CONF, 'publish_errors', True)
+        LOG = log.getLogger('common')
+        log.setup(None)
+        msgs = []
+
+        def mock_notify(context, topic, data):
+            msgs.append(data)
+
+        self.stubs.Set(rpc, 'notify', mock_notify)
+        LOG.error('foo')
+        self.assertEqual(1, len(msgs))
+        msg = msgs[0]
+        self.assertEqual(msg['event_type'], 'error_notification')
+        self.assertEqual(msg['priority'], 'ERROR')
+        self.assertEqual(msg['payload']['error'], 'foo')
+
+    def test_send_notification_by_decorator(self):
+        self.notify_called = False
+
+        def example_api(arg1, arg2):
+            return arg1 + arg2
+
+        example_api = notifier_api.notify_decorator(
+                            'example_api',
+                             example_api)
+
+        def mock_notify(cls, *args):
+            self.notify_called = True
+
+        self.stubs.Set(no_op_notifier, 'notify',
+                mock_notify)
+
+        self.assertEqual(3, example_api(1, 2))
+        self.assertEqual(self.notify_called, True)
+
+    def test_decorator_context(self):
+        """Verify that the notify decorator can extract the 'context' arg."""
+        self.notify_called = False
+        self.context_arg = None
+
+        def example_api(arg1, arg2, context):
+            return arg1 + arg2
+
+        def example_api2(arg1, arg2, **kw):
+            return arg1 + arg2
+
+        example_api = notifier_api.notify_decorator(
+                            'example_api',
+                             example_api)
+
+        example_api2 = notifier_api.notify_decorator(
+                             'example_api2',
+                              example_api2)
+
+        def mock_notify(context, cls, _type, _priority, _payload):
+            self.notify_called = True
+            self.context_arg = context
+
+        self.stubs.Set(notifier_api, 'notify',
+                mock_notify)
+
+        # Test positional context
+        self.assertEqual(3, example_api(1, 2, ctxt))
+        self.assertEqual(self.notify_called, True)
+        self.assertEqual(self.context_arg, ctxt)
+
+        self.notify_called = False
+        self.context_arg = None
+
+        # Test named context
+        self.assertEqual(3, example_api2(1, 2, context=ctxt2))
+        self.assertEqual(self.notify_called, True)
+        self.assertEqual(self.context_arg, ctxt2)
+
+        # Test missing context
+        self.assertEqual(3, example_api2(1, 2, bananas="delicious"))
+        self.assertEqual(self.notify_called, True)
+        self.assertEqual(self.context_arg, None)