diff --git a/doc/source/configuration.rst b/doc/source/configuration.rst index 563a7193ea..c770014091 100644 --- a/doc/source/configuration.rst +++ b/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` diff --git a/doc/source/man/openstack.rst b/doc/source/man/openstack.rst index 53bf36299b..3e47635e0f 100644 --- a/doc/source/man/openstack.rst +++ b/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 ===== diff --git a/openstackclient/common/context.py b/openstackclient/common/context.py new file mode 100644 index 0000000000..b7b16e9441 --- /dev/null +++ b/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) diff --git a/openstackclient/shell.py b/openstackclient/shell.py index 27bcba4891..01d6ce8a3c 100644 --- a/openstackclient/shell.py +++ b/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, - 'auth_type': auth_type, }) - self.log.debug("defaults: %s", cc.defaults) + override_defaults={ + 'interface': None, + '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 diff --git a/openstackclient/tests/common/test_context.py b/openstackclient/tests/common/test_context.py new file mode 100644 index 0000000000..145546a3c3 --- /dev/null +++ b/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) diff --git a/openstackclient/tests/test_shell.py b/openstackclient/tests/test_shell.py index 0e0cc50b54..5db04e7c99 100644 --- a/openstackclient/tests/test_shell.py +++ b/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, + )