Feature logging tracing 3 (Azure#210)

* Add TRACING to CLI; make --verbose and --debug flags

* Handle CLI exceptions that occur during normal operation

* Resolve pylint messages

* Should show logging message as a warning instead of using print statement

* Support colors of log output

* Catch adal error on login

* Support windows stream coloring

* Fix pylint warnings

* More tracing to long running operations and remove the dots (......)

* More descriptive logger.info message when module can't be loaded.

* Raise CLIError instead of RuntimeError & fix pylint errors

requirements.txt

@@ -9,6 +9,7 @@ pyyaml==3.11
 requests==2.9.1
 six==1.10.0
 vcrpy==1.7.4
+colorama==0.3.7
 
 # install adal from our libs dir
 libs/adal-0.2.2.zip

setup.py

@@ -69,6 +69,7 @@
     'applicationinsights',
     'argcomplete',
     'azure==2.0.0rc1',
+    'colorama',
     'jmespath',
     'msrest',
     'pip',

src/azure/cli/_locale.py

@@ -1,5 +1,6 @@
 import os.path
 from codecs import open as codecs_open
+from azure.cli._util import CLIError
 
 _translations = dict()
 _locale_dir = ''
@@ -27,6 +28,6 @@ def get_file(name):
     try:
         src = _locale_dir
     except (NameError, AttributeError):
-        raise RuntimeError("localizations not installed")
+        raise CLIError('Localizations not installed')
 
     return os.path.join(src, name)

src/azure/cli/_logging.py

@@ -1,7 +1,16 @@
 import os
+import platform
 import logging
 from logging.handlers import RotatingFileHandler
 
+import colorama
+
+AZ_LOGFILE_NAME = 'az.log'
+DEFAULT_LOG_DIR = os.path.expanduser(os.path.join('~', '.azure', 'logs'))
+
+ENABLE_LOG_FILE = os.environ.get('AZURE_CLI_ENABLE_LOG_FILE')
+LOG_DIR = os.environ.get('AZURE_CLI_LOG_DIR')
+
 CONSOLE_LOG_CONFIGS = [
     # (default)
     {
@@ -19,11 +28,19 @@
         'root': logging.DEBUG,
     }]
 
-AZ_LOGFILE_NAME = 'az.log'
-DEFAULT_LOG_DIR = os.path.expanduser(os.path.join('~', '.azure', 'logs'))
-
-ENABLE_LOG_FILE = os.environ.get('AZURE_CLI_ENABLE_LOG_FILE')
-LOG_DIR = os.environ.get('AZURE_CLI_LOG_DIR')
+# Formats for console logging if coloring is enabled or not.
+# Show the level name if coloring is disabled (e.g. INFO).
+# Also, Root logger should show the logger name.
+CONSOLE_LOG_FORMAT = {
+    'az': {
+        True: '%(message)s',
+        False: '%(levelname)s: %(message)s',
+    },
+    'root': {
+        True: '%(name)s : %(message)s',
+        False: '%(levelname)s: %(name)s : %(message)s',
+    }
+}
 
 def _determine_verbose_level(argv):
     # Get verbose level by reading the arguments.
@@ -43,18 +60,52 @@ def _determine_verbose_level(argv):
     # 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')
+def _color_wrapper(color_marker):
+    def wrap_msg_with_color(msg):
+        return color_marker + msg + colorama.Style.RESET_ALL
+    return wrap_msg_with_color
+
+class CustomStreamHandler(logging.StreamHandler):
+    COLOR_MAP = {
+        logging.CRITICAL: _color_wrapper(colorama.Fore.RED),
+        logging.ERROR: _color_wrapper(colorama.Fore.RED),
+        logging.WARNING: _color_wrapper(colorama.Fore.YELLOW),
+        logging.INFO: _color_wrapper(colorama.Fore.GREEN),
+        logging.DEBUG: _color_wrapper(colorama.Fore.CYAN),
+    }
 
-    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)
+    def _should_enable_color(self):
+        try:
+            # Color if tty stream available
+            if self.stream.isatty():
+                return True
+        except AttributeError:
+            pass
 
