[wip] az feedback

Dockerfile

@@ -34,7 +34,7 @@ LABEL maintainer="Microsoft" \
 # pip wheel - required for CLI packaging
 # jmespath-terminal - we include jpterm as a useful tool
 RUN apk add --no-cache bash openssh ca-certificates jq curl openssl git zip \
- && apk add --no-cache --virtual .build-deps gcc make openssl-dev libffi-dev musl-dev \
+ && apk add --no-cache --virtual .build-deps gcc make openssl-dev libffi-dev musl-dev linux-headers \
  && update-ca-certificates
 
 ARG JP_VERSION="0.1.3"

src/azure-cli-core/azure/cli/core/__init__.py

@@ -93,7 +93,7 @@ def show_version(self):
 
     def exception_handler(self, ex):  # pylint: disable=no-self-use
         from azure.cli.core.util import handle_exception
-        return handle_exception(ex, cli_ctx=self)
+        return handle_exception(ex)
 
 
 class MainCommandsLoader(CLICommandsLoader):

src/azure-cli-core/azure/cli/core/azlogging.py

@@ -23,11 +23,171 @@
 
 """
 
-from knack.log import CLILogging
+import os
+import logging
+import datetime
 
-CLI_LOGGER_NAME = 'az'
+from knack.log import CLILogging, get_logger
+from knack.util import ensure_dir
+from azure.cli.core.commands.events import EVENT_INVOKER_PRE_CMD_TBL_TRUNCATE
+
+
+_UNKNOWN_COMMAND = "unknown_command"
+_CMD_LOG_LINE_PREFIX = "CMD-LOG-LINE-BEGIN"
 
 
 class AzCliLogging(CLILogging):
+    _COMMAND_METADATA_LOGGER = 'az_command_data_logger'
+
+    def __init__(self, name, cli_ctx=None):
+        super(AzCliLogging, self).__init__(name, cli_ctx)
+        self.command_log_dir = os.path.join(cli_ctx.config.config_dir, 'commands')
+        self.command_logger_handler = None
+        self.command_metadata_logger = None
+        self.cli_ctx.register_event(EVENT_INVOKER_PRE_CMD_TBL_TRUNCATE, AzCliLogging.init_command_file_logging)
+
+    def get_command_log_dir(self):
+        return self.command_log_dir
+
+    @staticmethod
+    def init_command_file_logging(cli_ctx, **kwargs):
+        def _delete_old_logs(log_dir):
+            """
+            Periodically delete the 5 oldest command log files, ensuring that only the history of the last
+            25 commands (or less) are kept.
+            """
+
+            # get log file names and sort them from newest to oldest file.
+            log_file_names = [file for file in os.listdir(log_dir) if file.endswith(".log")]
+            sorted_files = sorted(log_file_names, reverse=True)
+
+            # if we have too many files, delete the 5 last / oldest command log files.
+            if len(sorted_files) > 25:
+                for file in sorted_files[-5:]:
+                    try:
+                        os.remove(os.path.join(log_dir, file))
+                    except OSError:  # FileNotFoundError introduced in Python 3
+                        continue
+
+        # if tab-completion and not command don't log to file.
+        if not cli_ctx.data.get('completer_active', False):
+            self = cli_ctx.logging
+            args = kwargs['args']
+
+            cmd_logger = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER)
+
+            self._init_command_logfile_handlers(cmd_logger, args)  # pylint: disable=protected-access
+            get_logger(__name__).debug("metadata file logging enabled - writing logs to '%s'.", self.command_log_dir)
+
+            _delete_old_logs(self.command_log_dir)
+
+    def _init_command_logfile_handlers(self, command_metadata_logger, args):
+
+        ensure_dir(self.command_log_dir)
+        command = self.cli_ctx.invocation._rudimentary_get_command(args) or _UNKNOWN_COMMAND  # pylint: disable=protected-access, line-too-long
+        command_str = command.replace(" ", "_")
+        if command_str.lower() == "feedback":
+            return
+
+        date_str = str(datetime.datetime.now().date())
+        time = datetime.datetime.now().time()
+        time_str = "{:02}-{:02}-{:02}".format(time.hour, time.minute, time.second)
+
+        log_name = "{}.{}.{}.{}.{}".format(date_str, time_str, command_str, os.getpid(), "log")
+
+        log_file_path = os.path.join(self.command_log_dir, log_name)
+
+        logfile_handler = logging.FileHandler(log_file_path)
+
+        lfmt = logging.Formatter(_CMD_LOG_LINE_PREFIX + ' %(process)d | %(asctime)s | %(levelname)s | %(name)s | %(message)s')  # pylint: disable=line-too-long
+        logfile_handler.setFormatter(lfmt)
+        logfile_handler.setLevel(logging.DEBUG)
+        command_metadata_logger.addHandler(logfile_handler)
+
+        self.command_logger_handler = logfile_handler
+        self.command_metadata_logger = command_metadata_logger
+
+        args = AzCliLogging._get_clean_args(command if command != _UNKNOWN_COMMAND else None, args)
+        command_metadata_logger.info("command args: %s", " ".join(args))
+
+    @staticmethod
+    def _get_clean_args(command, args):  # TODO: add test for this function
+        # based on AzCliCommandInvoker._extract_parameter_names(args)
+        # note: name start with more than 2 '-' will be treated as value e.g. certs in PEM format
+
+        # if no command provided, try to guess the intended command. This does not work for positionals
+        if not command:
+            command_list = []
+            for arg in args:
+                if arg.startswith('-') and not arg.startswith('---') and len(arg) > 1:
+                    break
+                command_list.append(arg)
+            command = " ".join(command_list)
+
+        command = command.split()
+        cleaned_args = []
+        placeholder = "{}"
+        for i, arg in enumerate(args):
+            # while this token a part of the command add it.
+            # Note: if 'command' is none first positional would be captured.
+            if i < len(command):
+                cleaned_args.append(arg)
+                continue
+
+            # if valid optional name
+            if arg.startswith('-') and not arg.startswith('---') and len(arg) > 1:
+
+                # if short option with or without "="
+                if not arg.startswith("--"):
+                    opt = arg[:2]  # get opt
+
+                    opt = opt + "=" if len(arg) > 2 and arg[2] == "=" else opt  # append '=' if necessary
+                    opt = opt + placeholder if (len(arg) > 2 and arg[2] != "=") or len(
+                        arg) > 3 else opt  # append placeholder if argument with optional
+                    cleaned_args.append(opt)
+                    continue
+
+                # otherwise if long option with "="
+                if "=" in arg:
+                    opt, _ = arg.split('=', 1)
+                    cleaned_args.append(opt + "=" + placeholder)
+                    continue
+
+                cleaned_args.append(arg)
+                continue
+
+            # else if positional or optional argument / value
+            else:
+                cleaned_args.append(placeholder)
+
+        return cleaned_args
+
+    def log_cmd_metadata_extension_info(self, extension_name, extension_version):
+        if self.command_metadata_logger:
+            self.command_metadata_logger.info("extension name: %s", extension_name)
+            self.command_metadata_logger.info("extension version: %s", extension_version)
+
+    def end_cmd_metadata_logging(self, exit_code):
+        if self.command_metadata_logger:
+            self.command_metadata_logger.info("exit code: %s", exit_code)
+
+            # We have finished metadata logging, remove handler and set command_metadata_handler to None.
+            # crucial to remove handler as in python logger objects are shared which can affect testing of this logger
+            # we do not want duplicate handlers to be added in subsequent calls of _init_command_logfile_handlers
+            self.command_metadata_logger.removeHandler(self.command_logger_handler)
+            self.command_metadata_logger = None
+
+
+class CommandLoggerContext(object):
+    def __init__(self, module_logger):
+        self.logger = module_logger
+        self.hdlr = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER)  # pylint: disable=protected-access
+
+    def __enter__(self):
+        if self.hdlr:
+            self.logger.addHandler(self.hdlr)  # add command metadata handler
+        return self
 
-    pass
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        if self.hdlr:
+            self.logger.removeHandler(self.hdlr)

src/azure-cli-core/azure/cli/core/commands/__init__.py

@@ -296,6 +296,7 @@ def execute(self, args):
                                       extension_name=extension_name, extension_version=extension_version)
         if extension_name:
             self.data['command_extension_name'] = extension_name
+            self.cli_ctx.logging.log_cmd_metadata_extension_info(extension_name, extension_version)
 
         self.resolve_warnings(cmd, parsed_args)
         self.resolve_confirmation(cmd, parsed_args)

src/azure-cli-core/azure/cli/core/commands/arm.py

@@ -736,9 +736,11 @@ def handler(args):
 
 def show_exception_handler(ex):
     if getattr(getattr(ex, 'response', ex), 'status_code', None) == 404:
-        logger.error(getattr(ex, 'message', ex))
         import sys
-        sys.exit(3)
+        from azure.cli.core.azlogging import CommandLoggerContext
+        with CommandLoggerContext(logger):
+            logger.error(getattr(ex, 'message', ex))
+            sys.exit(3)
     raise ex
 
 

src/azure-cli-core/azure/cli/core/parser.py

@@ -12,6 +12,7 @@
 import argcomplete
 
 import azure.cli.core.telemetry as telemetry
+from azure.cli.core.azlogging import CommandLoggerContext
 from azure.cli.core.extension import get_extension
 from azure.cli.core.commands import ExtensionCommandSource
 from azure.cli.core.commands.events import EVENT_INVOKER_ON_TAB_COMPLETION
@@ -132,7 +133,8 @@ def validation_error(self, message):
     def error(self, message):
         telemetry.set_user_fault('parse error: {}'.format(message))
         args = {'prog': self.prog, 'message': message}
-        logger.error('%(prog)s: error: %(message)s', args)
+        with CommandLoggerContext(logger):
+            logger.error('%(prog)s: error: %(message)s', args)
         self.print_usage(sys.stderr)
         self.exit(2)
 
@@ -172,7 +174,8 @@ def _check_value(self, action, value):
                 error_msg = "{prog}: '{value}' is not a valid value for '{param}'. See '{prog} --help'.".format(
                     prog=self.prog, value=value, param=parameter)
             telemetry.set_user_fault(error_msg)
-            logger.error(error_msg)
+            with CommandLoggerContext(logger):
+                logger.error(error_msg)
             candidates = difflib.get_close_matches(value, action.choices, cutoff=0.7)
             if candidates:
                 print_args = {

src/azure-cli-core/azure/cli/core/util.py

@@ -20,48 +20,42 @@
 COMPONENT_PREFIX = 'azure-cli-'
 
 
-def handle_exception(ex, cli_ctx=None):
+def handle_exception(ex):
     # For error code, follow guidelines at https://docs.python.org/2/library/sys.html#sys.exit,
     from msrestazure.azure_exceptions import CloudError
     from msrest.exceptions import HttpOperationError
-    if isinstance(ex, (CLIError, CloudError)):
-        logger.error(ex.args[0])
-        return ex.args[1] if len(ex.args) >= 2 else 1
-    if isinstance(ex, KeyboardInterrupt):
-        return 1
-    if isinstance(ex, HttpOperationError):
-        try:
-            response_dict = json.loads(ex.response.text)
-            error = response_dict['error']
-
-            # ARM should use ODATA v4. So should try this first.
-            # http://docs.oasis-open.org/odata/odata-json-format/v4.0/os/odata-json-format-v4.0-os.html#_Toc372793091
-            if isinstance(error, dict):
-                code = "{} - ".format(error.get('code', 'Unknown Code'))
-                message = error.get('message', ex)
-                logger.error("%s%s", code, message)
-            else:
-                logger.error(error)
+    from azure.cli.core.azlogging import CommandLoggerContext
 
-        except (ValueError, KeyError):
-            logger.error(ex)
-        return 1
+    with CommandLoggerContext(logger):
 
-    # Otherwise, unhandled exception. Direct users to create an issue.
-    is_extension = False
-    if cli_ctx:
-        try:
-            if cli_ctx.invocation.data['command_extension_name']:
-                is_extension = True
-        except (AttributeError, KeyError):
-            pass
-
-    issue_url = "https://aka.ms/azcli/ext/issues" if is_extension else "https://aka.ms/azcli/issues"
-    logger.error("The command failed with an unexpected error. Here is the traceback:\n")
-    logger.exception(ex)
-    logger.warning("\nTo open an issue, please visit: %s", issue_url)
+        if isinstance(ex, (CLIError, CloudError)):
+            logger.error(ex.args[0])
+            return ex.args[1] if len(ex.args) >= 2 else 1
+        if isinstance(ex, KeyboardInterrupt):
+            return 1
+        if isinstance(ex, HttpOperationError):
+            try:
+                response_dict = json.loads(ex.response.text)
+                error = response_dict['error']
+
+                # ARM should use ODATA v4. So should try this first.
+                # http://docs.oasis-open.org/odata/odata-json-format/v4.0/os/odata-json-format-v4.0-os.html#_Toc372793091
+                if isinstance(error, dict):
+                    code = "{} - ".format(error.get('code', 'Unknown Code'))
+                    message = error.get('message', ex)
+                    logger.error("%s%s", code, message)
+                else:
+                    logger.error(error)
+
+            except (ValueError, KeyError):
+                logger.error(ex)
+            return 1
+
+        logger.error("The command failed with an unexpected error. Here is the traceback:\n")
+        logger.exception(ex)
+        logger.warning("\nTo open an issue, please run: 'az feedback'")
 
-    return 1
+        return 1
 
 
 # pylint: disable=inconsistent-return-statements
@@ -351,7 +345,7 @@ def open_page_in_browser(url):
     if _is_wsl(platform_name, release):   # windows 10 linux subsystem
         try:
             return subprocess.call(['cmd.exe', '/c', "start {}".format(url.replace('&', '^&'))])
-        except FileNotFoundError:  # WSL might be too old
+        except OSError:  # WSL might be too old  # FileNotFoundError introduced in Python 3
             pass
     elif platform_name == 'darwin':
         # handle 2 things:

src/azure-cli-core/setup.py

@@ -72,7 +72,9 @@
     'six',
     'tabulate>=0.7.7',
     'wheel==0.30.0',
-    'azure-mgmt-resource==2.1.0'
+    'azure-mgmt-resource==2.1.0',
+    'pyperclip>=1.7.0',
+    'psutil>=5.6.1'
 ]
 
 with open('README.rst', 'r', encoding='utf-8') as f:

src/azure-cli/azure/cli/__main__.py

@@ -5,6 +5,7 @@
 
 import sys
 import uuid
+import timeit
 
 from knack.completion import ARGCOMPLETE_ENV_NAME
 from knack.log import get_logger
@@ -35,6 +36,7 @@ def cli_main(cli, args):
 
 try:
     telemetry.start()
+    start_time = timeit.default_timer()
 
     exit_code = cli_main(az_cli, sys.argv[1:])
 
@@ -43,9 +45,29 @@ def cli_main(cli, args):
     else:
         telemetry.set_success()
 
+    elapsed_time = timeit.default_timer() - start_time
+
+    az_cli.logging.end_cmd_metadata_logging(exit_code)
     sys.exit(exit_code)
+
 except KeyboardInterrupt:
     telemetry.set_user_fault('keyboard interrupt')
     sys.exit(1)
+except SystemExit as ex:  # some code directly call sys.exit, this is to make sure command metadata is logged
+    exit_code = ex.code if ex.code is not None else 1
+
+    try:
+        elapsed_time = timeit.default_timer() - start_time
+    except NameError:
+        pass
+
+    az_cli.logging.end_cmd_metadata_logging(exit_code)
+    raise ex
+
 finally:
     telemetry.conclude()
+
+    try:
+        logger.info("command ran in %.3f seconds.", elapsed_time)
+    except NameError:
+        pass

src/command_modules/azure-cli-botservice/azure/cli/command_modules/botservice/custom.py

@@ -438,7 +438,7 @@ def prepare_publish(cmd, client, resource_group_name, resource_name, sln_name, p
         try:
             shutil.copyfile(os.path.join(download_path['downloadPath'], 'PostDeployScripts', 'deploy.cmd.template'),
                             'deploy.cmd')
-        except FileNotFoundError as error:
+        except OSError as error:  # FileNotFoundError introduced in Python 3
             logger.error('"deploy.cmd.template" not found. This may be due to calling \'az bot prepare-publish\' on a '
                          'v4 bot. To prepare and publish a v4 bot, please instead use \'az bot publish\'.')
             raise CLIError(error)