diff --git a/openstackclient/common/context.py b/openstackclient/common/context.py index 570919392c..6d1aec13b7 100644 --- a/openstackclient/common/context.py +++ b/openstackclient/common/context.py @@ -11,9 +11,10 @@ # under the License. # -"""Context and Formatter""" +"""Application logging""" import logging +import sys import warnings @@ -99,76 +100,71 @@ class _FileFormatter(logging.Formatter): logging.Formatter.__init__(self, self.fmt, self._LOG_DATE_FORMAT) -def setup_handler_logging_level(handler_type, level): - """Setup of the handler for set the logging level +class LogConfigurator(object): - :param handler_type: type of logging handler - :param level: logging level - :return: None - """ - # Set the handler logging level of FileHandler(--log-file) - # and StreamHandler - for h in logging.getLogger('').handlers: - if type(h) is handler_type: - h.setLevel(level) + _CONSOLE_MESSAGE_FORMAT = '%(message)s' + def __init__(self, options): + self.root_logger = logging.getLogger('') + self.root_logger.setLevel(logging.DEBUG) -def setup_logging(shell, cloud_config): - """Get one cloud configuration from configuration file and setup logging + # Force verbose_level 3 on --debug + self.dump_trace = False + if options.debug: + options.verbose_level = 3 + self.dump_trace = True - :param shell: instance of openstackclient shell - :param cloud_config: - instance of the cloud specified by --os-cloud - in the configuration file - :return: None - """ + # Always send higher-level messages to the console via stderr + self.console_logger = logging.StreamHandler(sys.stderr) + log_level = log_level_from_options(options) + self.console_logger.setLevel(log_level) + formatter = logging.Formatter(self._CONSOLE_MESSAGE_FORMAT) + self.console_logger.setFormatter(formatter) + self.root_logger.addHandler(self.console_logger) - log_level = log_level_from_config(cloud_config.config) - set_warning_filter(log_level) + # Set the warning filter now + set_warning_filter(log_level) - log_file = cloud_config.config.get('log_file', None) - if log_file: - # setup the logging context - formatter = _FileFormatter(config=cloud_config) - # setup the logging handler - log_handler = _setup_handler_for_logging( - logging.FileHandler, - log_level, - file_name=log_file, - formatter=formatter, - ) - if log_level == logging.DEBUG: - # DEBUG only. - # setup the operation_log - shell.enable_operation_logging = True - shell.operation_log.setLevel(logging.DEBUG) - shell.operation_log.addHandler(log_handler) + # Set up logging to a file + self.file_logger = None + log_file = options.log_file + if log_file: + self.file_logger = logging.FileHandler(filename=log_file) + self.file_logger.setFormatter(_FileFormatter(options=options)) + self.file_logger.setLevel(log_level) + self.root_logger.addHandler(self.file_logger) + # Requests logs some stuff at INFO that we don't want + # unless we have DEBUG + requests_log = logging.getLogger("requests") -def _setup_handler_for_logging(handler_type, level, file_name, formatter): - """Setup of the handler + # Other modules we don't want DEBUG output for + cliff_log = logging.getLogger('cliff') + stevedore_log = logging.getLogger('stevedore') + iso8601_log = logging.getLogger("iso8601") - Setup of the handler for addition of the logging handler, - changes of the logging format, change of the logging level, + if options.debug: + # --debug forces traceback + requests_log.setLevel(logging.DEBUG) + else: + requests_log.setLevel(logging.ERROR) - :param handler_type: type of logging handler - :param level: logging level - :param file_name: name of log-file - :param formatter: instance of logging.Formatter - :return: logging handler - """ + cliff_log.setLevel(logging.ERROR) + stevedore_log.setLevel(logging.ERROR) + iso8601_log.setLevel(logging.ERROR) - root_logger = logging.getLogger('') - handler = None - # Setup handler for FileHandler(--os-cloud) - handler = logging.FileHandler( - filename=file_name, - ) - handler.setFormatter(formatter) - handler.setLevel(level) + def configure(self, cloud_config): + log_level = log_level_from_config(cloud_config.config) + set_warning_filter(log_level) + self.dump_trace = cloud_config.config.get('debug', self.dump_trace) + self.console_logger.setLevel(log_level) - # If both `--log-file` and `--os-cloud` are specified, - # the log is output to each file. - root_logger.addHandler(handler) - - return handler + log_file = cloud_config.config.get('log_file', None) + if log_file: + if not self.file_logger: + self.file_logger = logging.FileHandler(filename=log_file) + formatter = _FileFormatter(cloud_config=cloud_config) + self.file_logger.setFormatter(formatter) + self.file_logger.setFormatter(_FileFormatter(config=cloud_config)) + self.file_logger.setLevel(log_level) + self.root_logger.addHandler(self.file_logger) diff --git a/openstackclient/shell.py b/openstackclient/shell.py index 6ba19d194f..72f663a093 100644 --- a/openstackclient/shell.py +++ b/openstackclient/shell.py @@ -94,60 +94,12 @@ class OpenStackShell(app.App): self.verify = True self.client_manager = None - - # Operation log - self.enable_operation_logging = False self.command_options = None def configure_logging(self): - """Configure logging for the app - - Cliff sets some defaults we don't want so re-work it a bit - """ - - if self.options.debug: - # --debug forces verbose_level 3 - # Set this here so cliff.app.configure_logging() can work - self.options.verbose_level = 3 - - super(OpenStackShell, self).configure_logging() - - # Set logging to the requested level - log_level = context.log_level_from_options(self.options) - context.set_warning_filter(log_level) - - # Set the handler logging level of FileHandler(--log-file) - # and StreamHandler - if self.options.log_file: - context.setup_handler_logging_level(logging.FileHandler, log_level) - - context.setup_handler_logging_level(logging.StreamHandler, log_level) - - # Requests logs some stuff at INFO that we don't want - # unless we have DEBUG - requests_log = logging.getLogger("requests") - - # Other modules we don't want DEBUG output for - cliff_log = logging.getLogger('cliff') - stevedore_log = logging.getLogger('stevedore') - iso8601_log = logging.getLogger("iso8601") - - if self.options.debug: - # --debug forces traceback - self.dump_stack_trace = True - requests_log.setLevel(logging.DEBUG) - else: - self.dump_stack_trace = False - requests_log.setLevel(logging.ERROR) - - cliff_log.setLevel(logging.ERROR) - stevedore_log.setLevel(logging.ERROR) - iso8601_log.setLevel(logging.ERROR) - - # Operation logging - self.operation_log = logging.getLogger("operation_log") - self.operation_log.setLevel(logging.ERROR) - self.operation_log.propagate = False + """Configure logging for the app.""" + self.log_configurator = context.LogConfigurator(self.options) + self.dump_stack_trace = self.log_configurator.dump_trace def run(self, argv): ret_val = 1 @@ -162,8 +114,6 @@ class OpenStackShell(app.App): self.log.error(traceback.format_exc(e)) else: self.log.error('Exception raised: ' + str(e)) - if self.enable_operation_logging: - self.operation_log.error(traceback.format_exc(e)) return ret_val @@ -287,9 +237,8 @@ class OpenStackShell(app.App): argparse=self.options, ) - # Set up every time record log in file and logging start - context.setup_logging(self, self.cloud) - + self.log_configurator.configure(self.cloud) + self.dump_stack_trace = self.log_configurator.dump_trace self.log.info("START with options: %s", self.command_options) self.log.debug("options: %s", self.options) self.log.debug("defaults: %s", cc.defaults) diff --git a/openstackclient/tests/common/test_context.py b/openstackclient/tests/common/test_context.py index cc213b13f4..55e42851b3 100644 --- a/openstackclient/tests/common/test_context.py +++ b/openstackclient/tests/common/test_context.py @@ -13,7 +13,6 @@ import logging import mock -import os from openstackclient.common import context from openstackclient.tests import utils @@ -21,47 +20,6 @@ from openstackclient.tests import utils class TestContext(utils.TestCase): - TEST_LOG_FILE = "/tmp/test_log_file" - - def setUp(self): - super(TestContext, self).setUp() - - def tearDown(self): - super(TestContext, self).tearDown() - if os.path.exists(self.TEST_LOG_FILE): - os.remove(self.TEST_LOG_FILE) - - def setup_handler_logging_level(self): - handler_type = logging.FileHandler - handler = logging.FileHandler(filename=self.TEST_LOG_FILE) - handler.setLevel(logging.ERROR) - logging.getLogger('').addHandler(handler) - context.setup_handler_logging_level(handler_type, logging.INFO) - self.log.info("test log") - ld = open(self.TEST_LOG_FILE) - line = ld.readlines() - ld.close() - if os.path.exists(self.TEST_LOG_FILE): - os.remove(self.TEST_LOG_FILE) - self.assertGreaterEqual(line.find("test log"), 0) - - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_setup_logging(self, setuph): - setuph.return_value = mock.MagicMock() - shell = mock.MagicMock() - cloud_config = mock.MagicMock() - cloud_config.auth = { - 'project_name': 'heart-o-gold', - 'username': 'zaphod' - } - cloud_config.config = { - 'log_level': 'debug', - 'log_file': self.TEST_LOG_FILE, - 'cloud': 'megadodo' - } - context.setup_logging(shell, cloud_config) - self.assertEqual(True, shell.enable_operation_logging) - def test_log_level_from_options(self): opts = mock.Mock() opts.verbose_level = 0 @@ -132,3 +90,113 @@ class TestFileFormatter(utils.TestCase): self.assertEqual(('%(asctime)s.%(msecs)03d %(process)d %(levelname)s ' '%(name)s [cloudy usernamey projecty] %(message)s'), formatter.fmt) + + +class TestLogConfigurator(utils.TestCase): + def setUp(self): + super(TestLogConfigurator, self).setUp() + self.options = mock.Mock() + self.options.verbose_level = 1 + self.options.log_file = None + self.options.debug = False + self.root_logger = mock.Mock() + self.root_logger.setLevel = mock.Mock() + self.root_logger.addHandler = mock.Mock() + self.requests_log = mock.Mock() + self.requests_log.setLevel = mock.Mock() + self.cliff_log = mock.Mock() + self.cliff_log.setLevel = mock.Mock() + self.stevedore_log = mock.Mock() + self.stevedore_log.setLevel = mock.Mock() + self.iso8601_log = mock.Mock() + self.iso8601_log.setLevel = mock.Mock() + self.loggers = [ + self.root_logger, + self.requests_log, + self.cliff_log, + self.stevedore_log, + self.iso8601_log] + + @mock.patch('logging.StreamHandler') + @mock.patch('logging.getLogger') + @mock.patch('openstackclient.common.context.set_warning_filter') + def test_init(self, warning_filter, getLogger, handle): + getLogger.side_effect = self.loggers + console_logger = mock.Mock() + console_logger.setFormatter = mock.Mock() + console_logger.setLevel = mock.Mock() + handle.return_value = console_logger + + configurator = context.LogConfigurator(self.options) + + getLogger.assert_called_with('iso8601') # last call + warning_filter.assert_called_with(logging.WARNING) + self.root_logger.setLevel.assert_called_with(logging.DEBUG) + self.root_logger.addHandler.assert_called_with(console_logger) + self.requests_log.setLevel.assert_called_with(logging.ERROR) + self.cliff_log.setLevel.assert_called_with(logging.ERROR) + self.stevedore_log.setLevel.assert_called_with(logging.ERROR) + self.iso8601_log.setLevel.assert_called_with(logging.ERROR) + self.assertEqual(False, configurator.dump_trace) + + @mock.patch('logging.getLogger') + @mock.patch('openstackclient.common.context.set_warning_filter') + def test_init_no_debug(self, warning_filter, getLogger): + getLogger.side_effect = self.loggers + self.options.debug = True + + configurator = context.LogConfigurator(self.options) + + warning_filter.assert_called_with(logging.DEBUG) + self.requests_log.setLevel.assert_called_with(logging.DEBUG) + self.assertEqual(True, configurator.dump_trace) + + @mock.patch('logging.FileHandler') + @mock.patch('logging.getLogger') + @mock.patch('openstackclient.common.context.set_warning_filter') + @mock.patch('openstackclient.common.context._FileFormatter') + def test_init_log_file(self, formatter, warning_filter, getLogger, handle): + getLogger.side_effect = self.loggers + self.options.log_file = '/tmp/log_file' + file_logger = mock.Mock() + file_logger.setFormatter = mock.Mock() + file_logger.setLevel = mock.Mock() + handle.return_value = file_logger + mock_formatter = mock.Mock() + formatter.return_value = mock_formatter + + context.LogConfigurator(self.options) + + handle.assert_called_with(filename=self.options.log_file) + self.root_logger.addHandler.assert_called_with(file_logger) + file_logger.setFormatter.assert_called_with(mock_formatter) + file_logger.setLevel.assert_called_with(logging.WARNING) + + @mock.patch('logging.FileHandler') + @mock.patch('logging.getLogger') + @mock.patch('openstackclient.common.context.set_warning_filter') + @mock.patch('openstackclient.common.context._FileFormatter') + def test_configure(self, formatter, warning_filter, getLogger, handle): + getLogger.side_effect = self.loggers + configurator = context.LogConfigurator(self.options) + cloud_config = mock.Mock() + config_log = '/tmp/config_log' + cloud_config.config = { + 'log_file': config_log, + 'verbose_level': 1, + 'log_level': 'info'} + file_logger = mock.Mock() + file_logger.setFormatter = mock.Mock() + file_logger.setLevel = mock.Mock() + handle.return_value = file_logger + mock_formatter = mock.Mock() + formatter.return_value = mock_formatter + + configurator.configure(cloud_config) + + warning_filter.assert_called_with(logging.INFO) + handle.assert_called_with(filename=config_log) + self.root_logger.addHandler.assert_called_with(file_logger) + file_logger.setFormatter.assert_called_with(mock_formatter) + file_logger.setLevel.assert_called_with(logging.INFO) + self.assertEqual(False, configurator.dump_trace) diff --git a/openstackclient/tests/test_shell.py b/openstackclient/tests/test_shell.py index 5b84475329..cacd2fb763 100644 --- a/openstackclient/tests/test_shell.py +++ b/openstackclient/tests/test_shell.py @@ -623,12 +623,9 @@ class TestShellCli(TestShell): @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_cloud_public(self, setup_handler, config_mock, - public_mock): + def test_shell_args_cloud_public(self, config_mock, public_mock): config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) public_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() _shell = make_shell() fake_execute( @@ -666,12 +663,9 @@ class TestShellCli(TestShell): @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_precedence(self, setup_handler, config_mock, - vendor_mock): + def test_shell_args_precedence(self, config_mock, vendor_mock): config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() _shell = make_shell() # Test command option overriding config file value @@ -723,12 +717,9 @@ class TestShellCliEnv(TestShell): @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_precedence_1(self, setup_handler, config_mock, - vendor_mock): + def test_shell_args_precedence_1(self, config_mock, vendor_mock): config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() _shell = make_shell() # Test env var @@ -767,12 +758,9 @@ class TestShellCliEnv(TestShell): @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_precedence_2(self, setup_handler, config_mock, - vendor_mock): + def test_shell_args_precedence_2(self, config_mock, vendor_mock): config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() _shell = make_shell() # Test command option overriding config file value @@ -810,77 +798,3 @@ class TestShellCliEnv(TestShell): 'krikkit', _shell.cloud.config['region_name'], ) - - -class TestShellCliLogging(TestShell): - def setUp(self): - super(TestShellCliLogging, self).setUp() - - def tearDown(self): - super(TestShellCliLogging, self).tearDown() - - @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") - @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_precedence_1(self, setup_handler, config_mock, - vendor_mock): - config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) - vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() - _shell = make_shell() - - # These come from clouds.yaml - fake_execute( - _shell, - "--os-cloud megacloud list user", - ) - self.assertEqual( - 'megacloud', - _shell.cloud.name, - ) - - self.assertEqual( - '/tmp/test_log_file', - _shell.cloud.config['log_file'], - ) - self.assertEqual( - 'debug', - _shell.cloud.config['log_level'], - ) - - @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") - @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - def test_shell_args_precedence_2(self, config_mock, vendor_mock): - config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_1)) - vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - _shell = make_shell() - - # Test operation_log_file not set - fake_execute( - _shell, - "--os-cloud scc list user", - ) - self.assertEqual( - False, - _shell.enable_operation_logging, - ) - - @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file") - @mock.patch("os_client_config.config.OpenStackConfig._load_config_file") - @mock.patch("openstackclient.common.context._setup_handler_for_logging") - def test_shell_args_precedence_3(self, setup_handler, config_mock, - vendor_mock): - config_mock.return_value = ('file.yaml', copy.deepcopy(CLOUD_2)) - vendor_mock.return_value = ('file.yaml', copy.deepcopy(PUBLIC_1)) - setup_handler.return_value = mock.MagicMock() - _shell = make_shell() - - # Test enable_operation_logging set - fake_execute( - _shell, - "--os-cloud megacloud list user", - ) - self.assertEqual( - True, - _shell.enable_operation_logging, - )