-    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)
+        return False
+
+    def __init__(self, log_level_config, log_format):
+        logging.StreamHandler.__init__(self)
+        self.setLevel(log_level_config)
+        if platform.system() == 'Windows':
+            self.stream = colorama.AnsiToWin32(self.stream).stream
+        self.enable_color = self._should_enable_color()
+        self.setFormatter(logging.Formatter(log_format[self.enable_color]))
+
+    def format(self, record):
+        msg = logging.StreamHandler.format(self, record)
+        if self.enable_color:
+            try:
+                msg = self.COLOR_MAP[record.levelno](msg)
+            except KeyError:
+                pass
+        return msg
+
+def _init_console_handlers(root_logger, az_logger, log_level_config):
+    root_logger.addHandler(CustomStreamHandler(log_level_config['root'],
+                                               CONSOLE_LOG_FORMAT['root']))
+    az_logger.addHandler(CustomStreamHandler(log_level_config['az'],
+                                             CONSOLE_LOG_FORMAT['az']))
 
 def _get_log_file_path():
     log_dir = LOG_DIR or DEFAULT_LOG_DIR
@@ -67,7 +118,7 @@ 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)
-    lfmt = logging.Formatter('%(process)d : %(asctime)s : %(name)s :  %(levelname)s : %(message)s')
+    lfmt = logging.Formatter('%(process)d : %(asctime)s : %(levelname)s : %(name)s : %(message)s')
     logfile_handler.setFormatter(lfmt)
     logfile_handler.setLevel(logging.DEBUG)
     root_logger.addHandler(logfile_handler)

src/azure/cli/_output.py

@@ -6,9 +6,6 @@
 from collections import OrderedDict
 from six import StringIO
 
-class OutputFormatException(Exception):
-    pass
-
 def format_json(obj):
     input_dict = obj.__dict__ if hasattr(obj, '__dict__') else obj
     return json.dumps(input_dict, indent=2, sort_keys=True, separators=(',', ': ')) + '\n'

src/azure/cli/_profile.py

@@ -9,9 +9,12 @@
 from azure.mgmt.resource.subscriptions import (SubscriptionClient,
                                                SubscriptionClientConfiguration)
 from .main import ACCOUNT
+from ._util import CLIError
 from ._locale import L
 from ._azure_env import (get_authority_url, CLIENT_ID, get_management_endpoint_url,
                          ENV_DEFAULT, COMMON_TENANT)
+import azure.cli._logging as _logging
+logger = _logging.get_az_logger(__name__)
 
 #Names below are used by azure-xplat-cli to persist account information into
 #~/.azure/azureProfile.json or osx/keychainer or windows secure storage,
