Merge "Set up every time record log in file"

doc/source/configuration.rst

@@ -143,3 +143,74 @@ Debugging
 You may find the :doc:`config show <command-objects/config>`
 helpful to debug configuration issues.  It will display your current
 configuration.
+
+Logging Settings
+----------------
+
+By setting `log_level` or `log_file` in the configuration
+:file:`clouds.yaml`, a user may enable additional logging::
+
+    clouds:
+      devstack:
+        auth:
+          auth_url: http://192.168.122.10:35357/
+          project_name: demo
+          username: demo
+          password: 0penstack
+        region_name: RegionOne
+        operation_log:
+          logging: TRUE
+          file: /tmp/openstackclient_demo.log
+          level: info
+      ds-admin:
+        auth:
+          auth_url: http://192.168.122.10:35357/
+          project_name: admin
+          username: admin
+          password: 0penstack
+        region_name: RegionOne
+        log_file: /tmp/openstackclient_admin.log
+        log_level: debug
+
+:dfn:`log_file`: ``</path/file-name>``
+    Full path to logging file.
+:dfn:`log_level`: ``error`` | ``info`` | ``debug``
+    If log level is not set, ``warning`` will be used.
+
+If log level is ``info``, the following information is recorded:
+
+* cloud name
+* user name
+* project name
+* CLI start time (logging start time)
+* CLI end time
+* CLI arguments
+* CLI return value
+* and any ``info`` messages.
+
+If log level is ``debug``, the following information is recorded:
+
+* cloud name
+* user name
+* project name
+* CLI start time (logging start time)
+* CLI end time
+* CLI arguments
+* CLI return value
+* API request header/body
+* API response header/body
+* and any ``debug`` messages.
+
+When a command is executed, these logs are saved every time. Recording the user
+operations can help to identify resource changes and provide useful information
+for troubleshooting.
+
+If saving the output of a single command use the `--log-file` option instead.
+
+* `--log-file <LOG_FILE>`
+
+The logging level for `--log-file` can be set by using following options.
+
+*  `-v, --verbose`
+*  `-q, --quiet`
+*  `--debug`

doc/source/man/openstack.rst

@@ -123,6 +123,18 @@ OPTIONS
 :option:`--os-interface` <interface>
     Interface type. Valid options are `public`, `admin` and `internal`.
 
+:option:`--log-file` <LOGFILE>
+    Specify a file to log output. Disabled by default.
+
+:option:`-v, --verbose`
+    Increase verbosity of output. Can be repeated.
+
+:option:`-q, --quiet`
+    suppress output except warnings and errors
+
+:option:`--debug`
+    show tracebacks on errors and set verbosity to debug
+
 COMMANDS
 ========
 
@@ -240,6 +252,15 @@ When :option:`--os-token` and :option:`--os-url` are both present the
 :option:`--os-auth-url` and :option:`--os-username` are present ``password``
 auth type is selected.
 
+Logging Settings
+----------------
+
+:program:`openstack` can record the operation history by logging settings
+in configuration file. Recording the user operation, it can identify the
+change of the resource and it becomes useful information for troubleshooting.
+
+See :doc:`../configuration` about Logging Settings for more details.
+
 
 NOTES
 =====

openstackclient/common/context.py

