From 63dfee88a8eabeee36347ad7804299609e74d470 Mon Sep 17 00:00:00 2001 From: Yuriy Nesenenko Date: Wed, 29 Apr 2015 20:36:09 +0300 Subject: [PATCH] Fix unit tests spam output Some of unit tests print logs to stdout. Tests output should be clear and contain only necessary information. Debug output should not be mixed with tests output. Change-Id: Ia886998693ce559b270f52c3d9f2ac6062e09a67 Closes-Bug: #1449073 --- cinder/cmd/volume_usage_audit.py | 56 +++++------ cinder/tests/unit/api/test_wsgi.py | 10 +- cinder/tests/unit/test_cmd.py | 111 +++++++++++---------- cinder/tests/unit/test_eqlx.py | 10 +- cinder/tests/unit/test_glusterfs.py | 2 +- cinder/tests/unit/test_hds_hnas_backend.py | 4 +- cinder/tests/unit/test_quobyte.py | 2 +- cinder/tests/unit/test_volume.py | 8 +- 8 files changed, 107 insertions(+), 96 deletions(-) diff --git a/cinder/cmd/volume_usage_audit.py b/cinder/cmd/volume_usage_audit.py index b375d56f7..cfee52889 100644 --- a/cinder/cmd/volume_usage_audit.py +++ b/cinder/cmd/volume_usage_audit.py @@ -36,7 +36,6 @@ from __future__ import print_function import datetime import sys -import traceback import warnings warnings.simplefilter('once', DeprecationWarning) @@ -93,12 +92,11 @@ def main(): msg = _("The end time (%(end)s) must be after the start " "time (%(start)s).") % {'start': begin, 'end': end} - print(msg) LOG.error(msg) sys.exit(-1) - print(_("Starting volume usage audit")) + LOG.debug("Starting volume usage audit") msg = _("Creating usages for %(begin_period)s until %(end_period)s") - print(msg % {"begin_period": str(begin), "end_period": str(end)}) + LOG.debug(msg, {"begin_period": str(begin), "end_period": str(end)}) extra_info = { 'audit_period_beginning': str(begin), @@ -108,7 +106,7 @@ def main(): volumes = db.volume_get_active_by_window(admin_context, begin, end) - print(_("Found %d volumes") % len(volumes)) + LOG.debug("Found %d volumes"), len(volumes) for volume_ref in volumes: try: LOG.debug("Send exists notification for begin and @@ -149,10 +145,9 @@ def main(): admin_context, volume_ref, 'create.end', extra_usage_info=local_extra_info) - except Exception as e: - LOG.error(_LE("Failed to send create notification for " - "volume %s."), volume_ref.id) - print(traceback.format_exc(e)) + except Exception as exc_msg: + LOG.exception(_LE("Create volume notification failed: %s"), + exc_msg, resource=volume_ref) if (CONF.send_actions and volume_ref.deleted_at and volume_ref.deleted_at > begin and @@ -176,15 +171,14 @@ def main(): admin_context, volume_ref, 'delete.end', extra_usage_info=local_extra_info) - except Exception as e: - LOG.error(_LE("Failed to send delete notification for volume " - "%s."), volume_ref.id) - print(traceback.format_exc(e)) + except Exception as exc_msg: + LOG.exception(_LE("Delete volume notification failed: %s"), + exc_msg, resource=volume_ref) snapshots = db.snapshot_get_active_by_window(admin_context, begin, end) - print(_("Found %d snapshots") % len(snapshots)) + LOG.debug("Found %d snapshots"), len(snapshots) for snapshot_ref in snapshots: try: LOG.debug("Send notification for " @@ -196,11 +190,9 @@ def main(): snapshot_ref, 'exists', extra_info) - except Exception as e: - LOG.error(_LE("Failed to send exists notification " - "for snapshot %s."), - snapshot_ref.id) - print(traceback.format_exc(e)) + except Exception as exc_msg: + LOG.exception(_LE("Exists snapshot notification failed: %s"), + exc_msg, resource=snapshot_ref) if (CONF.send_actions and snapshot_ref.created_at > begin and @@ -224,10 +216,9 @@ def main(): admin_context, snapshot_ref, 'create.end', extra_usage_info=local_extra_info) - except Exception as e: - LOG.error(_LE("Failed to send create notification for snapshot" - "%s."), snapshot_ref.id) - print(traceback.format_exc(e)) + except Exception as exc_msg: + LOG.exception(_LE("Create snapshot notification failed: %s"), + exc_msg, resource=snapshot_ref) if (CONF.send_actions and snapshot_ref.deleted_at and snapshot_ref.deleted_at > begin and @@ -251,9 +242,8 @@ def main(): admin_context, snapshot_ref, 'delete.end', extra_usage_info=local_extra_info) - except Exception as e: - LOG.error(_LE("Failed to send delete notification for snapshot" - "%s."), snapshot_ref.id) - print(traceback.format_exc(e)) + except Exception as exc_msg: + LOG.exception(_LE("Delete snapshot notification failed: %s"), + exc_msg, resource=snapshot_ref) - print(_("Volume usage audit completed")) + LOG.debug("Volume usage audit completed") diff --git a/cinder/tests/unit/api/test_wsgi.py b/cinder/tests/unit/api/test_wsgi.py index fc52fb9a5..d96cf9538 100644 --- a/cinder/tests/unit/api/test_wsgi.py +++ b/cinder/tests/unit/api/test_wsgi.py @@ -19,6 +19,9 @@ Test WSGI basics and provide some helper functions for other WSGI tests. """ +import mock +import six + from cinder import test import routes @@ -38,9 +41,10 @@ class Test(test.TestCase): start_response("200", [("X-Test", "checking")]) return ['Test result'] - application = wsgi.Debug(Application()) - result = webob.Request.blank('/').get_response(application) - self.assertEqual(result.body, "Test result") + with mock.patch('sys.stdout', new=six.StringIO()): + application = wsgi.Debug(Application()) + result = webob.Request.blank('/').get_response(application) + self.assertEqual(result.body, "Test result") def test_router(self): diff --git a/cinder/tests/unit/test_cmd.py b/cinder/tests/unit/test_cmd.py index c3306ba8d..8b2a031bc 100644 --- a/cinder/tests/unit/test_cmd.py +++ b/cinder/tests/unit/test_cmd.py @@ -11,7 +11,7 @@ # under the License. import datetime -import StringIO +import six import sys import mock @@ -339,20 +339,23 @@ class TestCinderManageCmd(test.TestCase): @mock.patch('oslo_db.sqlalchemy.migration.db_version') def test_db_commands_version(self, db_version): db_cmds = cinder_manage.DbCommands() - db_cmds.version() - self.assertEqual(1, db_version.call_count) + with mock.patch('sys.stdout', new=six.StringIO()): + db_cmds.version() + self.assertEqual(1, db_version.call_count) @mock.patch('cinder.version.version_string') def test_versions_commands_list(self, version_string): version_cmds = cinder_manage.VersionCommands() - version_cmds.list() - version_string.assert_called_once_with() + with mock.patch('sys.stdout', new=six.StringIO()): + version_cmds.list() + version_string.assert_called_once_with() @mock.patch('cinder.version.version_string') def test_versions_commands_call(self, version_string): version_cmds = cinder_manage.VersionCommands() - version_cmds.__call__() - version_string.assert_called_once_with() + with mock.patch('sys.stdout', new=six.StringIO()): + version_cmds.__call__() + version_string.assert_called_once_with() @mock.patch('cinder.db.service_get_all') @mock.patch('cinder.context.get_admin_context') @@ -361,7 +364,7 @@ class TestCinderManageCmd(test.TestCase): service_get_all.return_value = [{'host': 'fake-host', 'availability_zone': 'fake-az'}] - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: expected_out = ("%(host)-25s\t%(zone)-15s\n" % {'host': 'host', 'zone': 'zone'}) expected_out += ("%(host)-25s\t%(availability_zone)-15s\n" % @@ -384,7 +387,7 @@ class TestCinderManageCmd(test.TestCase): {'host': 'fake-host', 'availability_zone': 'fake-az2'}] - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: expected_out = ("%(host)-25s\t%(zone)-15s\n" % {'host': 'host', 'zone': 'zone'}) expected_out += ("%(host)-25s\t%(availability_zone)-15s\n" % @@ -455,7 +458,7 @@ class TestCinderManageCmd(test.TestCase): volume = {'id': volume_id, 'host': None, 'status': 'available'} volume_get.return_value = volume - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: expected_out = ('Volume not yet assigned to host.\n' 'Deleting volume from database and skipping' ' rpc.\n') @@ -480,7 +483,7 @@ class TestCinderManageCmd(test.TestCase): volume = {'id': volume_id, 'host': 'fake-host', 'status': 'in-use'} volume_get.return_value = volume - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: expected_out = ('Volume is in-use.\n' 'Detach volume from instance and then try' ' again.\n') @@ -491,7 +494,7 @@ class TestCinderManageCmd(test.TestCase): self.assertEqual(expected_out, fake_out.getvalue()) def test_config_commands_list(self): - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: expected_out = '' for key, value in CONF.iteritems(): expected_out += '%s = %s' % (key, value) + '\n' @@ -502,7 +505,7 @@ class TestCinderManageCmd(test.TestCase): self.assertEqual(expected_out, fake_out.getvalue()) def test_config_commands_list_param(self): - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: CONF.set_override('host', 'fake') expected_out = 'host = fake\n' @@ -512,7 +515,7 @@ class TestCinderManageCmd(test.TestCase): self.assertEqual(expected_out, fake_out.getvalue()) def test_get_log_commands_no_errors(self): - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: CONF.set_override('log_dir', None) expected_out = 'No errors in logfiles!\n' @@ -527,8 +530,8 @@ class TestCinderManageCmd(test.TestCase): CONF.set_override('log_dir', 'fake-dir') listdir.return_value = ['fake-error.log'] - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: - open.return_value = StringIO.StringIO( + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: + open.return_value = six.StringIO( '[ ERROR ] fake-error-message') expected_out = ('fake-dir/fake-error.log:-\n' 'Line 1 : [ ERROR ] fake-error-message\n') @@ -546,11 +549,12 @@ class TestCinderManageCmd(test.TestCase): path_exists.return_value = False get_log_cmds = cinder_manage.GetLogCommands() - exit = self.assertRaises(SystemExit, get_log_cmds.syslog) + with mock.patch('sys.stdout', new=six.StringIO()): + exit = self.assertRaises(SystemExit, get_log_cmds.syslog) + self.assertEqual(1, exit.code) - self.assertEqual(exit.code, 1) - path_exists.assert_any_call('/var/log/syslog') - path_exists.assert_any_call('/var/log/messages') + path_exists.assert_any_call('/var/log/syslog') + path_exists.assert_any_call('/var/log/messages') @mock.patch('cinder.db.backup_get_all') @mock.patch('cinder.context.get_admin_context') @@ -567,7 +571,7 @@ class TestCinderManageCmd(test.TestCase): 'size': 123, 'object_count': 1} backup_get_all.return_value = [backup] - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: hdr = ('%-32s\t%-32s\t%-32s\t%-24s\t%-24s\t%-12s\t%-12s\t%-12s' '\t%-12s') header = hdr % ('ID', @@ -613,7 +617,7 @@ class TestCinderManageCmd(test.TestCase): 'disabled': False} service_get_all.return_value = [service] service_is_up.return_value = True - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: format = "%-16s %-36s %-16s %-10s %-5s %-10s" print_format = format % ('Binary', 'Host', @@ -643,10 +647,10 @@ class TestCinderManageCmd(test.TestCase): sys.argv = [script_name] CONF(sys.argv[1:], project='cinder', version=version.version_string()) - exit = self.assertRaises(SystemExit, cinder_manage.main) - - self.assertTrue(register_cli_opt.called) - self.assertEqual(exit.code, 2) + with mock.patch('sys.stdout', new=six.StringIO()): + exit = self.assertRaises(SystemExit, cinder_manage.main) + self.assertTrue(register_cli_opt.called) + self.assertEqual(2, exit.code) @mock.patch('oslo_config.cfg.ConfigOpts.__call__') @mock.patch('oslo_log.log.setup') @@ -658,14 +662,15 @@ class TestCinderManageCmd(test.TestCase): config_opts_call.side_effect = cfg.ConfigFilesNotFoundError( mock.sentinel._namespace) - exit = self.assertRaises(SystemExit, cinder_manage.main) + with mock.patch('sys.stdout', new=six.StringIO()): + exit = self.assertRaises(SystemExit, cinder_manage.main) - self.assertTrue(register_cli_opt.called) - config_opts_call.assert_called_once_with( - sys.argv[1:], project='cinder', - version=version.version_string()) - self.assertFalse(log_setup.called) - self.assertEqual(exit.code, 2) + self.assertTrue(register_cli_opt.called) + config_opts_call.assert_called_once_with( + sys.argv[1:], project='cinder', + version=version.version_string()) + self.assertFalse(log_setup.called) + self.assertEqual(2, exit.code) @mock.patch('oslo_config.cfg.ConfigOpts.__call__') @mock.patch('oslo_config.cfg.ConfigOpts.register_cli_opt') @@ -697,12 +702,13 @@ class TestCinderRtstoolCmd(test.TestCase): def test_create_rtslib_error(self, rtsroot): rtsroot.side_effect = rtslib.utils.RTSLibError() - self.assertRaises(rtslib.utils.RTSLibError, cinder_rtstool.create, - mock.sentinel.backing_device, - mock.sentinel.name, - mock.sentinel.userid, - mock.sentinel.password, - mock.sentinel.iser_enabled) + with mock.patch('sys.stdout', new=six.StringIO()): + self.assertRaises(rtslib.utils.RTSLibError, cinder_rtstool.create, + mock.sentinel.backing_device, + mock.sentinel.name, + mock.sentinel.userid, + mock.sentinel.password, + mock.sentinel.iser_enabled) def _test_create_rtslib_error_network_portal(self, ip): with mock.patch('rtslib.NetworkPortal') as network_portal, \ @@ -757,10 +763,12 @@ class TestCinderRtstoolCmd(test.TestCase): network_portal.assert_any_call(tpg_new, ip, 3260, mode='any') def test_create_rtslib_error_network_portal_ipv4(self): - self._test_create_rtslib_error_network_portal('0.0.0.0') + with mock.patch('sys.stdout', new=six.StringIO()): + self._test_create_rtslib_error_network_portal('0.0.0.0') def test_create_rtslib_error_network_portal_ipv6(self): - self._test_create_rtslib_error_network_portal('::0') + with mock.patch('sys.stdout', new=six.StringIO()): + self._test_create_rtslib_error_network_portal('::0') def _test_create(self, ip): with mock.patch('rtslib.NetworkPortal') as network_portal, \ @@ -820,12 +828,13 @@ class TestCinderRtstoolCmd(test.TestCase): def test_add_initiator_rtslib_error(self, rtsroot): rtsroot.side_effect = rtslib.utils.RTSLibError() - self.assertRaises(rtslib.utils.RTSLibError, - cinder_rtstool.add_initiator, - mock.sentinel.target_iqn, - mock.sentinel.initiator_iqn, - mock.sentinel.userid, - mock.sentinel.password) + with mock.patch('sys.stdout', new=six.StringIO()): + self.assertRaises(rtslib.utils.RTSLibError, + cinder_rtstool.add_initiator, + mock.sentinel.target_iqn, + mock.sentinel.initiator_iqn, + mock.sentinel.userid, + mock.sentinel.password) @mock.patch('rtslib.root.RTSRoot') def test_add_initiator_rtstool_error(self, rtsroot): @@ -889,7 +898,7 @@ class TestCinderRtstoolCmd(test.TestCase): target.dump.return_value = {'wwn': 'fake-wwn'} rtsroot.return_value = mock.MagicMock(targets=[target]) - with mock.patch('sys.stdout', new=StringIO.StringIO()) as fake_out: + with mock.patch('sys.stdout', new=six.StringIO()) as fake_out: cinder_rtstool.get_targets() self.assertEqual(str(target.wwn), fake_out.getvalue().strip()) @@ -917,9 +926,9 @@ class TestCinderRtstoolCmd(test.TestCase): rtsroot.return_value.save_to_file.assert_called_once_with(filename) def test_usage(self): - exit = self.assertRaises(SystemExit, cinder_rtstool.usage) - - self.assertEqual(exit.code, 1) + with mock.patch('sys.stdout', new=six.StringIO()): + exit = self.assertRaises(SystemExit, cinder_rtstool.usage) + self.assertEqual(1, exit.code) @mock.patch('cinder.cmd.rtstool.usage') def test_main_argc_lt_2(self, usage): diff --git a/cinder/tests/unit/test_eqlx.py b/cinder/tests/unit/test_eqlx.py index cb928c6d2..7803aa45d 100644 --- a/cinder/tests/unit/test_eqlx.py +++ b/cinder/tests/unit/test_eqlx.py @@ -20,6 +20,7 @@ import mock from oslo_concurrency import processutils from oslo_log import log as logging import paramiko +import six from cinder import context from cinder import exception @@ -302,6 +303,9 @@ class DellEQLSanISCSIDriverTestCase(test.TestCase): self.driver._ssh_execute(ssh, self.cmd)) def test_ssh_execute_error(self): + self.mock_object(self.driver, '_ssh_execute', + mock.Mock(side_effect= + processutils.ProcessExecutionError)) ssh = mock.Mock(paramiko.SSHClient) chan = mock.Mock(paramiko.Channel) transport = mock.Mock(paramiko.Transport) @@ -368,8 +372,10 @@ class DellEQLSanISCSIDriverTestCase(test.TestCase): mock.Mock(side_effect=exception. VolumeBackendAPIException("some error"))) # now call the execute - self.assertRaises(exception.VolumeBackendAPIException, - self.driver._eql_execute, "fake command") + with mock.patch('sys.stderr', new=six.StringIO()): + self.assertRaises(exception.VolumeBackendAPIException, + self.driver._eql_execute, "fake command") + self.assertEqual(num_attempts + 1, self.driver._get_output.call_count) def test_with_timeout(self): diff --git a/cinder/tests/unit/test_glusterfs.py b/cinder/tests/unit/test_glusterfs.py index 4a66af9ed..f6c282735 100644 --- a/cinder/tests/unit/test_glusterfs.py +++ b/cinder/tests/unit/test_glusterfs.py @@ -114,7 +114,7 @@ class GlusterFsDriverTestCase(test.TestCase): caught = True self.assertEqual(excClass, type(exc), 'Wrong exception caught: %s Stacktrace: %s' % - (exc, traceback.print_exc())) + (exc, traceback.format_exc())) self.assertIn(msg, six.text_type(exc)) if not caught: diff --git a/cinder/tests/unit/test_hds_hnas_backend.py b/cinder/tests/unit/test_hds_hnas_backend.py index 8f2070a75..64d32aae5 100644 --- a/cinder/tests/unit/test_hds_hnas_backend.py +++ b/cinder/tests/unit/test_hds_hnas_backend.py @@ -263,8 +263,8 @@ UTILS_EXEC_OUT = ["output: test_cmd", ""] def m_run_cmd(*args, **kargs): - print(args) # noqa - print(HNAS_CMDS.get(args)) # noqa + LOG.debug(args) + LOG.debug(HNAS_CMDS.get(args)) return HNAS_CMDS.get(args) diff --git a/cinder/tests/unit/test_quobyte.py b/cinder/tests/unit/test_quobyte.py index e9dfaa478..41b5957c5 100644 --- a/cinder/tests/unit/test_quobyte.py +++ b/cinder/tests/unit/test_quobyte.py @@ -107,7 +107,7 @@ class QuobyteDriverTestCase(test.TestCase): caught = True self.assertEqual(excClass, type(exc), 'Wrong exception caught: %s Stacktrace: %s' % - (exc, traceback.print_exc())) + (exc, traceback.format_exc())) self.assertIn(msg, six.text_type(exc)) if not caught: diff --git a/cinder/tests/unit/test_volume.py b/cinder/tests/unit/test_volume.py index 2c7b129ed..8f2d1644f 100644 --- a/cinder/tests/unit/test_volume.py +++ b/cinder/tests/unit/test_volume.py @@ -35,6 +35,7 @@ from oslo_serialization import jsonutils from oslo_utils import importutils from oslo_utils import timeutils from oslo_utils import units +import six from stevedore import extension from taskflow.engines.action_engine import engine @@ -1261,7 +1262,8 @@ class VolumeTestCase(BaseVolumeTestCase): # source volume was deleted while the create was locked. Note that the # volume is still in the db since it was created by the test prior to # calling manager.create_volume. - self.assertRaises(exception.VolumeNotFound, gthreads[0].wait) + with mock.patch('sys.stderr', new=six.StringIO()): + self.assertRaises(exception.VolumeNotFound, gthreads[0].wait) def _raise_metadata_copy_failure(self, method, dst_vol_id, **kwargs): # MetadataCopyFailure exception will be raised if DB service is Down @@ -1519,8 +1521,8 @@ class VolumeTestCase(BaseVolumeTestCase): # snapshot was deleted while the create was locked. Note that the # volume is still in the db since it was created by the test prior to # calling manager.create_volume. - self.assertRaises(exception.SnapshotNotFound, gthreads[0].wait) - + with mock.patch('sys.stderr', new=six.StringIO()): + self.assertRaises(exception.SnapshotNotFound, gthreads[0].wait) # locked self.volume.delete_volume(self.context, src_vol_id) # make sure it is gone -- 2.45.2