Copy StandardLogging fixture from Nova

This code was originally written for Nova by Joe Gordon
<joe.gordon0@gmail.com> and Sean Dague <sean@dague.net>.

This enables debug logging that is exercised by unit test
runs to be handled and detect formatting errors. The debug
logging does not actually go to the console unless the
OS_DEBUG environment variable is set.

As a result, a few formatting errors are detected and
cleaned up with this change.

This also fixes a problem where debug logging from stevedore
is dumped to the console every time an extension is loaded,
which in a gate-cinder-python27 job is 65K+ times.

Change-Id: I989f9d591d1483a56a1bab3c20de583e85997562
Closes-Bug: #1551325
This commit is contained in:
Matt Riedemann 2016-02-29 12:31:22 -05:00
parent 350f19d031
commit 32719d4041
5 changed files with 110 additions and 17 deletions

View File

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

View File

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

101
cinder/tests/fixtures.py Normal file
View File

@ -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)

View File

@ -733,7 +733,8 @@ class VMwareVcVmdkDriverTestCase(test.TestCase):
host = mock.sentinel.host host = mock.sentinel.host
rp = mock.sentinel.rp rp = mock.sentinel.rp
folder = mock.sentinel.folder 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) select_ds_for_volume.return_value = (host, rp, folder, summary)
profile_id = mock.sentinel.profile_id profile_id = mock.sentinel.profile_id

View File

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