@@ -0,0 +1,149 @@
+#   Licensed under the Apache License, Version 2.0 (the "License"); you may
+#   not use this file except in compliance with the License. You may obtain
+#   a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#   WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#   License for the specific language governing permissions and limitations
+#   under the License.
+#
+
+"""Context and Formatter"""
+
+import logging
+
+_LOG_MESSAGE_FORMAT = ('%(asctime)s.%(msecs)03d %(process)d '
+                       '%(levelname)s %(name)s [%(clouds_name)s '
+                       '%(username)s %(project_name)s] %(message)s')
+_LOG_DATE_FORMAT = '%Y-%m-%d %H:%M:%S'
+
+
+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 = logging.WARNING
+    log_file = cloud_config.config.get('log_file', None)
+    if log_file:
+        # setup the logging level
+        get_log_level = cloud_config.config.get('log_level')
+        if get_log_level:
+            log_level = {
+                'error': logging.ERROR,
+                'info': logging.INFO,
+                'debug': logging.DEBUG,
+            }.get(get_log_level, logging.WARNING)
+
+        # setup the logging context
+        log_cont = _LogContext(
+            clouds_name=cloud_config.config.get('cloud'),
+            project_name=cloud_config.auth.get('project_name'),
+            username=cloud_config.auth.get('username'),
+        )
+        # setup the logging handler
+        log_handler = _setup_handler_for_logging(
+            logging.FileHandler,
+            log_level,
+            file_name=log_file,
+            context=log_cont,
+        )
+        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, context):
+    """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 context: instance of _LogContext()
+        :return: logging handler
+    """
+
+    root_logger = logging.getLogger('')
+    handler = None
+    # Setup handler for FileHandler(--os-cloud)
+    handler = logging.FileHandler(
+        filename=file_name,
+    )
+    formatter = _LogContextFormatter(
+        context=context,
+        fmt=_LOG_MESSAGE_FORMAT,
+        datefmt=_LOG_DATE_FORMAT,
+    )
+    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 _LogContext(object):
+    """Helper class to represent useful information about a logging context"""
+
+    def __init__(self, clouds_name=None, project_name=None, username=None):
+        """Initialize _LogContext instance
+
+            :param clouds_name: one of the cloud name in configuration file
+            :param project_name: the project name in cloud(clouds_name)
+            :param username: the user name in cloud(clouds_name)
+        """
+
+        self.clouds_name = clouds_name
+        self.project_name = project_name
+        self.username = username
+
+    def to_dict(self):
+        return {
+            'clouds_name': self.clouds_name,
+            'project_name': self.project_name,
+            'username': self.username
+        }
+
+
+class _LogContextFormatter(logging.Formatter):
+    """Customize the logging format for logging handler"""
+
+    def __init__(self, *args, **kwargs):
+        self.context = kwargs.pop('context', None)
+        logging.Formatter.__init__(self, *args, **kwargs)
+
+    def format(self, record):
+        d = self.context.to_dict()
+        for k, v in d.items():
+            setattr(record, k, v)
+        return logging.Formatter.format(self, record)

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/common/test_context.py

@@ -0,0 +1,102 @@
+#   Licensed under the Apache License, Version 2.0 (the "License"); you may
+#   not use this file except in compliance with the License. You may obtain
+#   a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#   WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#   License for the specific language governing permissions and limitations
+#   under the License.
+#
+
+import logging
+import mock
+import os
+
+from openstackclient.common import context
+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)
+
+
+class Test_LogContext(utils.TestCase):
+    def setUp(self):
+        super(Test_LogContext, self).setUp()
+
+    def test_context(self):
+        ctx = context._LogContext()
+        self.assertTrue(ctx)
+
+    def test_context_to_dict(self):
+        ctx = context._LogContext('cloudsName', 'projectName', 'userNmae')
+        ctx_dict = ctx.to_dict()
+        self.assertEqual('cloudsName', ctx_dict['clouds_name'])
+        self.assertEqual('projectName', ctx_dict['project_name'])
+        self.assertEqual('userNmae', ctx_dict['username'])
+
+
+class Test_LogContextFormatter(utils.TestCase):
+    def setUp(self):
+        super(Test_LogContextFormatter, self).setUp()
+        self.ctx = context._LogContext('cloudsName', 'projectName', 'userNmae')
+        self.addfmt = "%(clouds_name)s %(project_name)s %(username)s"
+
+    def test_contextrrormatter(self):
+        ctxfmt = context._LogContextFormatter()
+        self.assertTrue(ctxfmt)
+
+    def test_context_format(self):
+        record = mock.MagicMock()
+        logging.Formatter.format = mock.MagicMock()
+        logging.Formatter.format.return_value = record
+
+        ctxfmt = context._LogContextFormatter(context=self.ctx,
+                                              fmt=self.addfmt)
+        addctx = ctxfmt.format(record)
+        self.assertEqual('cloudsName', addctx.clouds_name)
+        self.assertEqual('projectName', addctx.project_name)
+        self.assertEqual('userNmae', addctx.username)

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',
         }
     }
 }
@@ -623,9 +625,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(
@@ -663,9 +668,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
@@ -717,9 +725,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
@@ -758,9 +769,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
@@ -798,3 +812,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,
+        )