diff --git a/cinder/backup/chunkeddriver.py b/cinder/backup/chunkeddriver.py index c77536109f2..065e61cb5d1 100644 --- a/cinder/backup/chunkeddriver.py +++ b/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 ' diff --git a/cinder/test.py b/cinder/test.py index b068f237d03..1d2d01c35ab 100644 --- a/cinder/test.py +++ b/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) diff --git a/cinder/tests/fixtures.py b/cinder/tests/fixtures.py new file mode 100644 index 00000000000..f8585781321 --- /dev/null +++ b/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) diff --git a/cinder/tests/unit/test_vmware_vmdk.py b/cinder/tests/unit/test_vmware_vmdk.py index 2e514bbdc19..f1870a3f5e9 100644 --- a/cinder/tests/unit/test_vmware_vmdk.py +++ b/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 diff --git a/cinder/volume/drivers/hpe/hpe_lefthand_iscsi.py b/cinder/volume/drivers/hpe/hpe_lefthand_iscsi.py index ac5f9a9b18c..0c5411d044c 100644 --- a/cinder/volume/drivers/hpe/hpe_lefthand_iscsi.py +++ b/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'