Create log configuration class

Configuration of logging gets triggered twice.  The first time it
uses the CLI options when the application is started and second
it uses the configuration file after that is read.  The state of
the logging needs to be saved from the first to the second time,
so I created a class.

Implements: blueprint logging-migration

Change-Id: I7b8d1a3b6fd128e98cafd7c16009c7b694a52146

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):
+class LogConfigurator(object):
-    """Setup of the handler for set the logging level
 
-        :param handler_type: type of logging handler
+    _CONSOLE_MESSAGE_FORMAT = '%(message)s'
-        :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)
 
+    def __init__(self, options):
+        self.root_logger = logging.getLogger('')
+        self.root_logger.setLevel(logging.DEBUG)
 
-def setup_logging(shell, cloud_config):
+        # Force verbose_level 3 on --debug
-    """Get one cloud configuration from configuration file and setup logging
+        self.dump_trace = False
+        if options.debug:
+            options.verbose_level = 3
+            self.dump_trace = True
 
-        :param shell: instance of openstackclient shell
+        # Always send higher-level messages to the console via stderr
-        :param cloud_config:
+        self.console_logger = logging.StreamHandler(sys.stderr)
-            instance of the cloud specified by --os-cloud
+        log_level = log_level_from_options(options)
-            in the configuration file
+        self.console_logger.setLevel(log_level)
-        :return: None
+        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 the warning filter now
-    set_warning_filter(log_level)
+        set_warning_filter(log_level)
 
-    log_file = cloud_config.config.get('log_file', None)
+        # Set up logging to a file
-    if log_file:
+        self.file_logger = None
-        # setup the logging context
+        log_file = options.log_file
-        formatter = _FileFormatter(config=cloud_config)
+        if log_file:
-        # setup the logging handler
+            self.file_logger = logging.FileHandler(filename=log_file)
-        log_handler = _setup_handler_for_logging(
+            self.file_logger.setFormatter(_FileFormatter(options=options))
-            logging.FileHandler,
+            self.file_logger.setLevel(log_level)
-            log_level,
+            self.root_logger.addHandler(self.file_logger)
-            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)
 
+        # 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):
+        # Other modules we don't want DEBUG output for
-    """Setup of the handler
+        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,
+        if options.debug:
-       changes of the logging format, change of the logging level,
+            # --debug forces traceback
+            requests_log.setLevel(logging.DEBUG)
+        else:
+            requests_log.setLevel(logging.ERROR)
 
-        :param handler_type: type of logging handler
+        cliff_log.setLevel(logging.ERROR)
-        :param level: logging level
+        stevedore_log.setLevel(logging.ERROR)
-        :param file_name: name of log-file
+        iso8601_log.setLevel(logging.ERROR)
-        :param formatter: instance of logging.Formatter
-        :return: logging handler
-    """
 
-    root_logger = logging.getLogger('')
+    def configure(self, cloud_config):
-    handler = None
+        log_level = log_level_from_config(cloud_config.config)
-    # Setup handler for FileHandler(--os-cloud)
+        set_warning_filter(log_level)
-    handler = logging.FileHandler(
+        self.dump_trace = cloud_config.config.get('debug', self.dump_trace)
-        filename=file_name,
+        self.console_logger.setLevel(log_level)
-    )
-    handler.setFormatter(formatter)
-    handler.setLevel(level)
 
-    # If both `--log-file` and `--os-cloud` are specified,
+        log_file = cloud_config.config.get('log_file', None)
-    # the log is output to each file.
+        if log_file:
-    root_logger.addHandler(handler)
+            if not self.file_logger:
-
+                self.file_logger = logging.FileHandler(filename=log_file)
-    return handler
+            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)

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
+        """Configure logging for the app."""
-
+        self.log_configurator = context.LogConfigurator(self.options)
-        Cliff sets some defaults we don't want so re-work it a bit
+        self.dump_stack_trace = self.log_configurator.dump_trace
-        """
-
-        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
 
     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
+        self.log_configurator.configure(self.cloud)
-        context.setup_logging(self, 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)

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)

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, config_mock, public_mock):
-    def test_shell_args_cloud_public(self, setup_handler, 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, config_mock, vendor_mock):
-    def test_shell_args_precedence(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 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, config_mock, vendor_mock):
-    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()
 
         # 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, config_mock, vendor_mock):
-    def test_shell_args_precedence_2(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 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,
-        )