[Logging] (part2) Output full logs to rotating log file

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"
 

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')

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

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,15 +20,15 @@
 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)
     ACCOUNT.load(os.path.join(azure_folder, 'azureProfile.json'))
     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',

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
 

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

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()

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,

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()