From 31b313fee73ecbb308c6c4e18bdebb6fe3c86d16 Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Wed, 27 Apr 2016 14:52:10 -0700 Subject: [PATCH 1/7] Create logging infrastructure --- src/azure/cli/_debug.py | 4 +- src/azure/cli/_logging.py | 107 +++++++++--------- src/azure/cli/application.py | 4 +- src/azure/cli/main.py | 8 +- src/azure/cli/tests/test_connection_verify.py | 1 - src/azure/cli/tests/test_help.py | 1 - .../cli/command_modules/profile/account.py | 4 +- 7 files changed, 68 insertions(+), 61 deletions(-) diff --git a/src/azure/cli/_debug.py b/src/azure/cli/_debug.py index 806fcb252f8..d881e28b22b 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.getAzLogger(__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..9f6a1e1cff7 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -1,59 +1,62 @@ -import logging as _logging -import sys - -__all__ = ['logger', 'configure_logging'] - -logger = _logging.Logger('az', _logging.WARNING) - -def _arg_name(arg): - a = arg.lstrip('-/') - if a == arg: - return None - return a.lower() - -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. +import logging + +LOG_LEVEL_CONFIGS = [ + # (default) + { + 'az': logging.WARNING, + 'root': logging.CRITICAL, + }, + # -v + { + 'az': logging.INFO, + 'root': logging.CRITICAL, + }, + # -vv + { + 'az': logging.DEBUG, + 'root': logging.DEBUG, + }] + +def _determine_verbose_level(argv): + # Get verbose level by reading the arguments. + # Remove any consumed args. + verbose_level = 0 i = 0 + # TODO: WRITE TESTS FOR THIS while i < len(argv): - arg = _arg_name(argv[i]) - if arg in ('v', 'verbose'): - level = min(_logging.INFO, level) + arg = argv[i] + if arg in ['-v', '--verbose']: + verbose_level += 1 argv.pop(i) - elif arg in ('debug',): - level = min(_logging.DEBUG, level) + elif arg in ['-vv'] and verbose_level == 0: + verbose_level = 2 argv.pop(i) - elif arg in ('log',): - argv.pop(i) - try: - logfile = argv.pop(i) - except IndexError: - pass else: i += 1 + return verbose_level + +def _configure_root_logger(log_level_config): + root_logger = logging.getLogger() + root_logger.setLevel(log_level_config['root']) + +def _configure_az_logger(log_level_config): + az_logger = logging.getLogger('az') + az_logger.setLevel(log_level_config['az']) + +def _init_console_handler(): + logging.basicConfig(format='%(levelname)s: %(message)s') + +def configure_logging(argv): + verbose_level = _determine_verbose_level(argv) + + try: + log_level_config = LOG_LEVEL_CONFIGS[verbose_level] + except IndexError: + log_level_config = LOG_LEVEL_CONFIGS[0] + + _init_console_handler() + _configure_root_logger(log_level_config) + _configure_az_logger(log_level_config) - # 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 getAzLogger(module_name): + return logging.getLogger('az.'+module_name) diff --git a/src/azure/cli/application.py b/src/azure/cli/application.py index b45644237b5..93a07eb1f5f 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): @@ -138,6 +136,8 @@ 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('-v', '--verbose', action="count", dest='_log_verbosity', help='Logging verbosity. Can be used up to 2 times.') 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..bb21ec17233 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.getAzLogger(__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 a55ff0f9844..09d18363e12 100644 --- a/src/azure/cli/tests/test_help.py +++ b/src/azure/cli/tests/test_help.py @@ -3,7 +3,6 @@ from six import StringIO from azure.cli.parser import ArgumentParser, IncorrectUsageError - from azure.cli._logging import logger from azure.cli.commands import command, description, option import azure.cli._help_files import logging 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..e1efeb09aff 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.getAzLogger(__name__) command_table = CommandTable() From 0a90bc555ba06f7249f8993971e172b6f04c4ba6 Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Wed, 27 Apr 2016 17:16:39 -0700 Subject: [PATCH 2/7] Add tests for logging config --- src/azure/cli/_logging.py | 18 +++--- src/azure/cli/application.py | 3 +- src/azure/cli/tests/test_logging.py | 96 +++++++++++++++++++++++++++++ 3 files changed, 105 insertions(+), 12 deletions(-) create mode 100644 src/azure/cli/tests/test_logging.py diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index 9f6a1e1cff7..ce861574ae7 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -22,18 +22,18 @@ def _determine_verbose_level(argv): # Remove any consumed args. verbose_level = 0 i = 0 - # TODO: WRITE TESTS FOR THIS while i < len(argv): arg = argv[i] if arg in ['-v', '--verbose']: verbose_level += 1 argv.pop(i) - elif arg in ['-vv'] and verbose_level == 0: - verbose_level = 2 + elif arg in ['-vv']: + verbose_level += 2 argv.pop(i) else: i += 1 - return verbose_level + # Default to 0 verbose level if too much verbosity specified. + return verbose_level if verbose_level < len(LOG_LEVEL_CONFIGS) else 0 def _configure_root_logger(log_level_config): root_logger = logging.getLogger() @@ -48,15 +48,11 @@ def _init_console_handler(): def configure_logging(argv): verbose_level = _determine_verbose_level(argv) - - try: - log_level_config = LOG_LEVEL_CONFIGS[verbose_level] - except IndexError: - log_level_config = LOG_LEVEL_CONFIGS[0] + log_level_config = LOG_LEVEL_CONFIGS[verbose_level] _init_console_handler() _configure_root_logger(log_level_config) _configure_az_logger(log_level_config) -def getAzLogger(module_name): - return logging.getLogger('az.'+module_name) +def getAzLogger(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 93a07eb1f5f..6656d733516 100644 --- a/src/azure/cli/application.py +++ b/src/azure/cli/application.py @@ -137,7 +137,8 @@ def _register_builtin_arguments(parser): 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('-v', '--verbose', action="count", dest='_log_verbosity', help='Logging verbosity. Can be used up to 2 times.') + parser.add_argument('-v', '--verbose', action="count", dest='_log_verbosity', + help='Logging verbosity. Can be used up to 2 times (-vv for short).') def _handle_builtin_arguments(self, args): self.configuration.output_format = args._output_format #pylint: disable=protected-access diff --git a/src/azure/cli/tests/test_logging.py b/src/azure/cli/tests/test_logging.py new file mode 100644 index 00000000000..a97e5b29997 --- /dev/null +++ b/src/azure/cli/tests/test_logging.py @@ -0,0 +1,96 @@ +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_v(self): + argv = ['-v'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 1 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_v_v(self): + argv = ['-v', '-v'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 2 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_verbose_verbose(self): + argv = ['--verbose', '--verbose'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 2 + self.assertEqual(actual_level, expected_level) + self.assertFalse(argv) + + def test_determine_verbose_level_vv(self): + argv = ['-vv'] + 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): + # User specified verbose 3 times (we only support 2) + # So default to verbose level of 0 + argv = ['-v', '-v', '-v'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 0 + self.assertEqual(actual_level, expected_level) + # We still consumed the arguments + self.assertFalse(argv) + + def test_determine_verbose_level_v_vv(self): + # Too much verbosity specified + argv = ['-v', '-vv'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 0 + self.assertEqual(actual_level, expected_level) + # We still consumed the arguments + self.assertFalse(argv) + + def test_determine_verbose_level_vv_v(self): + # Too much verbosity specified + argv = ['-vv', '-v'] + actual_level = _logging._determine_verbose_level(argv) + expected_level = 0 + self.assertEqual(actual_level, expected_level) + # We still consumed the arguments + self.assertFalse(argv) + + def test_determine_verbose_level_other_args(self): + argv = ['account', '-v'] + 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_get_az_logger(self): + az_logger = _logging.getAzLogger() + self.assertEqual(az_logger.name, 'az') + + def test_get_az_logger_module(self): + az_module_logger = _logging.getAzLogger('azure.cli.module') + self.assertEqual(az_module_logger.name, 'az.azure.cli.module') + +if __name__ == '__main__': + unittest.main() From 662fa878382dd04217733755ca102b694450788e Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Thu, 28 Apr 2016 09:39:24 -0700 Subject: [PATCH 3/7] Use max verbose level if too much verbosity specified & function rename --- src/azure/cli/_debug.py | 2 +- src/azure/cli/_logging.py | 6 +++--- src/azure/cli/main.py | 2 +- src/azure/cli/tests/test_logging.py | 12 ++++++------ .../azure/cli/command_modules/profile/account.py | 2 +- 5 files changed, 12 insertions(+), 12 deletions(-) diff --git a/src/azure/cli/_debug.py b/src/azure/cli/_debug.py index d881e28b22b..b99f9401635 100644 --- a/src/azure/cli/_debug.py +++ b/src/azure/cli/_debug.py @@ -1,7 +1,7 @@ import os import azure.cli._logging as _logging -logger = _logging.getAzLogger(__name__) +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 ce861574ae7..e7842f649e7 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -32,8 +32,8 @@ def _determine_verbose_level(argv): argv.pop(i) else: i += 1 - # Default to 0 verbose level if too much verbosity specified. - return verbose_level if verbose_level < len(LOG_LEVEL_CONFIGS) else 0 + # Use max verbose level if too much verbosity specified. + return verbose_level if verbose_level < len(LOG_LEVEL_CONFIGS) else len(LOG_LEVEL_CONFIGS)-1 def _configure_root_logger(log_level_config): root_logger = logging.getLogger() @@ -54,5 +54,5 @@ def configure_logging(argv): _configure_root_logger(log_level_config) _configure_az_logger(log_level_config) -def getAzLogger(module_name=None): +def get_az_logger(module_name=None): return logging.getLogger('az.' + module_name if module_name else 'az') diff --git a/src/azure/cli/main.py b/src/azure/cli/main.py index bb21ec17233..967894f7033 100644 --- a/src/azure/cli/main.py +++ b/src/azure/cli/main.py @@ -7,7 +7,7 @@ from ._session import Session from ._output import OutputProducer -logger = _logging.getAzLogger(__name__) +logger = _logging.get_az_logger(__name__) #ACCOUNT contains subscriptions information # this file will be shared with azure-xplat-cli, which assumes ascii diff --git a/src/azure/cli/tests/test_logging.py b/src/azure/cli/tests/test_logging.py index a97e5b29997..f84e419fe10 100644 --- a/src/azure/cli/tests/test_logging.py +++ b/src/azure/cli/tests/test_logging.py @@ -50,10 +50,10 @@ def test_determine_verbose_level_vv(self): def test_determine_verbose_level_v_v_v_default(self): # User specified verbose 3 times (we only support 2) - # So default to verbose level of 0 + # So default to verbose level of max argv = ['-v', '-v', '-v'] actual_level = _logging._determine_verbose_level(argv) - expected_level = 0 + expected_level = 2 self.assertEqual(actual_level, expected_level) # We still consumed the arguments self.assertFalse(argv) @@ -62,7 +62,7 @@ def test_determine_verbose_level_v_vv(self): # Too much verbosity specified argv = ['-v', '-vv'] actual_level = _logging._determine_verbose_level(argv) - expected_level = 0 + expected_level = 2 self.assertEqual(actual_level, expected_level) # We still consumed the arguments self.assertFalse(argv) @@ -71,7 +71,7 @@ def test_determine_verbose_level_vv_v(self): # Too much verbosity specified argv = ['-vv', '-v'] actual_level = _logging._determine_verbose_level(argv) - expected_level = 0 + expected_level = 2 self.assertEqual(actual_level, expected_level) # We still consumed the arguments self.assertFalse(argv) @@ -85,11 +85,11 @@ def test_determine_verbose_level_other_args(self): self.assertEqual(argv, ['account']) def test_get_az_logger(self): - az_logger = _logging.getAzLogger() + az_logger = _logging.get_az_logger() self.assertEqual(az_logger.name, 'az') def test_get_az_logger_module(self): - az_module_logger = _logging.getAzLogger('azure.cli.module') + az_module_logger = _logging.get_az_logger('azure.cli.module') self.assertEqual(az_module_logger.name, 'az.azure.cli.module') if __name__ == '__main__': 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 e1efeb09aff..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 @@ -4,7 +4,7 @@ from .command_tables import COMMAND_TABLES import azure.cli._logging as _logging -logger = _logging.getAzLogger(__name__) +logger = _logging.get_az_logger(__name__) command_table = CommandTable() From 6bb8e5466109bd7054a14587ef6beda813494fc1 Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Thu, 28 Apr 2016 11:49:23 -0700 Subject: [PATCH 4/7] Use --debug and --verbose instead of -v etc. --- src/azure/cli/_logging.py | 8 ++--- src/azure/cli/application.py | 6 ++-- src/azure/cli/tests/test_logging.py | 53 ++++++----------------------- 3 files changed, 18 insertions(+), 49 deletions(-) diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index e7842f649e7..51c5abf9b95 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -6,12 +6,12 @@ 'az': logging.WARNING, 'root': logging.CRITICAL, }, - # -v + # --verbose { 'az': logging.INFO, 'root': logging.CRITICAL, }, - # -vv + # --debug { 'az': logging.DEBUG, 'root': logging.DEBUG, @@ -24,10 +24,10 @@ def _determine_verbose_level(argv): i = 0 while i < len(argv): arg = argv[i] - if arg in ['-v', '--verbose']: + if arg in ['--verbose']: verbose_level += 1 argv.pop(i) - elif arg in ['-vv']: + elif arg in ['--debug']: verbose_level += 2 argv.pop(i) else: diff --git a/src/azure/cli/application.py b/src/azure/cli/application.py index 6656d733516..a8c1aae294b 100644 --- a/src/azure/cli/application.py +++ b/src/azure/cli/application.py @@ -137,8 +137,10 @@ def _register_builtin_arguments(parser): 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('-v', '--verbose', action="count", dest='_log_verbosity', - help='Logging verbosity. Can be used up to 2 times (-vv for short).') + 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/tests/test_logging.py b/src/azure/cli/tests/test_logging.py index f84e419fe10..ed5d8d49170 100644 --- a/src/azure/cli/tests/test_logging.py +++ b/src/azure/cli/tests/test_logging.py @@ -20,67 +20,34 @@ def test_determine_verbose_level_verbose(self): self.assertEqual(actual_level, expected_level) self.assertFalse(argv) - def test_determine_verbose_level_v(self): - argv = ['-v'] - actual_level = _logging._determine_verbose_level(argv) - expected_level = 1 - self.assertEqual(actual_level, expected_level) - self.assertFalse(argv) - - def test_determine_verbose_level_v_v(self): - argv = ['-v', '-v'] - actual_level = _logging._determine_verbose_level(argv) - expected_level = 2 - self.assertEqual(actual_level, expected_level) - self.assertFalse(argv) - - def test_determine_verbose_level_verbose_verbose(self): - argv = ['--verbose', '--verbose'] - actual_level = _logging._determine_verbose_level(argv) - expected_level = 2 - self.assertEqual(actual_level, expected_level) - self.assertFalse(argv) - - def test_determine_verbose_level_vv(self): - argv = ['-vv'] + 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): - # User specified verbose 3 times (we only support 2) - # So default to verbose level of max - argv = ['-v', '-v', '-v'] + 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_v_vv(self): - # Too much verbosity specified - argv = ['-v', '-vv'] + def test_determine_verbose_level_other_args_verbose(self): + argv = ['account', '--verbose'] actual_level = _logging._determine_verbose_level(argv) - expected_level = 2 + expected_level = 1 self.assertEqual(actual_level, expected_level) - # We still consumed the arguments - self.assertFalse(argv) + # We consumed 1 argument + self.assertEqual(argv, ['account']) - def test_determine_verbose_level_vv_v(self): - # Too much verbosity specified - argv = ['-vv', '-v'] + 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 still consumed the arguments - self.assertFalse(argv) - - def test_determine_verbose_level_other_args(self): - argv = ['account', '-v'] - actual_level = _logging._determine_verbose_level(argv) - expected_level = 1 - self.assertEqual(actual_level, expected_level) # We consumed 1 argument self.assertEqual(argv, ['account']) From 87c9c3c5a46de622b38e1ec4d5797bb9a3eb9e6f Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Thu, 28 Apr 2016 13:11:48 -0700 Subject: [PATCH 5/7] Send different verbosity of logs to log file and console - Support user specified log dir, user can disable logging, rotating files --- src/azure/cli/_logging.py | 63 +++++++++++++++++++++++++++++---------- 1 file changed, 48 insertions(+), 15 deletions(-) diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index 51c5abf9b95..8d1dedc05d7 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -1,6 +1,8 @@ -import logging +import os +import logging +from logging.handlers import RotatingFileHandler -LOG_LEVEL_CONFIGS = [ +CONSOLE_LOG_LEVEL_CONFIGS = [ # (default) { 'az': logging.WARNING, @@ -17,6 +19,12 @@ 'root': logging.DEBUG, }] +AZ_LOGFILE_NAME = 'az.log' +DEFAULT_LOG_DIR = os.path.expanduser(os.path.join('~', '.azure', 'logs')) + +DISABLE_LOG_FILE = os.environ.get('AZURE_CLI_DISABLE_LOG_FILE') +LOG_DIR = os.environ.get('AZURE_CLI_LOG_DIR') + def _determine_verbose_level(argv): # Get verbose level by reading the arguments. # Remove any consumed args. @@ -33,26 +41,51 @@ def _determine_verbose_level(argv): else: i += 1 # Use max verbose level if too much verbosity specified. - return verbose_level if verbose_level < len(LOG_LEVEL_CONFIGS) else len(LOG_LEVEL_CONFIGS)-1 + return verbose_level if verbose_level < len(CONSOLE_LOG_LEVEL_CONFIGS) else len(CONSOLE_LOG_LEVEL_CONFIGS)-1 -def _configure_root_logger(log_level_config): - root_logger = logging.getLogger() - root_logger.setLevel(log_level_config['root']) +def _init_console_handlers(root_logger, az_logger, log_level_config): + console_log_format = logging.Formatter('%(levelname)s: %(message)s') -def _configure_az_logger(log_level_config): - az_logger = logging.getLogger('az') - az_logger.setLevel(log_level_config['az']) + 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 _init_console_handler(): - logging.basicConfig(format='%(levelname)s: %(message)s') +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 DISABLE_LOG_FILE: + return + log_file_path = _get_log_file_path() + logfile_handler = RotatingFileHandler(log_file_path, maxBytes=5*1024*1024, backupCount=5) + logfile_handler.setFormatter(logging.Formatter('%(process)d : %(asctime)s : %(name)s : %(levelname)s : %(message)s')) + 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 = LOG_LEVEL_CONFIGS[verbose_level] + log_level_config = CONSOLE_LOG_LEVEL_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_handler() - _configure_root_logger(log_level_config) - _configure_az_logger(log_level_config) + _init_console_handlers(root_logger, az_logger, log_level_config) + _init_logfile_handlers(root_logger, az_logger) def get_az_logger(module_name=None): return logging.getLogger('az.' + module_name if module_name else 'az') From df4e7632b7ff9522c75259b40ec6352cb1f6081b Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Thu, 28 Apr 2016 15:51:33 -0700 Subject: [PATCH 6/7] Fix pylint errors & no need to configure logging in the test as it causes tests to show all DEBUG logs --- src/azure/cli/_logging.py | 9 +++++---- src/azure/cli/utils/command_test_util.py | 1 - 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index 8d1dedc05d7..3c81869847f 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -2,7 +2,7 @@ import logging from logging.handlers import RotatingFileHandler -CONSOLE_LOG_LEVEL_CONFIGS = [ +CONSOLE_LOG_CONFIGS = [ # (default) { 'az': logging.WARNING, @@ -41,7 +41,7 @@ def _determine_verbose_level(argv): else: i += 1 # Use max verbose level if too much verbosity specified. - return verbose_level if verbose_level < len(CONSOLE_LOG_LEVEL_CONFIGS) else len(CONSOLE_LOG_LEVEL_CONFIGS)-1 + 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') @@ -67,14 +67,15 @@ def _init_logfile_handlers(root_logger, az_logger): return log_file_path = _get_log_file_path() logfile_handler = RotatingFileHandler(log_file_path, maxBytes=5*1024*1024, backupCount=5) - logfile_handler.setFormatter(logging.Formatter('%(process)d : %(asctime)s : %(name)s : %(levelname)s : %(message)s')) + 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_LEVEL_CONFIGS[verbose_level] + log_level_config = CONSOLE_LOG_CONFIGS[verbose_level] root_logger = logging.getLogger() az_logger = logging.getLogger('az') 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, From d70519538b80713dcdf372ce2d5942def6b33d39 Mon Sep 17 00:00:00 2001 From: Derek Bekoe Date: Fri, 29 Apr 2016 15:06:17 -0700 Subject: [PATCH 7/7] Disable log file by default. User can enable with env var. --- src/azure/cli/_logging.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/azure/cli/_logging.py b/src/azure/cli/_logging.py index 3c81869847f..d56ee4e0d14 100644 --- a/src/azure/cli/_logging.py +++ b/src/azure/cli/_logging.py @@ -22,7 +22,7 @@ AZ_LOGFILE_NAME = 'az.log' DEFAULT_LOG_DIR = os.path.expanduser(os.path.join('~', '.azure', 'logs')) -DISABLE_LOG_FILE = os.environ.get('AZURE_CLI_DISABLE_LOG_FILE') +ENABLE_LOG_FILE = os.environ.get('AZURE_CLI_ENABLE_LOG_FILE') LOG_DIR = os.environ.get('AZURE_CLI_LOG_DIR') def _determine_verbose_level(argv): @@ -63,7 +63,7 @@ def _get_log_file_path(): return os.path.join(log_dir, AZ_LOGFILE_NAME) def _init_logfile_handlers(root_logger, az_logger): - if DISABLE_LOG_FILE: + 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)