diff --git a/Dockerfile b/Dockerfile index 78f28c73b51..563c5f4d3b1 100644 --- a/Dockerfile +++ b/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" diff --git a/src/azure-cli-core/azure/cli/core/__init__.py b/src/azure-cli-core/azure/cli/core/__init__.py index baf7e312d8a..f24991726dc 100644 --- a/src/azure-cli-core/azure/cli/core/__init__.py +++ b/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): diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 38263248fd8..0259b6ef0f5 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/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) diff --git a/src/azure-cli-core/azure/cli/core/commands/__init__.py b/src/azure-cli-core/azure/cli/core/commands/__init__.py index e861b0a231f..659ac296833 100644 --- a/src/azure-cli-core/azure/cli/core/commands/__init__.py +++ b/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) diff --git a/src/azure-cli-core/azure/cli/core/commands/arm.py b/src/azure-cli-core/azure/cli/core/commands/arm.py index 2d34dba0591..826fd9d3d22 100644 --- a/src/azure-cli-core/azure/cli/core/commands/arm.py +++ b/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 diff --git a/src/azure-cli-core/azure/cli/core/parser.py b/src/azure-cli-core/azure/cli/core/parser.py index e400c0b72b3..dbb84e4bb26 100644 --- a/src/azure-cli-core/azure/cli/core/parser.py +++ b/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 = { diff --git a/src/azure-cli-core/azure/cli/core/util.py b/src/azure-cli-core/azure/cli/core/util.py index efedcfe6eb8..1980f698c85 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/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: diff --git a/src/azure-cli-core/setup.py b/src/azure-cli-core/setup.py index 5e415bb4491..8f852bded38 100644 --- a/src/azure-cli-core/setup.py +++ b/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: diff --git a/src/azure-cli/azure/cli/__main__.py b/src/azure-cli/azure/cli/__main__.py index 51b55727506..f168e7d1871 100644 --- a/src/azure-cli/azure/cli/__main__.py +++ b/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 diff --git a/src/command_modules/azure-cli-botservice/azure/cli/command_modules/botservice/custom.py b/src/command_modules/azure-cli-botservice/azure/cli/command_modules/botservice/custom.py index b61b144dbf7..4e4fd1f58db 100644 --- a/src/command_modules/azure-cli-botservice/azure/cli/command_modules/botservice/custom.py +++ b/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) diff --git a/src/command_modules/azure-cli-container/azure/cli/command_modules/container/custom.py b/src/command_modules/azure-cli-container/azure/cli/command_modules/container/custom.py index 677b35edfe6..4675fed1972 100644 --- a/src/command_modules/azure-cli-container/azure/cli/command_modules/container/custom.py +++ b/src/command_modules/azure-cli-container/azure/cli/command_modules/container/custom.py @@ -378,7 +378,7 @@ def _create_update_from_file(cli_ctx, resource_group_name, name, location, file, try: with open(file, 'r') as f: cg_defintion = yaml.safe_load(f) - except FileNotFoundError: + except OSError: # FileNotFoundError introduced in Python 3 raise CLIError("No such file or directory: " + file) except yaml.YAMLError as e: raise CLIError("Error while parsing yaml file:\n\n" + str(e)) diff --git a/src/command_modules/azure-cli-feedback/HISTORY.rst b/src/command_modules/azure-cli-feedback/HISTORY.rst index cda8f8de1e4..0bdb8b4179e 100644 --- a/src/command_modules/azure-cli-feedback/HISTORY.rst +++ b/src/command_modules/azure-cli-feedback/HISTORY.rst @@ -3,6 +3,12 @@ Release History =============== +2.2.0 ++++++ +* `az feedback` now shows metadata on recently run commands +* `az feedback` prompts user to assist in issue creation process. Opens browser to issue url and copies auto-generated issue + text containing command and system related information to clipboard. Prints out issue body when run with '--verbose' + 2.1.4 +++++ * Minor fixes diff --git a/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py index 727bfe18f7e..752f085f605 100644 --- a/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py +++ b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py @@ -4,61 +4,552 @@ # -------------------------------------------------------------------------------------------- from __future__ import print_function -import sys +import os +import math +import platform +import datetime + +try: + from urllib.parse import urlencode # python 3 +except ImportError: + from urllib import urlencode # python 2 + +from collections import namedtuple from knack.log import get_logger from knack.prompting import prompt, NoTTYException from knack.util import CLIError -from azure.cli.core.util import COMPONENT_PREFIX, get_installed_cli_distributions -from azure.cli.core.telemetry import set_feedback +from azure.cli.core.util import get_az_version_string +from azure.cli.core.azlogging import _UNKNOWN_COMMAND, _CMD_LOG_LINE_PREFIX +from azure.cli.core.util import open_page_in_browser +import pyperclip + +_ONE_MIN_IN_SECS = 60 + +_ONE_HR_IN_SECS = 3600 + logger = get_logger(__name__) -MSG_RATE = '\nHow likely is it you would recommend our Azure CLI to a friend or colleague? [0 to 10]: ' -MSG_INTR = 'We appreciate your feedback! This survey is only two questions and should take less than a minute.' -MSG_BAD = '\nWhat changes would we have to make for you to give us a higher rating? ' -MSG_GOOD = '\nWhat do we do really well? ' -MSG_EMIL = '\nIf you would like to join our insiders program and receive tips, tricks, and early access to new ' \ - 'features, let us know by leaving your email address (leave blank to skip): ' -MSG_THNK = '\nThanks for your feedback!' +_MSG_THNK = 'Thanks for your feedback!' + +_GET_STARTED_URL = "aka.ms/azcli/get-started" +_QUESTIONS_URL = "aka.ms/azcli/questions" +_CLI_ISSUES_URL = "aka.ms/azcli/issues" +_EXTENSIONS_ISSUES_URL = "aka.ms/azcli/ext/issues" + +_MSG_INTR = \ + '\nWe appreciate your feedback!\n\n' \ + 'For more information on getting started, visit: {}\n' \ + 'If you have questions, visit our Stack Overflow page: {}\n'\ + .format(_GET_STARTED_URL, _QUESTIONS_URL) + +_MSG_CMD_ISSUE = "\nEnter the number of the command you would like to create an issue for. Enter q to quit: " + +_MSG_ISSUE = "Would you like to create an issue? Enter Y or N: " + +_ISSUES_TEMPLATE_PREFIX = """ + +BEGIN TEMPLATE +=============== +**A browser has been opened to {} to create an issue.** +**The issue template has been copied to your clipboard. You can also run `az feedback --verbose` to emit the output to stdout.** +""" + +_ISSUES_TEMPLATE = """ + +### **This is an autogenerated template. Please review and update as needed.** + +## Describe the bug + +**Command Name** +`{command_name}` + +**Errors:** +{errors_string} + +## To Reproduce: +Steps to reproduce the behavior. Note: Command arguments have been redacted. + +- `Fill in additional info here` +- `Run: {executed_command}` + +## Expected Behavior + +A clear and concise description of what you expected to happen. + +## Environment Summary +``` +{platform} +{python_info} +{shell} + +{cli_version} +``` +## Additional Context +Add any other context about the problem here. + + +{auto_gen_comment} + +""" + +_AUTO_GEN_COMMENT = "" + +_LogMetadataType = namedtuple('LogMetadata', ['cmd', 'seconds_ago', 'file_path', 'p_id']) + + +class CommandLogFile(object): + _LogRecordType = namedtuple("LogRecord", ["p_id", "date_time", "level", "logger", "log_msg"]) + UNKNOWN_CMD = "Unknown" + + def __init__(self, log_file_path, time_now=None): + + if (time_now is not None) and (not isinstance(time_now, datetime.datetime)): + raise TypeError("Expected type {} for time_now, instead received {}.".format(datetime.datetime, type(time_now))) # pylint: disable=line-too-long + + if not os.path.isfile(log_file_path): + raise ValueError("File {} is not an existing file.".format(log_file_path)) + + self._command_name = None + self._log_file_path = log_file_path + if time_now is None: + self._time_now = datetime.datetime.now() + else: + self._time_now = time_now + + self._metadata = self._get_command_metadata_from_file() + self._data = None + + @property + def metadata_tup(self): + return self._metadata + + @property + def command_data_dict(self): + if not self._data: + self._data = self._get_command_data_from_metadata() + return self._data + + def get_command_name_str(self): + if self._command_name is not None: + return self._command_name # attempt to return cached command name + + if not self.metadata_tup: + return "" + + args = self.command_data_dict.get("command_args", "") + + if self.metadata_tup.cmd != self.UNKNOWN_CMD: + self._command_name = self.metadata_tup.cmd + + if "-h" in args or "--help" in args: + self._command_name += " --help" + else: + self._command_name = self.UNKNOWN_CMD + if args: + command_args = args if len(args) < 16 else args[:11] + " ..." + command_args = command_args.replace("=", "").replace("{", "").replace("}", "") + self._command_name = "{} ({}) ".format(self._command_name, command_args) + + return self._command_name + + def get_command_status(self): + if not self.command_data_dict: + return "" + + was_successful = self.command_data_dict.get("success", None) + if was_successful is None: + success_msg = "RUNNING" + else: + success_msg = "SUCCESS" if was_successful else "FAILURE" + return success_msg + + def get_command_time_str(self): + if not self.metadata_tup: + return "" + + total_seconds = self.metadata_tup.seconds_ago + + time_delta = datetime.timedelta(seconds=total_seconds) + logger.debug("%s time_delta", time_delta) + + if time_delta.days > 0: + time_str = "Ran: {} days ago".format(time_delta.days) + elif total_seconds > _ONE_HR_IN_SECS: + hrs, secs = divmod(total_seconds, _ONE_HR_IN_SECS) + logger.debug("%s hrs, %s secs", hrs, secs) + hrs = int(hrs) + mins = math.floor(secs / _ONE_MIN_IN_SECS) + time_str = "Ran: {} hrs {:02} mins ago".format(hrs, mins) + elif total_seconds > _ONE_MIN_IN_SECS: + time_str = "Ran: {} mins ago".format(math.floor(total_seconds / _ONE_MIN_IN_SECS)) + else: + time_str = "Ran: {} secs ago".format(math.floor(total_seconds)) + + return time_str + + def _get_command_metadata_from_file(self): + if not self._log_file_path: + return None + + time_now = datetime.datetime.now() if not self._time_now else self._time_now -def _prompt_net_promoter_score(): - score = -1 - help_string = 'Please rate between 0 and 10' - while score < 0 or score > 10: try: - score = int(prompt(MSG_RATE, help_string=help_string)) - except ValueError: - logger.warning(help_string) + _, file_name = os.path.split(self._log_file_path) + poss_date, poss_time, poss_command, poss_pid, _ = file_name.split(".") + date_time_stamp = datetime.datetime.strptime("{}-{}".format(poss_date, poss_time), "%Y-%m-%d-%H-%M-%S") + command = "az " + poss_command.replace("_", " ") if poss_command != _UNKNOWN_COMMAND else self.UNKNOWN_CMD # pylint: disable=line-too-long + except ValueError as e: + logger.debug("Could not load metadata from file name %s.", self._log_file_path) + logger.debug(e) + return None - return score + difference = time_now - date_time_stamp + total_seconds = difference.total_seconds() -def _get_version_info(): - installed_dists = get_installed_cli_distributions() + return _LogMetadataType(cmd=command, seconds_ago=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) # pylint: disable=line-too-long - component_version_info = sorted([{'name': dist.key.replace(COMPONENT_PREFIX, ''), - 'version': dist.version} - for dist in installed_dists - if dist.key.startswith(COMPONENT_PREFIX)], - key=lambda x: x['name']) - return str(component_version_info), sys.version + def _get_command_data_from_metadata(self): # pylint: disable=too-many-statements + def _get_log_record_list(log_fp, p_id): + """ + Get list of records / messages in the log file + :param log_fp: log file object + :param p_id: process id of command + :return: + """ + prev_record = None + log_record_list = [] + for line in log_fp: + # attempt to extract log data + log_record = CommandLogFile._get_info_from_log_line(line, p_id) + if log_record: # if new record parsed, add old record to the list + if prev_record: + log_record_list.append(prev_record) + prev_record = log_record + elif prev_record: # otherwise this is a continuation of a log record, add to prev record + new_log_msg = prev_record.log_msg + line + prev_record = CommandLogFile._LogRecordType(p_id=prev_record.p_id, date_time=prev_record.date_time, + # pylint: disable=line-too-long + level=prev_record.level, logger=prev_record.logger, + log_msg=new_log_msg) + if prev_record: + log_record_list.append(prev_record) + return log_record_list -def handle_feedback(): - try: - print(MSG_INTR) - score = _prompt_net_promoter_score() - if score == 10: - suggestion = prompt(MSG_GOOD) + if not self.metadata_tup: + return {} + + _EXT_NAME_PREFIX = "extension name:" + _EXT_VERS_PREFIX = "extension version:" + + file_name = self.metadata_tup.file_path + p_id = self.metadata_tup.p_id + + try: + with open(file_name, 'r') as log_fp: + log_record_list = _get_log_record_list(log_fp, p_id) + except IOError: + logger.debug("Failed to open command log file %s", file_name) + return {} + + if not log_record_list: + logger.debug("No command log messages found in file %s", file_name) + return {} + + log_data = {} + # 1. Figure out whether the command was successful or not. Last log record should be the exit code + try: + status_msg = log_record_list[-1].log_msg.strip() + if status_msg.startswith("exit code"): + idx = status_msg.index(":") # raises ValueError + exit_code = int(log_record_list[-1].log_msg[idx + 1:].strip()) + log_data["success"] = True if not exit_code else False + except (IndexError, ValueError): + logger.debug("Couldn't extract exit code from command log %s.", file_name) + + # 2. If there are any errors, this is a failed command. Log the errors + # 3. Also get extension information. + for record in log_record_list: + errors = log_data.setdefault("errors", []) # log_data["errors"] + if record.level.lower() == "error": + log_data["success"] = False + errors.append(record.log_msg) + + poss_ext_msg = record.log_msg.strip() + if record.level.lower() == "info": + if poss_ext_msg.startswith(_EXT_NAME_PREFIX): + log_data["extension_name"] = poss_ext_msg[len(_EXT_NAME_PREFIX):].strip() + elif poss_ext_msg.startswith(_EXT_VERS_PREFIX): + log_data["extension_version"] = poss_ext_msg[len(_EXT_VERS_PREFIX):].strip() + + # 4. Get command args string. from first record + try: + command_args_msg = log_record_list[0].log_msg.strip() + if command_args_msg.lower().startswith("command args:"): + idx = command_args_msg.index(":") + log_data["command_args"] = command_args_msg[idx + 1:].strip() + else: + raise ValueError + except (IndexError, ValueError): + logger.debug("Couldn't get command args from command log %s.", file_name) + + return log_data + + @staticmethod + def _get_info_from_log_line(line, p_id): + """ + + Extract log line information based on the following command log format in azlogging.py + + lfmt = logging.Formatter('%(process)d | %(created)s | %(levelname)s | %(name)s | %(message)s') + + :param line: the line from the log file. + :return: returned parsed line information or None + """ + + if not line.startswith(_CMD_LOG_LINE_PREFIX): + return None + + line = line[len(_CMD_LOG_LINE_PREFIX):] + parts = line.split("|", 4) + + if len(parts) != 5: # there must be 5 items + return None + + for i, part in enumerate(parts): + parts[i] = part.strip() + if i == 0: + parts[0] = int(parts[0]) + if parts[0] != p_id: # ensure that this is indeed a valid log. + return None + + return CommandLogFile._LogRecordType(*parts) + + +def _build_issue_info_tup(command_log_file=None): + def _get_parent_proc_name(): + import psutil + parent = psutil.Process(os.getpid()).parent() + if parent: + # powershell.exe launches cmd.exe to launch the cli. + grandparent = parent.parent() + if grandparent and grandparent.name().lower().startswith("powershell"): + return grandparent.name() + # if powershell is not the grandparent, simply return the parent's name. + return parent.name() + return None + + format_dict = {"command_name": "", "errors_string": "", + "executed_command": ""} + + is_ext = False + # Get command information, if applicable + if command_log_file: + command_name = command_log_file.metadata_tup.cmd + format_dict["command_name"] = command_name + + if command_log_file.command_data_dict: + errors = "\n".join(command_log_file.command_data_dict.get("errors", [])) + executed_command = command_log_file.command_data_dict.get("command_args", "") + extension_name = command_log_file.command_data_dict.get("extension_name", "") + extension_version = command_log_file.command_data_dict.get("extension_version", "") + + extension_info = "" + if extension_name: + extension_info = "\nExtension Name: {}. Version: {}.".format(extension_name, extension_version) + is_ext = True + + if errors: + num_lines = errors.count("\n") + reaction = ":confused:" + if num_lines >= 100: + reaction = ":expressionless:" + elif num_lines >= 15: + reaction = ":open_mouth:" + errors = "\n{}\n\n```{}```".format(reaction, errors) + + format_dict["errors_string"] = errors + format_dict["executed_command"] = "az " + executed_command if executed_command else executed_command + format_dict["command_name"] += extension_info + + # Get other system information + format_dict["cli_version"] = _get_az_version_summary() + format_dict["python_info"] = "Python {}".format(platform.python_version()) + format_dict["platform"] = "{}".format(platform.platform()) + format_dict["shell"] = "Shell: {}".format(_get_parent_proc_name()) + format_dict["auto_gen_comment"] = _AUTO_GEN_COMMENT + + issues_url = _EXTENSIONS_ISSUES_URL if is_ext else _CLI_ISSUES_URL + + # prefix formatted url with 'https://' if necessary and supply empty body to remove any existing issue template + formatted_issues_url = issues_url + if not formatted_issues_url.startswith("http"): + formatted_issues_url = "https://" + formatted_issues_url + new_placeholder = urlencode({'body': "The issue has been copied to your clipboard. Paste it here!" + "\nTo print out the issue body locally, run `az feedback --verbose`"}) + formatted_issues_url = "{}?{}".format(formatted_issues_url, new_placeholder) + + return _ISSUES_TEMPLATE_PREFIX.format(issues_url), _ISSUES_TEMPLATE.format(**format_dict), formatted_issues_url + + +def _get_az_version_summary(): + """ + This depends on get_az_version_string not being changed, add some tests to make this and other methods more robust. + :return: az version info + """ + az_vers_string = get_az_version_string()[0] + + lines = az_vers_string.splitlines() + + new_lines = [] + ext_line = -1 + legal_line = -1 + for i, line in enumerate(lines): + if line.startswith("azure-cli"): + new_lines.append(line) + if line.lower().startswith("extensions:"): + ext_line = i + continue + l_lower = line.lower() + if all(["legal" in l_lower, "docs" in l_lower, "info" in l_lower]): + legal_line = i + break + + new_lines.append("") + + if 0 < ext_line < legal_line: + for i in range(ext_line, legal_line): + new_lines.append(lines[i]) + + return "\n".join(new_lines) + + +def _get_command_log_files(cli_ctx, time_now=None): + command_logs_dir = cli_ctx.logging.get_command_log_dir() + files = os.listdir(command_logs_dir) + files = (file_name for file_name in files if file_name.endswith(".log")) + files = sorted(files) + command_log_files = [] + for file_name in files: + file_path = os.path.join(command_logs_dir, file_name) + cmd_log_file = CommandLogFile(file_path, time_now) + + if cmd_log_file.metadata_tup: + command_log_files.append(cmd_log_file) + else: + logger.debug("%s is an invalid command log file.", file_path) + return command_log_files + + +def _display_recent_commands(cmd): + def _pad_string(my_str, pad_len): + while len(my_str) < pad_len: + my_str += " " + return my_str + + time_now = datetime.datetime.now() + + command_log_files = _get_command_log_files(cmd.cli_ctx, time_now) + + # if no command log files, return + if not command_log_files: + return [] + + command_log_files = command_log_files[-9:] + + max_len_dict = dict(name_len=0, success_len=0, time_len=0) + + for log_file in command_log_files: + max_len_dict["name_len"] = max(len(log_file.get_command_name_str()), max_len_dict["name_len"]) + max_len_dict["success_len"] = max(len(log_file.get_command_status()), max_len_dict["success_len"]) + max_len_dict["time_len"] = max(len(log_file.get_command_time_str()), max_len_dict["time_len"]) + + print("Recent commands:\n") + command_log_files = [None] + command_log_files + for i, log_info in enumerate(command_log_files): + if log_info is None: + print(" [{}] {}".format(i, "create a generic issue.")) else: - suggestion = prompt(MSG_BAD) - email_address = prompt(MSG_EMIL) - set_feedback('[{}]{}[{}]'.format(score, suggestion, email_address)) - print(MSG_THNK) + cmd_name = _pad_string(log_info.get_command_name_str(), max_len_dict["name_len"]) + success_msg = _pad_string(log_info.get_command_status() + ".", max_len_dict["success_len"] + 1) + time_msg = _pad_string(log_info.get_command_time_str() + ".", max_len_dict["time_len"] + 1) + print(" [{}] {}: {} {}".format(i, cmd_name, success_msg, time_msg)) + + return command_log_files + + +def _prompt_issue(recent_command_list): + if recent_command_list: + max_idx = len(recent_command_list) - 1 + ans = -1 + help_string = 'Please choose between 0 and {}, or enter q to quit: '.format(max_idx) + + while ans < 0 or ans > max_idx: + try: + ans = prompt(_MSG_CMD_ISSUE.format(max_idx), help_string=help_string) + if ans.lower() in ["q", "quit"]: + ans = ans.lower() + break + ans = int(ans) + except ValueError: + logger.warning(help_string) + ans = -1 + + else: + ans = None + help_string = 'Please choose between Y and N: ' + + while not ans: + ans = prompt(_MSG_ISSUE, help_string=help_string) + if ans.lower() not in ["y", "n", "yes", "no", "q"]: + ans = None + continue + + # strip to short form + ans = ans[0].lower() if ans else None + + if ans in ["y", "n"]: + if ans == "y": + prefix, body, url = _build_issue_info_tup() + else: + return False + else: + if ans in ["q", "quit"]: + return False + if ans == 0: + prefix, body, url = _build_issue_info_tup() + else: + prefix, body, url = _build_issue_info_tup(recent_command_list[ans]) + + print(prefix) + + # open issues page in browser and copy issue body to clipboard + try: + pyperclip.copy(body) + except pyperclip.PyperclipException as ex: + logger.debug(ex) + + logger.info(body) + open_page_in_browser(url) + + return True + + +def handle_feedback(cmd): + try: + print(_MSG_INTR) + recent_commands = _display_recent_commands(cmd) + res = _prompt_issue(recent_commands) + + if res: + print(_MSG_THNK) + return except NoTTYException: - raise CLIError('This command is interactive and no tty available.') + raise CLIError('This command is interactive, however no tty is available.') except (EOFError, KeyboardInterrupt): print() diff --git a/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/__init__.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/__init__.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/__init__.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/__init__.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py new file mode 100644 index 00000000000..fafad62cda6 --- /dev/null +++ b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py @@ -0,0 +1,187 @@ +# -------------------------------------------------------------------------------------------- +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. See License.txt in the project root for license information. +# -------------------------------------------------------------------------------------------- + +import datetime +import logging +import os +import time +import unittest + +from azure.cli.core.azlogging import CommandLoggerContext +from azure.cli.core.extension.operations import get_extensions, add_extension, remove_extension, WheelExtension +from azure.cli.command_modules.feedback.custom import (_get_command_log_files, _build_issue_info_tup, + _CLI_ISSUES_URL, _EXTENSIONS_ISSUES_URL) +from azure.cli.testsdk import ScenarioTest +from azure.cli.testsdk.base import execute +from azure.cli.testsdk.reverse_dependency import get_dummy_cli + +# pylint: disable=line-too-long +# pylint: disable=too-many-lines + +logger = logging.getLogger(__name__) + + +class TestCommandLogFile(ScenarioTest): + + def __init__(self, *args, **kwargs): + super(TestCommandLogFile, self).__init__(*args, **kwargs) + + self.disable_recording = True + self.is_live = True + + @classmethod + def setUpClass(cls): + super(TestCommandLogFile, cls).setUpClass() + cls.ext_to_add_post_test = None + + # ensure that after tests are run we return to original extensions' state. + + cls.original_extensions = [ext.name for ext in get_extensions() if isinstance(ext, WheelExtension)] + + for ext_name in cls.original_extensions: + remove_extension(ext_name) + logger.warning("Removing ext %s, will reinstall it afterwards if it is a published whl extension.", ext_name) + + @classmethod + def tearDownClass(cls): + super(TestCommandLogFile, cls).tearDownClass() + + for ext_name in [ext.name for ext in get_extensions() if isinstance(ext, WheelExtension) and ext.name not in cls.original_extensions]: + remove_extension(ext_name) + logger.warning("Removing ext %s, as it was not in the original list of installed wheel extensions..", ext_name) + + for ext_name in cls.original_extensions: + add_extension(extension_name=ext_name) + logger.warning("Adding whl ext %s", ext_name) + + # using setup to benefit from self.cmd(). There should be only one test fixture in this class + def setUp(self): + super(TestCommandLogFile, self).setUp() + self.temp_command_log_dir = self.create_temp_dir() + + self.cli_ctx.logging.command_log_dir = self.temp_command_log_dir + + # populate command dir with logs + self._run_cmd("extension remove -n alias", expect_failure=True) + time.sleep(2) + self._run_cmd("extension add -n alias") + time.sleep(2) + self._run_cmd("alias create -n foo123 -c bar123", expect_failure=True) + time.sleep(2) + self._run_cmd("alias list") + + # There must be only one test fixture for this class. This is because the commands in setup must be run only once. + def test_feedback(self): + self._helper_test_log_metadata_correct() + self._helper_test_log_contents_correct() + self._helper_test_build_issue_info() + + def _helper_test_log_metadata_correct(self): + time_now = datetime.datetime.now() + command_log_files = _get_command_log_files(self.cli_ctx, time_now) + p_id = os.getpid() + self.assertEqual(len(command_log_files), 4) + + for log_file in command_log_files: + path = log_file.metadata_tup.file_path + time_ago = log_file.metadata_tup.seconds_ago + + # time of logging should be within a couple minutes of this check + self.assertTrue(time_ago < 300) + self.assertEqual(log_file.metadata_tup.p_id, p_id) + self.assertTrue(os.path.basename(path), self.temp_command_log_dir) + self.assertEqual(log_file.metadata_tup.cmd, log_file.get_command_name_str()) + + self.assertEqual("az extension remove", command_log_files[0].metadata_tup.cmd) + self.assertEqual("az extension add", command_log_files[1].metadata_tup.cmd) + self.assertEqual("az alias create", command_log_files[2].metadata_tup.cmd) + self.assertEqual("az alias list", command_log_files[3].metadata_tup.cmd) + + def _helper_test_log_contents_correct(self): + time_now = datetime.datetime.now() + command_log_files = _get_command_log_files(self.cli_ctx, time_now) + self.assertEqual(len(command_log_files), 4) + + self.assertEqual(command_log_files[0].get_command_status(), "FAILURE") + self.assertEqual(command_log_files[1].get_command_status(), "SUCCESS") + self.assertEqual(command_log_files[2].get_command_status(), "FAILURE") + self.assertEqual(command_log_files[3].get_command_status(), "SUCCESS") + + was_successful = command_log_files[0].command_data_dict.pop("success") + self.assertEqual(command_log_files[0].get_command_status(), "RUNNING") + command_log_files[0].command_data_dict["success"] = was_successful + + # check failed cli command: + data_dict = command_log_files[0].command_data_dict + self.assertTrue(data_dict["success"] is False) + self.assertEqual("There was an error during execution.", data_dict["errors"][0]) + self.assertEqual(data_dict["command_args"], "extension remove -n {}") + + # check successful cli command + data_dict = command_log_files[1].command_data_dict + self.assertTrue(data_dict["success"] is True) + self.assertEqual(data_dict["command_args"], "extension add -n {}") + + # check unsuccessful extension command + data_dict = command_log_files[2].command_data_dict + self.assertTrue(data_dict["success"] is False) + self.assertTrue("errors" in data_dict) + self.assertEqual(data_dict["command_args"], "alias create -n {} -c {}") + + # check successful extension command + data_dict = command_log_files[3].command_data_dict + self.assertTrue(data_dict["success"] is True) + self.assertEqual(data_dict["command_args"], "alias list") + + ext_version = self.cmd("az extension show -n alias").get_output_in_json()["version"] + for i, log_file in enumerate(command_log_files): + if i >= 2: + self.assertEqual(data_dict["extension_name"], "alias") + self.assertEqual(data_dict["extension_version"], ext_version) + + def _helper_test_build_issue_info(self): + items = [] + command_log_files = _get_command_log_files(self.cli_ctx) + + log_file = command_log_files[0] + issue_prefix, issue_body, _ = _build_issue_info_tup(log_file) + items.append((log_file, issue_body)) + self.assertTrue(_CLI_ISSUES_URL in issue_prefix) + + log_file = command_log_files[2] + issue_prefix, issue_body, _ = _build_issue_info_tup(log_file) + items.append((log_file, issue_body)) + self.assertTrue(_EXTENSIONS_ISSUES_URL in issue_prefix) + self.assertTrue(log_file.command_data_dict["extension_name"] in issue_body) + self.assertTrue(log_file.command_data_dict["extension_version"] in issue_body) + + for log_file, issue_body in items: + self.assertTrue(log_file.get_command_name_str() in issue_body) + self.assertTrue(log_file.command_data_dict["command_args"] in issue_body) + self.assertTrue(log_file.command_data_dict["errors"][0] in issue_body) + + @staticmethod + def _ext_installed(ext): + return ext in [ext.name for ext in get_extensions()] + + def _run_cmd(self, command, checks=None, expect_failure=False): + cli_ctx = get_dummy_cli() + cli_ctx.logging.command_log_dir = self.temp_command_log_dir + + result = execute(cli_ctx, command, expect_failure=expect_failure).assert_with_checks(checks) + + # manually handle error logging as azure.cli.core.util's handle_exception function is mocked out in testsdk / patches + # this logged error tests that we can properly parse errors from command log file. + with CommandLoggerContext(logger): + if result.exit_code != 0: + logger.error("There was an error during execution.") + + cli_ctx.logging.end_cmd_metadata_logging(result.exit_code) + + return result + + +if __name__ == '__main__': + unittest.main() diff --git a/src/command_modules/azure-cli-feedback/setup.py b/src/command_modules/azure-cli-feedback/setup.py index eb8d52d4e94..b5140ec22f9 100644 --- a/src/command_modules/azure-cli-feedback/setup.py +++ b/src/command_modules/azure-cli-feedback/setup.py @@ -15,7 +15,7 @@ cmdclass = {} -VERSION = "2.1.4" +VERSION = "2.2.0" CLASSIFIERS = [ 'Development Status :: 5 - Production/Stable', 'Intended Audience :: Developers', @@ -31,7 +31,6 @@ ] DEPENDENCIES = [ - 'applicationinsights', 'azure-cli-core', ] diff --git a/tools/automation/tests/verify_package_versions.py b/tools/automation/tests/verify_package_versions.py index 2c1079c2423..9ba0b97d21c 100644 --- a/tools/automation/tests/verify_package_versions.py +++ b/tools/automation/tests/verify_package_versions.py @@ -59,7 +59,7 @@ def version_in_base_repo(base_repo, mod_path, mod_name, mod_version): if mod_version == _get_mod_version(base_repo_mod_path): print('Version {} of {} is already used on in the base repo.'.format(mod_version, mod_name)) return True - except FileNotFoundError: + except OSError: # FileNotFoundError introduced in Python 3 print('Module {} not in base repo. Skipping...'.format(mod_name), file=sys.stderr) except Exception as ex: # Print warning if unable to get module from base version (e.g. mod didn't exist there)