diff --git a/src/azure/cli/_debug.py b/src/azure/cli/_debug.py index 806fcb252f8..b99f9401635 100644 --- a/src/azure/cli/_debug.py +++ b/src/azure/cli/_debug.py @@ -1,5 +1,7 @@ import os -from ._logging import logger +import azure.cli._logging as _logging + +logger = _logging.get_az_logger(__name__) DISABLE_VERIFY_VARIABLE_NAME = "AZURE_CLI_DISABLE_CONNECTION_VERIFICATION" diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index 47b45839b47..d56ee4e0d14 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -1,59 +1,92 @@ -import logging as _logging -import sys +import os +import logging +from logging.handlers import RotatingFileHandler -__all__ = ['logger', 'configure_logging'] +CONSOLE_LOG_CONFIGS = [ + # (default) + { + 'az': logging.WARNING, + 'root': logging.CRITICAL, + }, + # --verbose + { + 'az': logging.INFO, + 'root': logging.CRITICAL, + }, + # --debug + { + 'az': logging.DEBUG, + 'root': logging.DEBUG, + }] -logger = _logging.Logger('az', _logging.WARNING) +AZ_LOGFILE_NAME = 'az.log' +DEFAULT_LOG_DIR = os.path.expanduser(os.path.join('~', '.azure', 'logs')) -def _arg_name(arg): - a = arg.lstrip('-/') - if a == arg: - return None - return a.lower() +ENABLE_LOG_FILE = os.environ.get('AZURE_CLI_ENABLE_LOG_FILE') +LOG_DIR = os.environ.get('AZURE_CLI_LOG_DIR') -def configure_logging(argv, config): - level = _logging.WARNING - - # Load logging info from config - if config.get('verbose'): - level = _logging.INFO - if config.get('debug'): - level = _logging.DEBUG - logfile = config.get('log') - - # Load logging info from arguments - # Also remove any arguments consumed so that the parser does not - # have to explicitly ignore them. +def _determine_verbose_level(argv): + # Get verbose level by reading the arguments. + # Remove any consumed args. + verbose_level = 0 i = 0 while i < len(argv): - arg = _arg_name(argv[i]) - if arg in ('v', 'verbose'): - level = min(_logging.INFO, level) - argv.pop(i) - elif arg in ('debug',): - level = min(_logging.DEBUG, level) + arg = argv[i] + if arg in ['--verbose']: + verbose_level += 1 argv.pop(i) - elif arg in ('log',): + elif arg in ['--debug']: + verbose_level += 2 argv.pop(i) - try: - logfile = argv.pop(i) - except IndexError: - pass else: i += 1 + # Use max verbose level if too much verbosity specified. + return verbose_level if verbose_level < len(CONSOLE_LOG_CONFIGS) else len(CONSOLE_LOG_CONFIGS)-1 + +def _init_console_handlers(root_logger, az_logger, log_level_config): + console_log_format = logging.Formatter('%(levelname)s: %(message)s') + + root_console_handler = logging.StreamHandler() + root_console_handler.setFormatter(console_log_format) + root_console_handler.setLevel(log_level_config['root']) + root_logger.addHandler(root_console_handler) + + az_console_handler = logging.StreamHandler() + az_console_handler.setFormatter(console_log_format) + az_console_handler.setLevel(log_level_config['az']) + az_logger.addHandler(az_console_handler) + +def _get_log_file_path(): + log_dir = LOG_DIR or DEFAULT_LOG_DIR + if not os.path.isdir(log_dir): + os.makedirs(log_dir) + return os.path.join(log_dir, AZ_LOGFILE_NAME) + +def _init_logfile_handlers(root_logger, az_logger): + if not ENABLE_LOG_FILE: + return + log_file_path = _get_log_file_path() + logfile_handler = RotatingFileHandler(log_file_path, maxBytes=5*1024*1024, backupCount=5) + lfmt = logging.Formatter('%(process)d : %(asctime)s : %(name)s : %(levelname)s : %(message)s') + logfile_handler.setFormatter(lfmt) + logfile_handler.setLevel(logging.DEBUG) + root_logger.addHandler(logfile_handler) + az_logger.addHandler(logfile_handler) + +def configure_logging(argv): + verbose_level = _determine_verbose_level(argv) + log_level_config = CONSOLE_LOG_CONFIGS[verbose_level] + + root_logger = logging.getLogger() + az_logger = logging.getLogger('az') + # Set the levels of the loggers to lowest level. + # Handlers can override by choosing a higher level. + root_logger.setLevel(logging.DEBUG) + az_logger.setLevel(logging.DEBUG) + az_logger.propagate = False + + _init_console_handlers(root_logger, az_logger, log_level_config) + _init_logfile_handlers(root_logger, az_logger) - # Configure the console output handler - stderr_handler = _logging.StreamHandler(sys.stderr) - stderr_handler.formatter = _logging.Formatter('%(levelname)s: %(message)s') - logger.level = stderr_handler.level = level - logger.handlers.append(stderr_handler) - - # Set logging level for all loggers - _logging.basicConfig(level=level) - - if logfile: - # Configure the handler that logs code to a text file - log_handler = _logging.StreamHandler(open(logfile, 'w', encoding='utf-8')) - log_handler.formatter = _logging.Formatter('[%(levelname)s:%(asctime)s] %(message)s') - log_handler.level = level if level == _logging.DEBUG else _logging.INFO - logger.handlers.append(log_handler) +def get_az_logger(module_name=None): + return logging.getLogger('az.' + module_name if module_name else 'az') diff --git a/src/azure/cli/application.py b/src/azure/cli/application.py index 5c68c23d7f9..d2b710984d2 100644 --- a/src/azure/cli/application.py +++ b/src/azure/cli/application.py @@ -3,7 +3,6 @@ import sys import re import argparse -import logging from enum import Enum from .parser import AzCliCommandParser import azure.cli.extensions @@ -15,7 +14,6 @@ class Configuration(object): # pylint: disable=too-few-public-methods """ def __init__(self, argv): self.argv = argv or sys.argv[1:] - self.log = logging.getLogger('az') self.output_format = 'list' def get_command_table(self): @@ -141,6 +139,11 @@ def _register_builtin_arguments(parser): parser.add_argument('--output', '-o', dest='_output_format', choices=['list', 'json', 'tsv'], help='Output format of type "list", "json" or "tsv"') + # The arguments for verbosity don't get parsed by argparse but we add it here for help. + parser.add_argument('--verbose', dest='_log_verbosity_verbose', + help='Increase logging verbosity. Use --debug for full debug logs.') + parser.add_argument('--debug', dest='_log_verbosity_debug', + help='Increase logging verbosity to show all debug logs.') def _handle_builtin_arguments(self, args): self.configuration.output_format = args._output_format #pylint: disable=protected-access diff --git a/src/azure/cli/main.py b/src/azure/cli/main.py index fb60fdba8db..967894f7033 100644 --- a/src/azure/cli/main.py +++ b/src/azure/cli/main.py @@ -3,10 +3,12 @@ from .application import Application, Configuration -from ._logging import configure_logging, logger +import azure.cli._logging as _logging from ._session import Session from ._output import OutputProducer +logger = _logging.get_az_logger(__name__) + #ACCOUNT contains subscriptions information # this file will be shared with azure-xplat-cli, which assumes ascii ACCOUNT = Session('ascii') @@ -18,6 +20,8 @@ SESSION = Session() def main(args, file=sys.stdout): #pylint: disable=redefined-builtin + _logging.configure_logging(args) + azure_folder = os.path.expanduser('~/.azure') if not os.path.exists(azure_folder): os.makedirs(azure_folder) @@ -25,8 +29,6 @@ def main(args, file=sys.stdout): #pylint: disable=redefined-builtin CONFIG.load(os.path.join(azure_folder, 'az.json')) SESSION.load(os.path.join(azure_folder, 'az.sess'), max_age=3600) - configure_logging(args, CONFIG) - from ._locale import install as locale_install locale_install(os.path.join(os.path.dirname(os.path.abspath(__file__)), 'locale', diff --git a/src/azure/cli/tests/test_connection_verify.py b/src/azure/cli/tests/test_connection_verify.py index ca6444f7ddf..f07a7701f22 100644 --- a/src/azure/cli/tests/test_connection_verify.py +++ b/src/azure/cli/tests/test_connection_verify.py @@ -6,7 +6,6 @@ from mock import MagicMock from azure.cli.parser import IncorrectUsageError -from azure.cli._logging import logger import logging import azure.cli._debug as _debug diff --git a/src/azure/cli/tests/test_help.py b/src/azure/cli/tests/test_help.py index 76e9715d416..149cde05f92 100644 --- a/src/azure/cli/tests/test_help.py +++ b/src/azure/cli/tests/test_help.py @@ -5,7 +5,6 @@ import sys from six import StringIO -from azure.cli._logging import logger from azure.cli.parser import AzCliCommandParser from azure.cli.application import Application, Configuration from azure.cli.commands import CommandTable diff --git a/src/azure/cli/tests/test_logging.py b/src/azure/cli/tests/test_logging.py new file mode 100644 index 00000000000..ed5d8d49170 --- /dev/null +++ b/src/azure/cli/tests/test_logging.py @@ -0,0 +1,63 @@ +import unittest +import azure.cli._logging as _logging + +class TestLogging(unittest.TestCase): + + # When running verbose level tests, we check that argv is empty + # as we expect _determine_verbose_level to remove consumed arguments. + + def test_determine_verbose_level_default(self): + argv = [] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 0 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_verbose(self): + argv = ['--verbose'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 1 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_debug(self): + argv = ['--debug'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 2 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_v_v_v_default(self): + argv = ['--verbose', '--debug'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 2 + self.assertEqual(actual_level, expected_level) + # We still consumed the arguments + self.assertFalse(argv) + + def test_determine_verbose_level_other_args_verbose(self): + argv = ['account', '--verbose'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 1 + self.assertEqual(actual_level, expected_level) + # We consumed 1 argument + self.assertEqual(argv, ['account']) + + def test_determine_verbose_level_other_args_debug(self): + argv = ['account', '--debug'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 2 + self.assertEqual(actual_level, expected_level) + # We consumed 1 argument + self.assertEqual(argv, ['account']) + + def test_get_az_logger(self): + az_logger = _logging.get_az_logger() + self.assertEqual(az_logger.name, 'az') + + def test_get_az_logger_module(self): + az_module_logger = _logging.get_az_logger('azure.cli.module') + self.assertEqual(az_module_logger.name, 'az.azure.cli.module') + +if __name__ == '__main__': + unittest.main() diff --git a/src/azure/cli/utils/command_test_util.py b/src/azure/cli/utils/command_test_util.py index 29123be18c3..5c023693800 100644 --- a/src/azure/cli/utils/command_test_util.py +++ b/src/azure/cli/utils/command_test_util.py @@ -35,7 +35,6 @@ class CommandTestGenerator(object): def __init__(self, recording_dir, test_def, env_var): self.test_def = test_def self.recording_dir = recording_dir - logging.basicConfig() logging.getLogger('vcr').setLevel(logging.ERROR) self.my_vcr = vcr.VCR( cassette_library_dir=recording_dir, diff --git a/src/command_modules/azure-cli-profile/azure/cli/command_modules/profile/account.py b/src/command_modules/azure-cli-profile/azure/cli/command_modules/profile/account.py index d5feeb6af26..511231c4b64 100644 --- a/src/command_modules/azure-cli-profile/azure/cli/command_modules/profile/account.py +++ b/src/command_modules/azure-cli-profile/azure/cli/command_modules/profile/account.py @@ -2,7 +2,9 @@ from azure.cli.commands import CommandTable from azure.cli._locale import L from .command_tables import COMMAND_TABLES -from azure.cli._logging import logger +import azure.cli._logging as _logging + +logger = _logging.get_az_logger(__name__) command_table = CommandTable()