Merge "Copy StandardLogging fixture from Nova"

cinder/backup/chunkeddriver.py

@@ -352,7 +352,7 @@ class ChunkedBackupDriver(driver.BackupDriver):
                       'compressed length: %(compressed_size_bytes)d. '
                       'Using original data for this chunk.',
                       {'data_size_bytes': data_size_bytes,
-                       'comp_size_bytes': comp_size_bytes,
+                       'compressed_size_bytes': comp_size_bytes,
                        })
             return 'none', data
         LOG.debug('Compressed %(data_size_bytes)d bytes of data '

cinder/test.py

@@ -32,6 +32,7 @@ import mock
 from oslo_concurrency import lockutils
 from oslo_config import cfg
 from oslo_config import fixture as config_fixture
+from oslo_log.fixture import logging_error as log_fixture
 from oslo_log import log
 from oslo_messaging import conffixture as messaging_conffixture
 from oslo_utils import strutils
@@ -46,6 +47,7 @@ from cinder import i18n
 from cinder.objects import base as objects_base
 from cinder import rpc
 from cinder import service
+from cinder.tests import fixtures as cinder_fixtures
 from cinder.tests.unit import conf_fixture
 from cinder.tests.unit import fake_notifier
 
@@ -172,15 +174,9 @@ class TestCase(testtools.TestCase):
         if environ_enabled('OS_STDERR_CAPTURE'):
             stderr = self.useFixture(fixtures.StringStream('stderr')).stream
             self.useFixture(fixtures.MonkeyPatch('sys.stderr', stderr))
-        if environ_enabled('OS_LOG_CAPTURE'):
-            log_format = '%(levelname)s [%(name)s] %(message)s'
-            if environ_enabled('OS_DEBUG'):
-                level = logging.DEBUG
-            else:
-                level = logging.INFO
-            self.useFixture(fixtures.LoggerFixture(nuke_handlers=False,
-                                                   format=log_format,
-                                                   level=level))
+
+        self.useFixture(log_fixture.get_logging_handle_error_fixture())
+        self.useFixture(cinder_fixtures.StandardLogging())
 
         rpc.add_extra_exmods("cinder.tests.unit")
         self.addCleanup(rpc.clear_extra_exmods)
@@ -307,11 +303,6 @@ class TestCase(testtools.TestCase):
         for k, v in kw.items():
             self.override_config(k, v)
 
-    def log_level(self, level):
-        """Set logging level to the specified value."""
-        log_root = logging.getLogger(None).logger
-        log_root.setLevel(level)
-
     def start_service(self, name, host=None, **kwargs):
         host = host and host or uuid.uuid4().hex
         kwargs.setdefault('host', host)

cinder/tests/fixtures.py

@@ -0,0 +1,101 @@
+# Copyright 2016 IBM Corp.
+#
+#    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.
+
+"""Fixtures for Cinder tests."""
+# NOTE(mriedem): This is needed for importing from fixtures.
+from __future__ import absolute_import
+
+import logging as std_logging
+import os
+
+import fixtures
+
+_TRUE_VALUES = ('True', 'true', '1', 'yes')
+
+
+class NullHandler(std_logging.Handler):
+    """custom default NullHandler to attempt to format the record.
+
+    Used in conjunction with
+    log_fixture.get_logging_handle_error_fixture to detect formatting errors in
+    debug level logs without saving the logs.
+    """
+    def handle(self, record):
+        self.format(record)
+
+    def emit(self, record):
+        pass
+
+    def createLock(self):
+        self.lock = None
+
+
+class StandardLogging(fixtures.Fixture):
+    """Setup Logging redirection for tests.
+
+    There are a number of things we want to handle with logging in tests:
+
+    * Redirect the logging to somewhere that we can test or dump it later.
+
+    * Ensure that as many DEBUG messages as possible are actually
+       executed, to ensure they are actually syntactically valid (they
+       often have not been).
+
+    * Ensure that we create useful output for tests that doesn't
+      overwhelm the testing system (which means we can't capture the
+      100 MB of debug logging on every run).
+
+    To do this we create a logger fixture at the root level, which
+    defaults to INFO and create a Null Logger at DEBUG which lets
+    us execute log messages at DEBUG but not keep the output.
+
+    To support local debugging OS_DEBUG=True can be set in the
+    environment, which will print out the full debug logging.
+
+    There are also a set of overrides for particularly verbose
+    modules to be even less than INFO.
+
+    """
+
+    def setUp(self):
+        super(StandardLogging, self).setUp()
+
+        # set root logger to debug
+        root = std_logging.getLogger()
+        root.setLevel(std_logging.DEBUG)
+
+        # supports collecting debug level for local runs
+        if os.environ.get('OS_DEBUG') in _TRUE_VALUES:
+            level = std_logging.DEBUG
+        else:
+            level = std_logging.INFO
+
+        # Collect logs
+        fs = '%(asctime)s %(levelname)s [%(name)s] %(message)s'
+        self.logger = self.useFixture(
+            fixtures.FakeLogger(format=fs, level=None))
+        # TODO(sdague): why can't we send level through the fake
+        # logger? Tests prove that it breaks, but it's worth getting
+        # to the bottom of.
+        root.handlers[0].setLevel(level)
+
+        if level > std_logging.DEBUG:
+            # Just attempt to format debug level logs, but don't save them
+            handler = NullHandler()
+            self.useFixture(fixtures.LogHandler(handler, nuke_handlers=False))
+            handler.setLevel(std_logging.DEBUG)
+
+            # Don't log every single DB migration step
+            std_logging.getLogger(
+                'migrate.versioning.api').setLevel(std_logging.WARNING)

cinder/tests/unit/test_vmware_vmdk.py

@@ -733,7 +733,8 @@ class VMwareVcVmdkDriverTestCase(test.TestCase):
         host = mock.sentinel.host
         rp = mock.sentinel.rp
         folder = mock.sentinel.folder
-        summary = mock.Mock(name=mock.sentinel.ds_name)
+        # NOTE(mriedem): The summary.name gets logged so it has to be a string
+        summary = mock.Mock(name=six.text_type(mock.sentinel.ds_name))
         select_ds_for_volume.return_value = (host, rp, folder, summary)
 
         profile_id = mock.sentinel.profile_id

cinder/volume/drivers/hpe/hpe_lefthand_iscsi.py

@@ -462,7 +462,7 @@ class HPELeftHandISCSIDriver(driver.ISCSIDriver):
                 volume_update['status'] = 'deleted'
             except Exception as ex:
                 LOG.error(_LE("There was an error deleting volume %(id)s: "
-                              "%(error)."),
+                              "%(error)s."),
                           {'id': volume.id,
                            'error': six.text_type(ex)})
                 volume_update['status'] = 'error'