@@ -78,7 +81,7 @@ def find_subscriptions_on_login(self, #pylint: disable=too-many-arguments
         else:
             if is_service_principal:
                 if not tenant:
-                    raise ValueError(L('Please supply tenant using "--tenant"'))
+                    raise CLIError(L('Please supply tenant using "--tenant"'))
 
                 subscriptions = self._subscription_finder.find_from_service_principal_id(username,
                                                                                          password,
@@ -87,7 +90,7 @@ def find_subscriptions_on_login(self, #pylint: disable=too-many-arguments
                 subscriptions = self._subscription_finder.find_from_user_account(username, password)
 
         if not subscriptions:
-            raise RuntimeError(L('No subscriptions found for this account.'))
+            raise CLIError(L('No subscriptions found for this account.'))
 
         if is_service_principal:
             self._creds_cache.save_service_principal_cred(username,
@@ -155,8 +158,8 @@ def set_active_subscription(self, subscription_id_or_name):
                   subscription_id_or_name == x[_SUBSCRIPTION_NAME].lower()]
 
         if len(result) != 1:
-            raise ValueError('The subscription of "{}" does not exist or has more than'
-                             ' one match.'.format(subscription_id_or_name))
+            raise CLIError('The subscription of "{}" does not exist or has more than'
+                           ' one match.'.format(subscription_id_or_name))
 
         for s in subscriptions:
             s[_IS_DEFAULT_SUBSCRIPTION] = False
@@ -192,11 +195,11 @@ def _cache_subscriptions_to_local_storage(self, subscriptions):
     def get_login_credentials(self):
         subscriptions = self.load_cached_subscriptions()
         if not subscriptions:
-            raise ValueError('Please run login to setup account.')
+            raise CLIError('Please run login to setup account.')
 
         active = [x for x in subscriptions if x.get(_IS_DEFAULT_SUBSCRIPTION)]
         if len(active) != 1:
-            raise ValueError('Please run "account set" to select active account.')
+            raise CLIError('Please run "account set" to select active account.')
         active_account = active[0]
 
         user_type = active_account[_USER_ENTITY][_USER_TYPE]
@@ -236,7 +239,7 @@ def find_from_user_account(self, username, password):
     def find_through_interactive_flow(self):
         context = self._create_auth_context(COMMON_TENANT)
         code = context.acquire_user_code(self._resource, CLIENT_ID)
-        print(code['message'])
+        logger.warning(code['message'])
         token_entry = context.acquire_token_with_device_code(self._resource, code, CLIENT_ID)
         self.user_id = token_entry[_TOKEN_ENTRY_USER_ID]
         result = self._find_using_common_tenant(token_entry[_ACCESS_TOKEN])
@@ -315,7 +318,7 @@ def retrieve_token_for_user(self, username, tenant):
         context = self._auth_ctx_factory(authority, cache=self.adal_token_cache)
         token_entry = context.acquire_token(self._resource, username, CLIENT_ID)
         if not token_entry: #TODO: consider to letting adal-python throw
-            raise ValueError('Could not retrieve token from local cache, please run \'login\'.')
+            raise CLIError('Could not retrieve token from local cache, please run \'login\'.')
 
         if self.adal_token_cache.has_state_changed:
             self.persist_cached_creds()
@@ -324,7 +327,7 @@ def retrieve_token_for_user(self, username, tenant):
     def retrieve_token_for_service_principal(self, sp_id):
         matched = [x for x in self._service_principal_creds if sp_id == x[_SERVICE_PRINCIPAL_ID]]
         if not matched:
-            raise ValueError(L('Please run "account set" to select active account.'))
+            raise CLIError(L('Please run "account set" to select active account.'))
         cred = matched[0]
         authority_url = get_authority_url(cred[_SERVICE_PRINCIPAL_TENANT], ENV_DEFAULT)
         context = self._auth_ctx_factory(authority_url, None)

src/azure/cli/_util.py

@@ -1,2 +1,9 @@
+class CLIError(Exception):
+    """Base class for exceptions that occur during
+    normal operation of the application.
+    Typically due to user error and can be resolved by the user.
+    """
+    pass
+
 def normalize_newlines(str_to_normalize):
     return str_to_normalize.replace('\r\n', '\n')

src/azure/cli/application.py

@@ -7,6 +7,9 @@
 from .parser import AzCliCommandParser
 import azure.cli.extensions
 import azure.cli._help as _help
+import azure.cli._logging as _logging
+
+logger = _logging.get_az_logger(__name__)
 
 class Configuration(object): # pylint: disable=too-few-public-methods
     """The configuration object tracks session specific data such
@@ -91,6 +94,7 @@ def execute(self, argv):
     def raise_event(self, name, event_data):
         '''Raise the event `name`.
         '''
+        logger.info("Application event '%s' with event data %s", name, event_data)
         for func in self._event_handlers[name]:
             func(event_data)
 
@@ -104,6 +108,7 @@ def register(self, name, handler):
           event_data: `dict` with event specific data.
         '''
         self._event_handlers[name].append(handler)
+        logger.info("Registered application event handler '%s' at %s", name, handler)
 
     KEYS_CAMELCASE_PATTERN = re.compile('(?!^)_([a-zA-Z])')
     @classmethod
@@ -142,13 +147,10 @@ def _register_builtin_arguments(global_group):
                                   default='list',
                                   help='Output format')
         # The arguments for verbosity don't get parsed by argparse but we add it here for help.
-        global_group.add_argument('--verbose', dest='_log_verbosity_verbose',
-                                  help='Increase logging verbosity.'
-                                  ' Use --debug for full debug logs.',
-                                  action='store_true')
-        global_group.add_argument('--debug', dest='_log_verbosity_debug',
-                                  help='Increase logging verbosity to show all debug logs.',
-                                  action='store_true')
+        global_group.add_argument('--verbose', dest='_log_verbosity_verbose', action='store_true',
+                                  help='Increase logging verbosity. Use --debug for full debug logs.') #pylint: disable=line-too-long
+        global_group.add_argument('--debug', dest='_log_verbosity_debug', action='store_true',
+                                  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/commands/__init__.py

@@ -1,16 +1,23 @@
 from __future__ import print_function
-import sys
 import time
 import random
 from importlib import import_module
 from collections import defaultdict, OrderedDict
 from pip import get_installed_distributions
+from msrest.exceptions import ClientException
+
+from azure.cli._util import CLIError
+import azure.cli._logging as _logging
+
+logger = _logging.get_az_logger(__name__)
 
 # Find our command modules, they start with 'azure-cli-'
 INSTALLED_COMMAND_MODULES = [dist.key.replace('azure-cli-', '')
                              for dist in get_installed_distributions(local_only=True)
                              if dist.key.startswith('azure-cli-')]
 
+logger.info('Installed command modules %s', INSTALLED_COMMAND_MODULES)
+
 RESOURCE_GROUP_ARG_NAME = 'resource_group_name'
 
 COMMON_PARAMETERS = {
@@ -43,30 +50,27 @@ def extend_parameter(parameter_metadata, **kwargs):
 
 class LongRunningOperation(object): #pylint: disable=too-few-public-methods
 
-    progress_file = sys.stderr
-
     def __init__(self, start_msg='', finish_msg='', poll_interval_ms=1000.0):
         self.start_msg = start_msg
         self.finish_msg = finish_msg
         self.poll_interval_ms = poll_interval_ms
 
     def __call__(self, poller):
-        print(self.start_msg, file=self.progress_file)
-        succeeded = False
+        logger.warning(self.start_msg)
+        logger.info("Starting long running operation '%s' with polling interval %s ms",
+                    self.start_msg, self.poll_interval_ms)
+        while not poller.done():
+            time.sleep(self.poll_interval_ms / 1000.0)
+            logger.info("Long running operation '%s' polling now", self.start_msg)
         try:
-            while not poller.done():
-                if self.progress_file:
-                    print('.', end='', file=self.progress_file)
-                    self.progress_file.flush()
-                    time.sleep(self.poll_interval_ms / 1000.0)
             result = poller.result()
-            succeeded = True
-            return result
-        finally:
-            # Ensure that we get a newline after the dots...
-            if self.progress_file:
-                print(file=self.progress_file)
-                print(self.finish_msg if succeeded else '', file=self.progress_file)
+        except ClientException as client_exception:
+            message = getattr(client_exception, 'message', client_exception)
+            raise CLIError(message)
+        logger.info("Long running operation '%s' completed with result %s",
+                    self.start_msg, result)
+        logger.warning(self.finish_msg)
+        return result
 
 class CommandTable(defaultdict):
     """A command table is a dictionary of func -> {name,
@@ -130,13 +134,15 @@ def get_command_table(module_name=None):
     if module_name:
         try:
             command_table = _get_command_table(module_name)
+            logger.info("Successfully loaded command table from module '%s'.", module_name)
             loaded = True
         except ImportError:
             # Unknown command - we'll load all installed modules below
-            pass
+            logger.info("Loading all installed modules as module with name '%s' not found.", module_name) #pylint: disable=line-too-long
 
     if not loaded:
         command_table = {}
+        logger.info('Loading command tables from all installed modules.')
         for mod in INSTALLED_COMMAND_MODULES:
             command_table.update(_get_command_table(mod))
 

src/azure/cli/commands/_auto_command.py

@@ -4,6 +4,7 @@
 from msrest.paging import Paged
 from msrest.exceptions import ClientException
 from azure.cli.parser import IncorrectUsageError
+from azure.cli._util import CLIError
 from ..commands import COMMON_PARAMETERS
 
 EXCLUDED_PARAMS = frozenset(['self', 'raw', 'custom_headers', 'operation_config',
@@ -51,7 +52,7 @@ def call_client(args):
             raise IncorrectUsageError(exception)
         except ClientException as client_exception:
             message = getattr(client_exception, 'message', client_exception)
-            raise RuntimeError(message)
+            raise CLIError(message)
 
     return call_client