Merge "Create log configuration class"

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 0623d82d..c08d619d 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 5db04e7c..c548d890 100644
--- a/openstackclient/tests/test_shell.py
+++ b/openstackclient/tests/test_shell.py
@@ -625,12 +625,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(
@@ -668,12 +665,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
@@ -725,12 +719,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
@@ -769,12 +760,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
@@ -812,77 +800,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,
-        )