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

4 files changed, 189 insertions, 262 deletions

diff --git a/openstackclient/common/context.py b/openstackclient/common/context.py
index 57091939..6d1aec13 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
-
-        :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)
-
-
-def setup_logging(shell, cloud_config):
-    """Get one cloud configuration from configuration file and setup logging
-
-        :param shell: instance of openstackclient shell
-        :param cloud_config:
-            instance of the cloud specified by --os-cloud
-            in the configuration file
-        :return: None
-    """
-
-    log_level = log_level_from_config(cloud_config.config)
-    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)
-
-
-def _setup_handler_for_logging(handler_type, level, file_name, formatter):
-    """Setup of the handler
-
-       Setup of the handler for addition of the logging handler,
-       changes of the logging format, change of the logging level,
-
-        :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
-    """
-
-    root_logger = logging.getLogger('')
-    handler = None
-    # Setup handler for FileHandler(--os-cloud)
-    handler = logging.FileHandler(
-        filename=file_name,
-    )
-    handler.setFormatter(formatter)
-    handler.setLevel(level)
-
-    # If both `--log-file` and `--os-cloud` are specified,
-    # the log is output to each file.
-    root_logger.addHandler(handler)
-
-    return handler
+class LogConfigurator(object):
+
+    _CONSOLE_MESSAGE_FORMAT = '%(message)s'
+
+    def __init__(self, options):
+        self.root_logger = logging.getLogger('')
+        self.root_logger.setLevel(logging.DEBUG)
+
+        # Force verbose_level 3 on --debug
+        self.dump_trace = False
+        if options.debug:
+            options.verbose_level = 3
+            self.dump_trace = True
+
+        # 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)
+
+        # Set the warning filter now
+        set_warning_filter(log_level)
+
+        # 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")
+
+        # 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 options.debug:
+            # --debug forces traceback
+            requests_log.setLevel(logging.DEBUG)
+        else:
+            requests_log.setLevel(logging.ERROR)
+
+        cliff_log.setLevel(logging.ERROR)
+        stevedore_log.setLevel(logging.ERROR)
+        iso8601_log.setLevel(logging.ERROR)
+
+    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)
+
+        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 6ba19d19..72f663a0 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 cc213b13..55e42851 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 5b844753..cacd2fb7 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,
-        )