[wip] az feedback (#8829)

* Command metadata now logged per command. Feedback command can reach this metadata.

Command duration and time since last run now properly shown.

Print format updates. Minor bug fixes.

Prompt user for issue they want info on. Fix bugs.

changes with browser

Skip feedback commands. Browser open works. Verbose shows issue template.

Refactored code, although printing and time logic seems to be incorrect.

* Add tests for az feedback. Update bug_report.md file. Fix exit code bug.

* Address linter/style errors. Update History.rst

Delete last 5 commands if number of cached commands exceeds 25.

Address more style issues.

style fixes

Move feedback test to correct location.

More style fixes.

* Rename FileNotFoundError to OSError. Address style problems.

More style fixes. Fix python 2 error.

* Update command logger context. Ensure that failed show commands log to command metadata logs.

Minor changes.

* Fix docker build issue. Properly detect powershell. Address some feedback.

* Fixed log cleanup bug. Remove sensitive information from command_args. Minor updates.

Fix bug where command_data_dict could be None.

* Detect powershell. Take 2.

* Fix setup.py

* Style fix.

* az feedback no longer shows command duration. Other stylistic updates.

* Style fix.

* Pylint, line too long.

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)