Set up every time record log in file

This will allow users to record logs of all their commands into
a predefined log file, in clouds.yaml. The log should have a
format similar to that of oslo.log.

Change-Id: I1b334bf429d575fc25809c9706fc0b11116be3f1
Implements: blueprint every-time-record-log-in-file

openstackclient/shell.py

@@ -30,6 +30,7 @@ from cliff import help
 import openstackclient
 from openstackclient.common import clientmanager
 from openstackclient.common import commandmanager
+from openstackclient.common import context
 from openstackclient.common import exceptions as exc
 from openstackclient.common import timing
 from openstackclient.common import utils
@@ -95,6 +96,10 @@ class OpenStackShell(app.App):
 
         self.client_manager = None
 
+        # Operation log
+        self.enable_operation_logging = False
+        self.command_options = None
+
     def configure_logging(self):
         """Configure logging for the app
 
@@ -107,24 +112,30 @@ class OpenStackShell(app.App):
             self.options.verbose_level = 3
 
         super(OpenStackShell, self).configure_logging()
-        root_logger = logging.getLogger('')
 
         # Set logging to the requested level
         if self.options.verbose_level == 0:
             # --quiet
-            root_logger.setLevel(logging.ERROR)
+            log_level = logging.ERROR
             warnings.simplefilter("ignore")
         elif self.options.verbose_level == 1:
             # This is the default case, no --debug, --verbose or --quiet
-            root_logger.setLevel(logging.WARNING)
+            log_level = logging.WARNING
             warnings.simplefilter("ignore")
         elif self.options.verbose_level == 2:
             # One --verbose
-            root_logger.setLevel(logging.INFO)
+            log_level = logging.INFO
             warnings.simplefilter("once")
         elif self.options.verbose_level >= 3:
             # Two or more --verbose
-            root_logger.setLevel(logging.DEBUG)
+            log_level = logging.DEBUG
+
+        # 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
@@ -147,9 +158,17 @@ class OpenStackShell(app.App):
         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
+        self.command_options = argv
         try:
-            return super(OpenStackShell, self).run(argv)
+            ret_val = super(OpenStackShell, self).run(argv)
+            return ret_val
         except Exception as e:
             if not logging.getLogger('').handlers:
                 logging.basicConfig()
@@ -157,7 +176,13 @@ class OpenStackShell(app.App):
                 self.log.error(traceback.format_exc(e))
             else:
                 self.log.error('Exception raised: ' + str(e))
-            return 1
+                if self.enable_operation_logging:
+                    self.operation_log.error(traceback.format_exc(e))
+
+            return ret_val
+
+        finally:
+            self.log.info("END return value: %s", ret_val)
 
     def build_option_parser(self, description, version):
         parser = super(OpenStackShell, self).build_option_parser(
@@ -243,7 +268,6 @@ class OpenStackShell(app.App):
             auth_type = 'token_endpoint'
         else:
             auth_type = 'osc_password'
-        self.log.debug("options: %s", self.options)
 
         project_id = getattr(self.options, 'project_id', None)
         project_name = getattr(self.options, 'project_name', None)
@@ -266,14 +290,23 @@ class OpenStackShell(app.App):
         # Ignore the default value of interface. Only if it is set later
         # will it be used.
         cc = cloud_config.OpenStackConfig(
-            override_defaults={'interface': None,
+            override_defaults={
-                               'auth_type': auth_type, })
+                'interface': None,
-        self.log.debug("defaults: %s", cc.defaults)
+                'auth_type': auth_type,
+                },
+            )
 
         self.cloud = cc.get_one_cloud(
             cloud=self.options.cloud,
             argparse=self.options,
         )
+
+        # Set up every time record log in file and logging start
+        context.setup_logging(self, self.cloud)
+
+        self.log.info("START with options: %s", self.command_options)
+        self.log.debug("options: %s", self.options)
+        self.log.debug("defaults: %s", cc.defaults)
         self.log.debug("cloud cfg: %s", self.cloud.config)
 
         # Set up client TLS

openstackclient/tests/test_shell.py

@@ -77,6 +77,8 @@ CLOUD_2 = {
                 'username': 'zaphod',
             },
             'region_name': 'occ-cloud',
+            'log_file': '/tmp/test_log_file',
+            'log_level': 'debug',
         }
     }
 }
@@ -621,9 +623,12 @@ class TestShellCli(TestShell):
 
     @mock.patch("os_client_config.config.OpenStackConfig._load_vendor_file")
     @mock.patch("os_client_config.config.OpenStackConfig._load_config_file")
-    def test_shell_args_cloud_public(self, config_mock, public_mock):
+    @mock.patch("openstackclient.common.context._setup_handler_for_logging")
+    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(
@@ -661,9 +666,12 @@ class TestShellCli(TestShell):
 
     @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(self, config_mock, vendor_mock):
+    @mock.patch("openstackclient.common.context._setup_handler_for_logging")
+    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
@@ -715,9 +723,12 @@ class TestShellCliEnv(TestShell):
 
     @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_1(self, config_mock, vendor_mock):
+    @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()
 
         # Test env var
@@ -756,9 +767,12 @@ class TestShellCliEnv(TestShell):
 
     @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):
+    @mock.patch("openstackclient.common.context._setup_handler_for_logging")
+    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
@@ -796,3 +810,77 @@ 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,
+        )