From 26a3ddf7330b2958ed0fa40cfb74cd8477013ff7 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Fri, 15 Mar 2019 17:46:22 -0700 Subject: [PATCH 01/13] 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. --- .github/ISSUE_TEMPLATE/Bug_report.md | 2 + .../azure/cli/core/azlogging.py | 88 ++- .../azure/cli/core/commands/__init__.py | 1 + src/azure-cli-core/azure/cli/core/util.py | 16 +- src/azure-cli/azure/cli/__main__.py | 14 + .../cli/command_modules/feedback/custom.py | 547 ++++++++++++++++-- .../azure-cli-feedback/setup.py | 2 +- 7 files changed, 626 insertions(+), 44 deletions(-) diff --git a/.github/ISSUE_TEMPLATE/Bug_report.md b/.github/ISSUE_TEMPLATE/Bug_report.md index ec83fde65f6..a17a8574383 100644 --- a/.github/ISSUE_TEMPLATE/Bug_report.md +++ b/.github/ISSUE_TEMPLATE/Bug_report.md @@ -18,3 +18,5 @@ Install Method (e.g. pip, interactive script, apt-get, Docker, MSI, edge build) **Additional context** Add any other context about the problem here. + +Note: az feedback can be used to help generate some of this information. diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 38263248fd8..b712d043eb4 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -23,11 +23,93 @@ """ -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 = AzCliLogging._get_command_log_dir(cli_ctx) + 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) + + @staticmethod + def _get_command_log_dir(cli_ctx): + return os.path.join(cli_ctx.config.config_dir, 'commands') + + @staticmethod + def init_command_file_logging(cli_ctx, **kwargs): + def _delete_old_logs(log_dir): + log_file_names = [file for file in os.listdir(log_dir) if file.endswith(".log")] + sorted_files = sorted(log_file_names, reverse=True) + + if len(sorted_files) > 25: + for file in sorted_files[10:]: + os.remove(os.path.join(log_dir, file)) + + # 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) + 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 + command = command.replace(" ", "_") + if command == "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, 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') + 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 + + command_metadata_logger.info("command args: %s", " ".join(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, elapsed_time=None): + if self.command_metadata_logger: + if elapsed_time: + self.command_metadata_logger.info("command ran in %.3f seconds.", elapsed_time) + self.command_metadata_logger.info("exit code: %s", exit_code) - pass + # We have finished metadata logging, set metadata logger to None. + self.command_metadata_logger = None 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..afdaf83cd04 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/util.py b/src/azure-cli-core/azure/cli/core/util.py index efedcfe6eb8..106e7cab2d8 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -21,14 +21,22 @@ def handle_exception(ex, cli_ctx=None): + def remove_hdlr(exit_code, hdlr): + logger.removeHandler(hdlr) # remove command metadata handler + return exit_code + + hdlr = cli_ctx.logging.command_logger_handler + if hdlr: + logger.addHandler(hdlr) # add command metadata handler + # 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 + return remove_hdlr(ex.args[1] if len(ex.args) >= 2 else 1, hdlr) if isinstance(ex, KeyboardInterrupt): - return 1 + return remove_hdlr(1, hdlr) if isinstance(ex, HttpOperationError): try: response_dict = json.loads(ex.response.text) @@ -45,7 +53,7 @@ def handle_exception(ex, cli_ctx=None): except (ValueError, KeyError): logger.error(ex) - return 1 + return remove_hdlr(1, hdlr) # Otherwise, unhandled exception. Direct users to create an issue. is_extension = False @@ -61,7 +69,7 @@ def handle_exception(ex, cli_ctx=None): logger.exception(ex) logger.warning("\nTo open an issue, please visit: %s", issue_url) - return 1 + return remove_hdlr(1, hdlr) # pylint: disable=inconsistent-return-statements diff --git a/src/azure-cli/azure/cli/__main__.py b/src/azure-cli/azure/cli/__main__.py index 51b55727506..9f0a8dfe8bb 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,21 @@ 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, elapsed_time) + 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 + az_cli.logging._end_cmd_metadata_logging(exit_code, elapsed_time) + except NameError: + az_cli.logging._end_cmd_metadata_logging(exit_code, None) + finally: telemetry.conclude() 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..e1c4038507d 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,536 @@ # -------------------------------------------------------------------------------------------- from __future__ import print_function -import sys +import os +import math +import platform +import datetime + +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 = "If you would like to create an issue, please enter the number of the appropriate command.\n" \ + "Otherwise enter 0 to create a generic issue or 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 autogenerated template contains command parameters. Please review and remove sensitive information, if necessary** + +## Describe the bug + +**Command Name** + `{command_name}` + +**Ran:** + `{executed_command}` + + +**Command Duration** + {command_duration} + +**Errors:** +{errors_string} + +## To Reproduce: + + +## Expected behavior + +A clear and concise description of what you expected to happen. + +## Environment summary + +**Python Info** + {python_info} + +**System Info** + {system_name} + {platform} + {shell} + +**CLI Version** + +{cli_version} + +## Additional context +Add any other context about the problem here. + +""" + + +_LogMetadataType = namedtuple('LogMetadata', ['cmd', 'log_time', 'file_path', 'p_id']) + +class CommandLogFile(object): + _LogRecordType = namedtuple("LogRecord", ["p_id", "date_time", "level", "logger", "log_msg"]) + + 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 {}.", datetime.datetime, type(time_now)) + + if not os.path.isfile(log_file_path): + raise ValueError("File {} is not an existing file.", log_file_path) + + 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(self): + if not self.metadata_tup: + return "" + + return self.metadata_tup.cmd + + 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.log_time + + time_delta = datetime.timedelta(seconds=total_seconds) + + 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) + hrs = int(hrs) + mins = math.floor(total_seconds / _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_duration_str(self): + if not self.command_data_dict: + return "" + + duration = float(self.command_data_dict.get("duration", -1)) + + if duration < 0: + return "" + + if duration > _ONE_HR_IN_SECS: + hrs, secs = divmod(duration, _ONE_HR_IN_SECS) + hrs = math.floor(hrs) + mins = math.floor(secs / _ONE_MIN_IN_SECS) + duration_str = "Duration: {} hrs {:02} mins".format(hrs, mins) + elif duration > _ONE_MIN_IN_SECS: + mins, secs = divmod(duration, _ONE_MIN_IN_SECS) + mins = math.floor(mins) + secs = math.floor(secs) + duration_str = "Duration: {} mins {:02} secs".format(mins, secs) + else: + duration_str = "Duration: {:.2f} secs".format(duration) + + return duration_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 + + try: + _, file_name = os.path.split(self._log_file_path) + poss_date, poss_time, poss_command, poss_pid, _ = file_name.split(sep=".") + 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 "Unknown" + except ValueError as e: + logger.debug("Could not load metadata from file name %s.", self._log_file_path) + logger.debug(e) + return None + + difference = (time_now - date_time_stamp) + + total_seconds = difference.total_seconds() + + + return _LogMetadataType(cmd=command, log_time=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) + + + def _get_command_data_from_metadata(self): + if not self.metadata_tup: + return None + _EXT_NAME_PREFIX = "extension name:" + _EXT_VERS_PREFIX = "extension version:" -def _prompt_net_promoter_score(): - score = -1 - help_string = 'Please rate between 0 and 10' - while score < 0 or score > 10: + file_name = self.metadata_tup.file_path + p_id = self.metadata_tup.p_id + + try: + with open(file_name, 'r') as log_fp: + 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, + level=prev_record.level, + logger=prev_record.logger, log_msg=new_log_msg) + + if prev_record: + log_record_list.append(prev_record) + + if not log_record_list: + logger.debug("No command log messages found in file %s", file_name) + return None + + except IOError: + logger.debug("Failed to open command log file %s", file_name) + return None + + + 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. Get the duration of the command. Duration is printed before last log record if any + try: + command_duration_msg = log_record_list[-2].log_msg.strip() + if command_duration_msg.startswith("command ran in"): + words = command_duration_msg.split() + for word in words: + try: + log_data["duration"] = float(word) + break + except ValueError: + continue + except IndexError: + logger.debug("Couldn't extract duration from command log %s.", file_name) + + # 3. If there are any errors, this is a failed command. Log the errors + # 4. 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() + + # 5. Get command args. from first record try: - score = int(prompt(MSG_RATE, help_string=help_string)) - except ValueError: - logger.warning(help_string) + command_args_msg = log_record_list[0].log_msg.strip().lower() + if command_args_msg.startswith("command args:"): + idx = command_args_msg.index(":") + log_data["command_args"] = command_args_msg[idx + 1:] + else: + raise ValueError + except (IndexError, ValueError): + logger.debug("Couldn't get command args from command log %s.", file_name) + + return log_data or None + + @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') - return score + :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 -def _get_version_info(): - installed_dists = get_installed_cli_distributions() + line = line[len(CMD_LOG_LINE_PREFIX):] + parts = line.split("|", maxsplit=4) - 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 + if len(parts) != 5: # there must be 5 items + return None + for i, part in enumerate(parts): + if i == 0: + parts[0] = int(parts[0]) + if parts[0] != p_id: # ensure that this is indeed a valid log. + return None + else: + parts[i] = part.strip() -def handle_feedback(): + return CommandLogFile._LogRecordType(*parts) + + +def _prompt_issue(recent_command_list): + if recent_command_list: + max_idx = len(recent_command_list) + ans = -1 + help_string = 'Please rate between 0 and {}, or enter q to quit: '.format(max_idx) + + while ans < 0 or ans > max_idx: + try: + ans = prompt(MSG_CMD_ISSUE, help_string=help_string) + if ans in ["q", "quit"]: + break + ans = int(ans) + except ValueError: + logger.warning(help_string) + ans = -1 + + else: + ans = None + help_string = 'Please rate between Y and N: ' + + while not ans: + ans = prompt(MSG_ISSUE, help_string=help_string) + if ans.lower() not in ["y", "n", "yes", "no"]: + 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_body() + else: + return False + else: + if ans in ["q", "quit"]: + return False + if ans == 0: + prefix, body, url = _build_issue_body() + + else: + prefix, body, url = _build_issue_body(recent_command_list[ans-1]) + + print(prefix) + + # open issues page in browser and copy issue body to clipboard try: - print(MSG_INTR) - score = _prompt_net_promoter_score() - if score == 10: - suggestion = prompt(MSG_GOOD) + pyperclip.copy(body) + except pyperclip.PyperclipException as ex: + logger.debug(ex) + + logger.info(body) + open_page_in_browser("https://" + url) + + return True + + +def _build_issue_body(command_log_file=None): + + format_dict = {"command_name": "", + "command_duration": "", "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 + + format_dict["command_duration"] = command_log_file.get_command_duration_str() + 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["system_name"] = "OS/System Name: {}".format(platform.system()) + format_dict["platform"] = "Platform Name: {}".format(platform.platform()) + format_dict["shell"] = "Shell: {}".format(os.getenv("SHELL", "")) + + issues_url = _EXTENSIONS_ISSUES_URL if is_ext else _CLI_ISSUES_URL + + return _ISSUES_TEMPLATE_PREFIX.format(issues_url), _ISSUES_TEMPLATE.format(**format_dict), 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 _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_logs_dir = cmd.cli_ctx.logging._get_command_log_dir(cmd.cli_ctx) + + 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: - suggestion = prompt(MSG_BAD) - email_address = prompt(MSG_EMIL) - set_feedback('[{}]{}[{}]'.format(score, suggestion, email_address)) - print(MSG_THNK) + logger.debug("%s is an invalid command log file.", file_path) + + 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, duration_len=0) + + for log_file in command_log_files: + max_len_dict["name_len"] = max(len(log_file.metadata_tup.cmd), 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"]) + max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) + + for i, log_info in enumerate(command_log_files): + idx = i + 1 + + cmd_name = _pad_string(log_info.metadata_tup.cmd, 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) + duration_msg = _pad_string(log_info.get_command_duration_str() + ".", max_len_dict["duration_len"] + 1) + print(" [{}] {}: {} {} {} ".format(idx, cmd_name, success_msg, time_msg, duration_msg)) + + return command_log_files + + +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/setup.py b/src/command_modules/azure-cli-feedback/setup.py index eb8d52d4e94..e4c8a694225 100644 --- a/src/command_modules/azure-cli-feedback/setup.py +++ b/src/command_modules/azure-cli-feedback/setup.py @@ -31,8 +31,8 @@ ] DEPENDENCIES = [ - 'applicationinsights', 'azure-cli-core', + 'pyperclip' ] with open('README.rst', 'r', encoding='utf-8') as f: From 3019d1c5ae5078e73870e659a70c5236e43424c2 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Mon, 25 Mar 2019 21:32:41 -0700 Subject: [PATCH 02/13] Add tests for az feedback. Update bug_report.md file. Fix exit code bug. --- .github/ISSUE_TEMPLATE/Bug_report.md | 7 +- .../azure/cli/core/azlogging.py | 34 ++- src/azure-cli-core/azure/cli/core/util.py | 80 ++++--- src/azure-cli-core/setup.py | 2 + src/azure-cli/azure/cli/__main__.py | 2 +- .../command_modules/feedback/test_feedback.py | 198 ++++++++++++++++++ .../cli/command_modules/feedback/custom.py | 192 +++++++++-------- .../azure-cli-feedback/setup.py | 1 - 8 files changed, 377 insertions(+), 139 deletions(-) create mode 100644 src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py diff --git a/.github/ISSUE_TEMPLATE/Bug_report.md b/.github/ISSUE_TEMPLATE/Bug_report.md index a17a8574383..e3dfc3ac02e 100644 --- a/.github/ISSUE_TEMPLATE/Bug_report.md +++ b/.github/ISSUE_TEMPLATE/Bug_report.md @@ -4,6 +4,9 @@ about: Create a report to help us improve --- +#### **TIP**: `az feedback` +`az feedback` can be used to help generate some of the information requested below, such as, command, error and environment information. + **Describe the bug** A clear and concise description of what the bug is. @@ -17,6 +20,4 @@ A clear and concise description of what you expected to happen. Install Method (e.g. pip, interactive script, apt-get, Docker, MSI, edge build) / CLI version (`az --version`) / OS version / Shell Type (e.g. bash, cmd.exe, Bash on Windows) **Additional context** -Add any other context about the problem here. - -Note: az feedback can be used to help generate some of this information. +Add any other context about the problem here. \ No newline at end of file diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index b712d043eb4..b762a619d58 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -40,14 +40,14 @@ class AzCliLogging(CLILogging): def __init__(self, name, cli_ctx=None): super(AzCliLogging, self).__init__(name, cli_ctx) - self.command_log_dir = AzCliLogging._get_command_log_dir(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) - @staticmethod - def _get_command_log_dir(cli_ctx): - return os.path.join(cli_ctx.config.config_dir, 'commands') + + def _get_command_log_dir(self): + return self.command_log_dir @staticmethod def init_command_file_logging(cli_ctx, **kwargs): @@ -111,5 +111,29 @@ def _end_cmd_metadata_logging(self, exit_code, elapsed_time=None): self.command_metadata_logger.info("command ran in %.3f seconds.", elapsed_time) self.command_metadata_logger.info("exit code: %s", exit_code) - # We have finished metadata logging, set metadata logger to None. + # 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, cli_ctx, module_logger): + self.cli_ctx = cli_ctx + self.logger = module_logger + + + def __enter__(self): + if not self.cli_ctx: + return self + hdlr = self.cli_ctx.logging.command_logger_handler + if hdlr: + self.logger.addHandler(hdlr) # add command metadata handler + return self + + def __exit__(self, exc_type, exc_val, exc_tb): + if not self.cli_ctx: + return + hdlr = self.cli_ctx.logging.command_logger_handler + if hdlr: + self.logger.removeHandler(hdlr) diff --git a/src/azure-cli-core/azure/cli/core/util.py b/src/azure-cli-core/azure/cli/core/util.py index 106e7cab2d8..7eec822c025 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -21,55 +21,51 @@ def handle_exception(ex, cli_ctx=None): - def remove_hdlr(exit_code, hdlr): - logger.removeHandler(hdlr) # remove command metadata handler - return exit_code - - hdlr = cli_ctx.logging.command_logger_handler - if hdlr: - logger.addHandler(hdlr) # add command metadata handler - # 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 remove_hdlr(ex.args[1] if len(ex.args) >= 2 else 1, hdlr) - if isinstance(ex, KeyboardInterrupt): - return remove_hdlr(1, hdlr) - 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 remove_hdlr(1, hdlr) + with CommandLoggerContext(cli_ctx, 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 + 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 + + # 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) + 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) - return remove_hdlr(1, hdlr) + return 1 # pylint: disable=inconsistent-return-statements diff --git a/src/azure-cli-core/setup.py b/src/azure-cli-core/setup.py index 5e415bb4491..7c531bb72f3 100644 --- a/src/azure-cli-core/setup.py +++ b/src/azure-cli-core/setup.py @@ -73,6 +73,8 @@ 'tabulate>=0.7.7', 'wheel==0.30.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 9f0a8dfe8bb..851bf8d38f7 100644 --- a/src/azure-cli/azure/cli/__main__.py +++ b/src/azure-cli/azure/cli/__main__.py @@ -60,6 +60,6 @@ def cli_main(cli, args): az_cli.logging._end_cmd_metadata_logging(exit_code, elapsed_time) except NameError: az_cli.logging._end_cmd_metadata_logging(exit_code, None) - + raise ex finally: telemetry.conclude() diff --git a/src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py b/src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py new file mode 100644 index 00000000000..3b7baa4ffa4 --- /dev/null +++ b/src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py @@ -0,0 +1,198 @@ +# -------------------------------------------------------------------------------------------- +# 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 timeit + + +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 + + +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): + + for file in os.listdir(self.temp_command_log_dir): + with open(os.path.join(self.temp_command_log_dir, file), "r") as f: + print("File contents:\n%s", f.read()) + + print("temp dir contents: %s", os.listdir(self.temp_command_log_dir)) + + 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()) + + 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 alias") + + # 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 alias") + + # 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 foo123 -c bar123") + + # 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): + self.assertTrue("duration" in data_dict) + 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() in issue_body) + self.assertTrue(log_file.get_command_duration_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): + start_time = timeit.default_timer() + + 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 in testsdk / patches + with CommandLoggerContext(cli_ctx, logger): + if result.exit_code != 0: + logger.error("There was an error during execution.") + + elapsed_time = timeit.default_timer() - start_time + cli_ctx.logging._end_cmd_metadata_logging(result.exit_code, elapsed_time) + + return result 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 e1c4038507d..bd58d677530 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 @@ -27,23 +27,22 @@ logger = get_logger(__name__) -MSG_THNK = 'Thanks 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 = \ +_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 = "If you would like to create an issue, please enter the number of the appropriate command.\n" \ - "Otherwise enter 0 to create a generic issue or enter q to quit: " +_MSG_CMD_ISSUE = "\nEnter the number of the command you would like to create an issue for. \nEnter {} to create a generic issue. Enter q to quit: " -MSG_ISSUE = "Would you like to create an issue? Enter Y or N: " +_MSG_ISSUE = "Would you like to create an issue? Enter Y or N: " _ISSUES_TEMPLATE_PREFIX = """ @@ -98,13 +97,13 @@ """ +_LogMetadataType = namedtuple('LogMetadata', ['cmd', 'seconds_ago', 'file_path', 'p_id']) -_LogMetadataType = namedtuple('LogMetadata', ['cmd', 'log_time', 'file_path', 'p_id']) class CommandLogFile(object): _LogRecordType = namedtuple("LogRecord", ["p_id", "date_time", "level", "logger", "log_msg"]) - def __init__(self, log_file_path, time_now=None): + def __init__(self, log_file_path, time_now=None, cli_ctx=None): if (time_now is not None) and (not isinstance(time_now, datetime.datetime)): raise TypeError("Expected type {} for time_now, instead received {}.", datetime.datetime, type(time_now)) @@ -122,6 +121,8 @@ def __init__(self, log_file_path, time_now=None): self._metadata = self._get_command_metadata_from_file() self._data = None + self.cli_ctx = None + @property def metadata_tup(self): @@ -154,16 +155,18 @@ def get_command_time_str(self): if not self.metadata_tup: return "" - total_seconds = self.metadata_tup.log_time + 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(total_seconds / _ONE_MIN_IN_SECS) + 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)) @@ -213,12 +216,12 @@ def _get_command_metadata_from_file(self): logger.debug(e) return None - difference = (time_now - date_time_stamp) + difference = time_now - date_time_stamp total_seconds = difference.total_seconds() - return _LogMetadataType(cmd=command, log_time=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) + return _LogMetadataType(cmd=command, seconds_ago=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) def _get_command_data_from_metadata(self): @@ -306,7 +309,7 @@ def _get_command_data_from_metadata(self): command_args_msg = log_record_list[0].log_msg.strip().lower() if command_args_msg.startswith("command args:"): idx = command_args_msg.index(":") - log_data["command_args"] = command_args_msg[idx + 1:] + log_data["command_args"] = command_args_msg[idx + 1:].strip() else: raise ValueError except (IndexError, ValueError): @@ -346,64 +349,14 @@ def _get_info_from_log_line(line, p_id): return CommandLogFile._LogRecordType(*parts) -def _prompt_issue(recent_command_list): - if recent_command_list: - max_idx = len(recent_command_list) - ans = -1 - help_string = 'Please rate between 0 and {}, or enter q to quit: '.format(max_idx) - - while ans < 0 or ans > max_idx: - try: - ans = prompt(MSG_CMD_ISSUE, help_string=help_string) - if ans in ["q", "quit"]: - break - ans = int(ans) - except ValueError: - logger.warning(help_string) - ans = -1 - - else: - ans = None - help_string = 'Please rate between Y and N: ' - - while not ans: - ans = prompt(MSG_ISSUE, help_string=help_string) - if ans.lower() not in ["y", "n", "yes", "no"]: - 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_body() +def _build_issue_info_tup(command_log_file=None): + def _get_parent_proc_name(): + import psutil + parent = psutil.Process(os.getpid()).parent() + if parent: + return parent.name() else: - return False - else: - if ans in ["q", "quit"]: - return False - if ans == 0: - prefix, body, url = _build_issue_body() - - else: - prefix, body, url = _build_issue_body(recent_command_list[ans-1]) - - 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("https://" + url) - - return True - - -def _build_issue_body(command_log_file=None): + return None format_dict = {"command_name": "", "command_duration": "", "errors_string": "", @@ -436,7 +389,7 @@ def _build_issue_body(command_log_file=None): format_dict["python_info"] = "Python {}".format(platform.python_version()) format_dict["system_name"] = "OS/System Name: {}".format(platform.system()) format_dict["platform"] = "Platform Name: {}".format(platform.platform()) - format_dict["shell"] = "Shell: {}".format(os.getenv("SHELL", "")) + format_dict["shell"] = "Shell: {}".format(_get_parent_proc_name()) issues_url = _EXTENSIONS_ISSUES_URL if is_ext else _CLI_ISSUES_URL @@ -483,22 +436,9 @@ def _pad_string(my_str, pad_len): time_now = datetime.datetime.now() - command_logs_dir = cmd.cli_ctx.logging._get_command_log_dir(cmd.cli_ctx) - - 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) + command_log_files = _get_command_log_files(cmd.cli_ctx, time_now) + # if no command log files, return if not command_log_files: return [] @@ -512,6 +452,7 @@ def _pad_string(my_str, pad_len): max_len_dict["time_len"] = max(len(log_file.get_command_time_str()), max_len_dict["time_len"]) max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) + print("Recent commands:\n") for i, log_info in enumerate(command_log_files): idx = i + 1 @@ -521,17 +462,94 @@ def _pad_string(my_str, pad_len): duration_msg = _pad_string(log_info.get_command_duration_str() + ".", max_len_dict["duration_len"] + 1) print(" [{}] {}: {} {} {} ".format(idx, cmd_name, success_msg, time_msg, duration_msg)) + print(" [{}] None".format(len(command_log_files) + 1)) + command_log_files.append(None) + + return command_log_files + + +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, cli_ctx) + + 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 _prompt_issue(recent_command_list): + if recent_command_list: + max_idx = len(recent_command_list) + ans = -1 + help_string = 'Please choose between 1 and {}, or enter q to quit: '.format(max_idx) + + while ans < 1 or ans > max_idx: + try: + ans = prompt(_MSG_CMD_ISSUE.format(max_idx), help_string=help_string) + if ans in ["q", "quit"]: + 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 - 1]) + + 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("https://" + url) + + return True + + def handle_feedback(cmd): try: - print(MSG_INTR) + print(_MSG_INTR) recent_commands = _display_recent_commands(cmd) res = _prompt_issue(recent_commands) if res: - print(MSG_THNK) + print(_MSG_THNK) return except NoTTYException: raise CLIError('This command is interactive, however no tty is available.') diff --git a/src/command_modules/azure-cli-feedback/setup.py b/src/command_modules/azure-cli-feedback/setup.py index e4c8a694225..bc98afe3407 100644 --- a/src/command_modules/azure-cli-feedback/setup.py +++ b/src/command_modules/azure-cli-feedback/setup.py @@ -32,7 +32,6 @@ DEPENDENCIES = [ 'azure-cli-core', - 'pyperclip' ] with open('README.rst', 'r', encoding='utf-8') as f: From bdb8e9235b21b756a553f989c4c33e0c0e4e3c4f Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Mon, 25 Mar 2019 21:46:43 -0700 Subject: [PATCH 03/13] 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. --- .../azure/cli/core/azlogging.py | 8 +++--- .../azure-cli-feedback/HISTORY.rst | 5 ++++ .../cli/command_modules/feedback/custom.py | 27 ++++++++----------- .../feedback/tests/__init__.py | 0 .../feedback/tests/latest/__init__.py | 0 .../feedback/tests/latest}/test_feedback.py | 13 ++++----- .../azure-cli-feedback/setup.py | 2 +- 7 files changed, 27 insertions(+), 28 deletions(-) create mode 100644 src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/__init__.py create mode 100644 src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/__init__.py rename src/{azure-cli/azure/cli/command_modules/feedback => command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest}/test_feedback.py (98%) diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index b762a619d58..38bcbf31911 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -35,6 +35,7 @@ UNKNOWN_COMMAND = "unknown_command" CMD_LOG_LINE_PREFIX = "CMD-LOG-LINE-BEGIN" + class AzCliLogging(CLILogging): _COMMAND_METADATA_LOGGER = 'az_command_data_logger' @@ -45,7 +46,6 @@ def __init__(self, name, cli_ctx=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 @@ -56,7 +56,7 @@ def _delete_old_logs(log_dir): sorted_files = sorted(log_file_names, reverse=True) if len(sorted_files) > 25: - for file in sorted_files[10:]: + for file in sorted_files[5:]: os.remove(os.path.join(log_dir, file)) # if tab-completion and not command don't log to file. @@ -71,7 +71,6 @@ def _delete_old_logs(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 @@ -104,7 +103,6 @@ def _log_cmd_metadata_extension_info(self, extension_name, extension_version): 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, elapsed_time=None): if self.command_metadata_logger: if elapsed_time: @@ -117,12 +115,12 @@ def _end_cmd_metadata_logging(self, exit_code, elapsed_time=None): self.command_metadata_logger.removeHandler(self.command_logger_handler) self.command_metadata_logger = None + class CommandLoggerContext(object): def __init__(self, cli_ctx, module_logger): self.cli_ctx = cli_ctx self.logger = module_logger - def __enter__(self): if not self.cli_ctx: return self diff --git a/src/command_modules/azure-cli-feedback/HISTORY.rst b/src/command_modules/azure-cli-feedback/HISTORY.rst index cda8f8de1e4..a9343ed72d6 100644 --- a/src/command_modules/azure-cli-feedback/HISTORY.rst +++ b/src/command_modules/azure-cli-feedback/HISTORY.rst @@ -3,6 +3,11 @@ Release History =============== +2.2.0 ++++++ +* `az feedback` now shows metadata on recently run commands +* `az feedback` generates command and system related information to improve issue creation process + 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 bd58d677530..776e1c8b55b 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 @@ -38,7 +38,7 @@ '\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) + .format(_GET_STARTED_URL, _QUESTIONS_URL) _MSG_CMD_ISSUE = "\nEnter the number of the command you would like to create an issue for. \nEnter {} to create a generic issue. Enter q to quit: " @@ -60,7 +60,7 @@ **Command Name** `{command_name}` - + **Ran:** `{executed_command}` @@ -123,7 +123,6 @@ def __init__(self, log_file_path, time_now=None, cli_ctx=None): self.cli_ctx = None - @property def metadata_tup(self): return self._metadata @@ -199,7 +198,6 @@ def get_command_duration_str(self): return duration_str - def _get_command_metadata_from_file(self): if not self._log_file_path: return None @@ -208,7 +206,7 @@ def _get_command_metadata_from_file(self): try: _, file_name = os.path.split(self._log_file_path) - poss_date, poss_time, poss_command, poss_pid, _ = file_name.split(sep=".") + poss_date, poss_time, poss_command, poss_pid, _ = file_name.split(sep=".") 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 "Unknown" except ValueError as e: @@ -220,10 +218,8 @@ def _get_command_metadata_from_file(self): total_seconds = difference.total_seconds() - return _LogMetadataType(cmd=command, seconds_ago=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) - def _get_command_data_from_metadata(self): if not self.metadata_tup: return None @@ -249,8 +245,8 @@ def _get_command_data_from_metadata(self): 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, - level=prev_record.level, - logger=prev_record.logger, log_msg=new_log_msg) + level=prev_record.level, + logger=prev_record.logger, log_msg=new_log_msg) if prev_record: log_record_list.append(prev_record) @@ -263,7 +259,6 @@ def _get_command_data_from_metadata(self): logger.debug("Failed to open command log file %s", file_name) return None - log_data = {} # 1. Figure out whether the command was successful or not. Last log record should be the exit code try: @@ -405,7 +400,7 @@ def _get_az_version_summary(): lines = az_vers_string.splitlines() - new_lines=[] + new_lines = [] ext_line = -1 legal_line = -1 for i, line in enumerate(lines): @@ -427,13 +422,13 @@ def _get_az_version_summary(): return "\n".join(new_lines) + 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) @@ -447,10 +442,10 @@ def _pad_string(my_str, pad_len): max_len_dict = dict(name_len=0, success_len=0, time_len=0, duration_len=0) for log_file in command_log_files: - max_len_dict["name_len"] = max(len(log_file.metadata_tup.cmd), 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"]) - max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) + max_len_dict["name_len"] = max(len(log_file.metadata_tup.cmd), 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"]) + max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) print("Recent commands:\n") for i, log_info in enumerate(command_log_files): 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/azure-cli/azure/cli/command_modules/feedback/test_feedback.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py similarity index 98% rename from src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py rename to src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py index 3b7baa4ffa4..8ea40a16f10 100644 --- a/src/azure-cli/azure/cli/command_modules/feedback/test_feedback.py +++ b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/tests/latest/test_feedback.py @@ -8,7 +8,7 @@ import os import time import timeit - +import unittest from azure.cli.core.azlogging import CommandLoggerContext from azure.cli.core.extension.operations import get_extensions, add_extension, remove_extension, WheelExtension @@ -18,6 +18,8 @@ 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__) @@ -30,7 +32,6 @@ def __init__(self, *args, **kwargs): self.disable_recording = True self.is_live = True - @classmethod def setUpClass(cls): super(TestCommandLogFile, cls).setUpClass() @@ -56,7 +57,6 @@ def tearDownClass(cls): 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() @@ -107,7 +107,6 @@ def _helper_test_log_metadata_correct(self): 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) @@ -144,7 +143,6 @@ def _helper_test_log_contents_correct(self): 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): self.assertTrue("duration" in data_dict) @@ -161,7 +159,6 @@ def _helper_test_build_issue_info(self): 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)) @@ -196,3 +193,7 @@ def _run_cmd(self, command, checks=None, expect_failure=False): cli_ctx.logging._end_cmd_metadata_logging(result.exit_code, elapsed_time) 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 bc98afe3407..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', From 89dbd85ae289abb3e41611a1993045c3f3305a15 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 26 Mar 2019 12:37:12 -0700 Subject: [PATCH 04/13] Rename FileNotFoundError to OSError. Address style problems. More style fixes. Fix python 2 error. --- .github/ISSUE_TEMPLATE/Bug_report.md | 6 +- .../azure/cli/core/azlogging.py | 17 ++-- .../azure/cli/core/commands/__init__.py | 2 +- src/azure-cli-core/azure/cli/core/util.py | 2 +- src/azure-cli/azure/cli/__main__.py | 6 +- .../cli/command_modules/botservice/custom.py | 2 +- .../cli/command_modules/container/custom.py | 2 +- .../cli/command_modules/feedback/custom.py | 82 ++++++++++--------- .../feedback/tests/latest/test_feedback.py | 2 +- .../tests/verify_package_versions.py | 2 +- 10 files changed, 65 insertions(+), 58 deletions(-) diff --git a/.github/ISSUE_TEMPLATE/Bug_report.md b/.github/ISSUE_TEMPLATE/Bug_report.md index e3dfc3ac02e..46cccd63418 100644 --- a/.github/ISSUE_TEMPLATE/Bug_report.md +++ b/.github/ISSUE_TEMPLATE/Bug_report.md @@ -3,10 +3,6 @@ name: "\U0001F41BBug report" about: Create a report to help us improve --- - -#### **TIP**: `az feedback` -`az feedback` can be used to help generate some of the information requested below, such as, command, error and environment information. - **Describe the bug** A clear and concise description of what the bug is. @@ -20,4 +16,4 @@ A clear and concise description of what you expected to happen. Install Method (e.g. pip, interactive script, apt-get, Docker, MSI, edge build) / CLI version (`az --version`) / OS version / Shell Type (e.g. bash, cmd.exe, Bash on Windows) **Additional context** -Add any other context about the problem here. \ No newline at end of file +Add any other context about the problem here. diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 38bcbf31911..8d5e0a60f0e 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -46,7 +46,7 @@ def __init__(self, name, cli_ctx=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): + def get_command_log_dir(self): return self.command_log_dir @staticmethod @@ -57,7 +57,10 @@ def _delete_old_logs(log_dir): if len(sorted_files) > 25: for file in sorted_files[5:]: - os.remove(os.path.join(log_dir, file)) + 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): @@ -66,14 +69,14 @@ def _delete_old_logs(log_dir): cmd_logger = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER) - self._init_command_logfile_handlers(cmd_logger, args) + 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 + command = self.cli_ctx.invocation._rudimentary_get_command(args) or UNKNOWN_COMMAND # pylint: disable=protected-access, line-too-long command = command.replace(" ", "_") if command == "feedback": return @@ -88,7 +91,7 @@ def _init_command_logfile_handlers(self, command_metadata_logger, args): logfile_handler = logging.FileHandler(log_file_path) - lfmt = logging.Formatter(CMD_LOG_LINE_PREFIX + ' %(process)d | %(asctime)s | %(levelname)s | %(name)s | %(message)s') + 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) @@ -98,12 +101,12 @@ def _init_command_logfile_handlers(self, command_metadata_logger, args): command_metadata_logger.info("command args: %s", " ".join(args)) - def _log_cmd_metadata_extension_info(self, extension_name, extension_version): + 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, elapsed_time=None): + def end_cmd_metadata_logging(self, exit_code, elapsed_time=None): if self.command_metadata_logger: if elapsed_time: self.command_metadata_logger.info("command ran in %.3f seconds.", elapsed_time) 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 afdaf83cd04..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,7 +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.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/util.py b/src/azure-cli-core/azure/cli/core/util.py index 7eec822c025..87935d595c5 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -355,7 +355,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/azure/cli/__main__.py b/src/azure-cli/azure/cli/__main__.py index 851bf8d38f7..92f6b6fb633 100644 --- a/src/azure-cli/azure/cli/__main__.py +++ b/src/azure-cli/azure/cli/__main__.py @@ -46,7 +46,7 @@ def cli_main(cli, args): telemetry.set_success() elapsed_time = timeit.default_timer() - start_time - az_cli.logging._end_cmd_metadata_logging(exit_code, elapsed_time) + az_cli.logging.end_cmd_metadata_logging(exit_code, elapsed_time) sys.exit(exit_code) @@ -57,9 +57,9 @@ def cli_main(cli, args): exit_code = ex.code if ex.code is not None else 1 try: elapsed_time = timeit.default_timer() - start_time - az_cli.logging._end_cmd_metadata_logging(exit_code, elapsed_time) + az_cli.logging.end_cmd_metadata_logging(exit_code, elapsed_time) except NameError: - az_cli.logging._end_cmd_metadata_logging(exit_code, None) + az_cli.logging.end_cmd_metadata_logging(exit_code, None) raise ex finally: telemetry.conclude() 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/azure/cli/command_modules/feedback/custom.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py index 776e1c8b55b..97aefa4e94b 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 @@ -40,7 +40,8 @@ '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. \nEnter {} to create a generic issue. Enter q to quit: " +_MSG_CMD_ISSUE = "\nEnter the number of the command you would like to create an issue for. " \ + "\nEnter {} to create a generic issue. Enter q to quit: " _MSG_ISSUE = "Would you like to create an issue? Enter Y or N: " @@ -103,13 +104,13 @@ class CommandLogFile(object): _LogRecordType = namedtuple("LogRecord", ["p_id", "date_time", "level", "logger", "log_msg"]) - def __init__(self, log_file_path, time_now=None, cli_ctx=None): + 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 {}.", datetime.datetime, type(time_now)) + 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.", log_file_path) + raise ValueError("File {} is not an existing file.".format(log_file_path)) self._log_file_path = log_file_path @@ -206,7 +207,7 @@ def _get_command_metadata_from_file(self): try: _, file_name = os.path.split(self._log_file_path) - poss_date, poss_time, poss_command, poss_pid, _ = file_name.split(sep=".") + 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 "Unknown" except ValueError as e: @@ -218,9 +219,36 @@ def _get_command_metadata_from_file(self): total_seconds = difference.total_seconds() - return _LogMetadataType(cmd=command, seconds_ago=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) + return _LogMetadataType(cmd=command, seconds_ago=total_seconds, file_path=self._log_file_path, p_id=int(poss_pid)) # pylint: disable=line-too-long + + 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 _get_command_data_from_metadata(self): if not self.metadata_tup: return None @@ -232,33 +260,15 @@ def _get_command_data_from_metadata(self): try: with open(file_name, 'r') as log_fp: - 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, - level=prev_record.level, - logger=prev_record.logger, log_msg=new_log_msg) - - if prev_record: - log_record_list.append(prev_record) - - if not log_record_list: - logger.debug("No command log messages found in file %s", file_name) - return None - + 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 None + if not log_record_list: + logger.debug("No command log messages found in file %s", file_name) + return None + log_data = {} # 1. Figure out whether the command was successful or not. Last log record should be the exit code try: @@ -328,18 +338,17 @@ def _get_info_from_log_line(line, p_id): return None line = line[len(CMD_LOG_LINE_PREFIX):] - parts = line.split("|", maxsplit=4) + 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 - else: - parts[i] = part.strip() return CommandLogFile._LogRecordType(*parts) @@ -350,8 +359,7 @@ def _get_parent_proc_name(): parent = psutil.Process(os.getpid()).parent() if parent: return parent.name() - else: - return None + return None format_dict = {"command_name": "", "command_duration": "", "errors_string": "", @@ -464,14 +472,14 @@ def _pad_string(my_str, pad_len): def _get_command_log_files(cli_ctx, time_now=None): - command_logs_dir = cli_ctx.logging._get_command_log_dir() + 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, cli_ctx) + cmd_log_file = CommandLogFile(file_path, time_now) if cmd_log_file.metadata_tup: command_log_files.append(cmd_log_file) 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 index 8ea40a16f10..79482074d2f 100644 --- 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 @@ -190,7 +190,7 @@ def _run_cmd(self, command, checks=None, expect_failure=False): logger.error("There was an error during execution.") elapsed_time = timeit.default_timer() - start_time - cli_ctx.logging._end_cmd_metadata_logging(result.exit_code, elapsed_time) + cli_ctx.logging.end_cmd_metadata_logging(result.exit_code, elapsed_time) return result 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) From a08113b9a8626229891b9f0b9648e8f10073871d Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 26 Mar 2019 16:23:28 -0700 Subject: [PATCH 05/13] Update command logger context. Ensure that failed show commands log to command metadata logs. Minor changes. --- .github/ISSUE_TEMPLATE/Bug_report.md | 3 ++- src/azure-cli-core/azure/cli/core/azlogging.py | 18 ++++++------------ .../azure/cli/core/commands/arm.py | 6 ++++-- src/azure-cli-core/azure/cli/core/util.py | 2 +- .../feedback/tests/latest/test_feedback.py | 2 +- 5 files changed, 14 insertions(+), 17 deletions(-) diff --git a/.github/ISSUE_TEMPLATE/Bug_report.md b/.github/ISSUE_TEMPLATE/Bug_report.md index 46cccd63418..4a9e2f3a1bf 100644 --- a/.github/ISSUE_TEMPLATE/Bug_report.md +++ b/.github/ISSUE_TEMPLATE/Bug_report.md @@ -3,7 +3,8 @@ name: "\U0001F41BBug report" about: Create a report to help us improve --- -**Describe the bug** + +q**Describe the bug** A clear and concise description of what the bug is. **To Reproduce** diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 8d5e0a60f0e..fcbf079ac85 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -120,21 +120,15 @@ def end_cmd_metadata_logging(self, exit_code, elapsed_time=None): class CommandLoggerContext(object): - def __init__(self, cli_ctx, module_logger): - self.cli_ctx = cli_ctx + 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 not self.cli_ctx: - return self - hdlr = self.cli_ctx.logging.command_logger_handler - if hdlr: - self.logger.addHandler(hdlr) # add command metadata handler + if self.hdlr: + self.logger.addHandler(self.hdlr) # add command metadata handler return self def __exit__(self, exc_type, exc_val, exc_tb): - if not self.cli_ctx: - return - hdlr = self.cli_ctx.logging.command_logger_handler - if hdlr: - self.logger.removeHandler(hdlr) + if self.hdlr: + self.logger.removeHandler(self.hdlr) 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/util.py b/src/azure-cli-core/azure/cli/core/util.py index 87935d595c5..b2d4a08cda4 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -26,7 +26,7 @@ def handle_exception(ex, cli_ctx=None): from msrest.exceptions import HttpOperationError from azure.cli.core.azlogging import CommandLoggerContext - with CommandLoggerContext(cli_ctx, logger): + with CommandLoggerContext(logger): if isinstance(ex, (CLIError, CloudError)): logger.error(ex.args[0]) 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 index 79482074d2f..496c0566bd0 100644 --- 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 @@ -185,7 +185,7 @@ def _run_cmd(self, command, checks=None, expect_failure=False): 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 in testsdk / patches - with CommandLoggerContext(cli_ctx, logger): + with CommandLoggerContext(logger): if result.exit_code != 0: logger.error("There was an error during execution.") From 0598b71c7aa07269a55776bfc86ec48917fb163d Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Mon, 1 Apr 2019 16:35:30 -0700 Subject: [PATCH 06/13] Fix docker build issue. Properly detect powershell. Address some feedback. --- .github/ISSUE_TEMPLATE/Bug_report.md | 2 +- Dockerfile | 2 +- src/azure-cli-core/azure/cli/core/__init__.py | 2 +- src/azure-cli-core/azure/cli/core/azlogging.py | 15 +++++++++++---- src/azure-cli-core/azure/cli/core/util.py | 14 ++------------ src/azure-cli-core/setup.py | 4 ++-- .../azure/cli/command_modules/feedback/custom.py | 11 +++++++---- .../feedback/tests/latest/test_feedback.py | 10 ++-------- 8 files changed, 27 insertions(+), 33 deletions(-) diff --git a/.github/ISSUE_TEMPLATE/Bug_report.md b/.github/ISSUE_TEMPLATE/Bug_report.md index 4a9e2f3a1bf..ec83fde65f6 100644 --- a/.github/ISSUE_TEMPLATE/Bug_report.md +++ b/.github/ISSUE_TEMPLATE/Bug_report.md @@ -4,7 +4,7 @@ about: Create a report to help us improve --- -q**Describe the bug** +**Describe the bug** A clear and concise description of what the bug is. **To Reproduce** 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 fcbf079ac85..2f3df057b8d 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -32,8 +32,8 @@ 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" +_UNKNOWN_COMMAND = "unknown_command" +_CMD_LOG_LINE_PREFIX = "CMD-LOG-LINE-BEGIN" class AzCliLogging(CLILogging): @@ -52,9 +52,16 @@ def get_command_log_dir(self): @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: @@ -76,7 +83,7 @@ def _delete_old_logs(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 = self.cli_ctx.invocation._rudimentary_get_command(args) or _UNKNOWN_COMMAND # pylint: disable=protected-access, line-too-long command = command.replace(" ", "_") if command == "feedback": return @@ -91,7 +98,7 @@ def _init_command_logfile_handlers(self, command_metadata_logger, args): 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 + 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) diff --git a/src/azure-cli-core/azure/cli/core/util.py b/src/azure-cli-core/azure/cli/core/util.py index b2d4a08cda4..1980f698c85 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -20,7 +20,7 @@ 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 @@ -51,19 +51,9 @@ def handle_exception(ex, cli_ctx=None): logger.error(ex) return 1 - # 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) + logger.warning("\nTo open an issue, please run: 'az feedback'") return 1 diff --git a/src/azure-cli-core/setup.py b/src/azure-cli-core/setup.py index 7c531bb72f3..f15aa66973b 100644 --- a/src/azure-cli-core/setup.py +++ b/src/azure-cli-core/setup.py @@ -73,8 +73,8 @@ 'tabulate>=0.7.7', 'wheel==0.30.0', 'azure-mgmt-resource==2.1.0' - 'pyperclip==1.7.0', - 'psutil==5.6.1' + 'pyperclip>=1.7.0', + 'psutil>=5.6.1' ] with open('README.rst', 'r', encoding='utf-8') as f: 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 97aefa4e94b..b3bdde86976 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 @@ -16,7 +16,7 @@ from knack.util import CLIError 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.azlogging import _UNKNOWN_COMMAND, _CMD_LOG_LINE_PREFIX from azure.cli.core.util import open_page_in_browser import pyperclip @@ -209,7 +209,7 @@ def _get_command_metadata_from_file(self): _, 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 "Unknown" + command = "az " + poss_command.replace("_", " ") if poss_command != _UNKNOWN_COMMAND else "Unknown" except ValueError as e: logger.debug("Could not load metadata from file name %s.", self._log_file_path) logger.debug(e) @@ -334,10 +334,10 @@ def _get_info_from_log_line(line, p_id): :return: returned parsed line information or None """ - if not line.startswith(CMD_LOG_LINE_PREFIX): + if not line.startswith(_CMD_LOG_LINE_PREFIX): return None - line = line[len(CMD_LOG_LINE_PREFIX):] + line = line[len(_CMD_LOG_LINE_PREFIX):] parts = line.split("|", 4) if len(parts) != 5: # there must be 5 items @@ -358,6 +358,9 @@ def _get_parent_proc_name(): import psutil parent = psutil.Process(os.getpid()).parent() if parent: + # powershell.exe launches cmd.exe to launch the cli. + if parent.parent() and parent.name().lower().startswith("powershell"): + return parent.parent().name() return parent.name() return None 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 index 496c0566bd0..43637a32fa4 100644 --- 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 @@ -75,13 +75,6 @@ def setUp(self): # 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): - - for file in os.listdir(self.temp_command_log_dir): - with open(os.path.join(self.temp_command_log_dir, file), "r") as f: - print("File contents:\n%s", f.read()) - - print("temp dir contents: %s", os.listdir(self.temp_command_log_dir)) - self._helper_test_log_metadata_correct() self._helper_test_log_contents_correct() self._helper_test_build_issue_info() @@ -184,7 +177,8 @@ def _run_cmd(self, command, checks=None, expect_failure=False): 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 in testsdk / patches + # 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.") From a840d124289596c81522e3cfc674c11acebc8916 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 2 Apr 2019 13:02:57 -0700 Subject: [PATCH 07/13] Fixed log cleanup bug. Remove sensitive information from command_args. Minor updates. Fix bug where command_data_dict could be None. --- .../azure/cli/core/azlogging.py | 62 +++++++++- src/azure-cli-core/azure/cli/core/parser.py | 7 +- .../azure-cli-feedback/HISTORY.rst | 3 +- .../cli/command_modules/feedback/custom.py | 114 ++++++++++-------- .../feedback/tests/latest/test_feedback.py | 10 +- 5 files changed, 136 insertions(+), 60 deletions(-) diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 2f3df057b8d..5ec3743cf82 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -63,7 +63,7 @@ def _delete_old_logs(log_dir): # 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:]: + for file in sorted_files[-5:]: try: os.remove(os.path.join(log_dir, file)) except OSError: # FileNotFoundError introduced in Python 3 @@ -82,17 +82,18 @@ def _delete_old_logs(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 = command.replace(" ", "_") - if command == "feedback": + 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, os.getpid(), "log") + log_name = "{}.{}.{}.{}.{}".format(date_str, time_str, command_str, os.getpid(), "log") log_file_path = os.path.join(self.command_log_dir, log_name) @@ -106,8 +107,61 @@ def _init_command_logfile_handlers(self, command_metadata_logger, args): 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) 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/command_modules/azure-cli-feedback/HISTORY.rst b/src/command_modules/azure-cli-feedback/HISTORY.rst index a9343ed72d6..0bdb8b4179e 100644 --- a/src/command_modules/azure-cli-feedback/HISTORY.rst +++ b/src/command_modules/azure-cli-feedback/HISTORY.rst @@ -6,7 +6,8 @@ Release History 2.2.0 +++++ * `az feedback` now shows metadata on recently run commands -* `az feedback` generates command and system related information to improve issue creation process +* `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 +++++ 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 b3bdde86976..a222758e3ac 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 @@ -40,8 +40,7 @@ '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. " \ - "\nEnter {} to create a generic issue. Enter q to quit: " +_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: " @@ -55,17 +54,13 @@ _ISSUES_TEMPLATE = """ -### **This autogenerated template contains command parameters. Please review and remove sensitive information, if necessary** +### **This is an autogenerated template. Please review.** ## Describe the bug **Command Name** `{command_name}` -**Ran:** - `{executed_command}` - - **Command Duration** {command_duration} @@ -74,6 +69,7 @@ ## To Reproduce: +**Run:** `{executed_command}` ## Expected behavior @@ -96,13 +92,19 @@ ## 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): @@ -134,11 +136,27 @@ def command_data_dict(self): self._data = self._get_command_data_from_metadata() return self._data - def get_command_name(self): + def get_command_name_str(self): if not self.metadata_tup: return "" - return self.metadata_tup.cmd + try: + return self._command_name # attempt to return cached result + except AttributeError: + pass + + args = self.command_data_dict.get("command_args", "") + + if self.metadata_tup.cmd != self.UNKNOWN_CMD: + self._command_name = self.metadata_tup.cmd + else: + self._command_name = self.UNKNOWN_CMD + if args: + command_args = args if len(args) < 20 else args[:15] + " ..." + 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: @@ -209,7 +227,7 @@ def _get_command_metadata_from_file(self): _, 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 "Unknown" + 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) @@ -250,7 +268,7 @@ def _get_log_record_list(log_fp, p_id): return log_record_list if not self.metadata_tup: - return None + return {} _EXT_NAME_PREFIX = "extension name:" _EXT_VERS_PREFIX = "extension version:" @@ -263,11 +281,11 @@ def _get_log_record_list(log_fp, p_id): 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 None + return {} if not log_record_list: logger.debug("No command log messages found in file %s", file_name) - return None + return {} log_data = {} # 1. Figure out whether the command was successful or not. Last log record should be the exit code @@ -320,7 +338,7 @@ def _get_log_record_list(log_fp, p_id): except (IndexError, ValueError): logger.debug("Couldn't get command args from command log %s.", file_name) - return log_data or None + return log_data @staticmethod def _get_info_from_log_line(line, p_id): @@ -396,6 +414,7 @@ def _get_parent_proc_name(): format_dict["system_name"] = "OS/System Name: {}".format(platform.system()) format_dict["platform"] = "Platform Name: {}".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 @@ -434,6 +453,23 @@ def _get_az_version_summary(): 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: @@ -453,54 +489,37 @@ def _pad_string(my_str, pad_len): max_len_dict = dict(name_len=0, success_len=0, time_len=0, duration_len=0) for log_file in command_log_files: - max_len_dict["name_len"] = max(len(log_file.metadata_tup.cmd), max_len_dict["name_len"]) + 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"]) max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) print("Recent commands:\n") + command_log_files = [None] + command_log_files for i, log_info in enumerate(command_log_files): - idx = i + 1 - - cmd_name = _pad_string(log_info.metadata_tup.cmd, 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) - duration_msg = _pad_string(log_info.get_command_duration_str() + ".", max_len_dict["duration_len"] + 1) - print(" [{}] {}: {} {} {} ".format(idx, cmd_name, success_msg, time_msg, duration_msg)) - - print(" [{}] None".format(len(command_log_files) + 1)) - command_log_files.append(None) - - return command_log_files - - -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) + if log_info is None: + print(" [{}] {}".format(i, "create a generic issue.")) else: - logger.debug("%s is an invalid command log file.", file_path) + 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) + duration_msg = _pad_string(log_info.get_command_duration_str() + ".", max_len_dict["duration_len"] + 1) + print(" [{}] {}: {} {} {} ".format(i, cmd_name, success_msg, time_msg, duration_msg)) + return command_log_files def _prompt_issue(recent_command_list): if recent_command_list: - max_idx = len(recent_command_list) + max_idx = len(recent_command_list) - 1 ans = -1 - help_string = 'Please choose between 1 and {}, or enter q to quit: '.format(max_idx) + help_string = 'Please choose between 0 and {}, or enter q to quit: '.format(max_idx) - while ans < 1 or ans > max_idx: + while ans < 0 or ans > max_idx: try: ans = prompt(_MSG_CMD_ISSUE.format(max_idx), help_string=help_string) - if ans in ["q", "quit"]: + if ans.lower() in ["q", "quit"]: + ans = ans.lower() break ans = int(ans) except ValueError: @@ -530,9 +549,8 @@ def _prompt_issue(recent_command_list): return False if ans == 0: prefix, body, url = _build_issue_info_tup() - else: - prefix, body, url = _build_issue_info_tup(recent_command_list[ans - 1]) + prefix, body, url = _build_issue_info_tup(recent_command_list[ans]) print(prefix) 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 index 43637a32fa4..db621bbe5ce 100644 --- 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 @@ -93,7 +93,7 @@ def _helper_test_log_metadata_correct(self): 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()) + 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) @@ -118,18 +118,18 @@ def _helper_test_log_contents_correct(self): 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 alias") + 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 alias") + 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 foo123 -c bar123") + self.assertEqual(data_dict["command_args"], "alias create -n {} -c {}") # check successful extension command data_dict = command_log_files[3].command_data_dict @@ -160,7 +160,7 @@ def _helper_test_build_issue_info(self): 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() in issue_body) + self.assertTrue(log_file.get_command_name_str() in issue_body) self.assertTrue(log_file.get_command_duration_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) From 045eede90dacff75c33f5600d1c4e764d2803f11 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 2 Apr 2019 14:45:20 -0700 Subject: [PATCH 08/13] Detect powershell. Take 2. --- .../azure/cli/command_modules/feedback/custom.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) 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 a222758e3ac..3d0b3edfff1 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 @@ -377,8 +377,10 @@ def _get_parent_proc_name(): parent = psutil.Process(os.getpid()).parent() if parent: # powershell.exe launches cmd.exe to launch the cli. - if parent.parent() and parent.name().lower().startswith("powershell"): - return parent.parent().name() + 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 From 4429056097a92ee6749280a8ce32e443059968a6 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 2 Apr 2019 15:36:34 -0700 Subject: [PATCH 09/13] Fix setup.py --- src/azure-cli-core/setup.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/azure-cli-core/setup.py b/src/azure-cli-core/setup.py index f15aa66973b..8f852bded38 100644 --- a/src/azure-cli-core/setup.py +++ b/src/azure-cli-core/setup.py @@ -72,7 +72,7 @@ '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' ] From 74a8da0840d03b84907d64bc607c37b074ee335d Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Tue, 2 Apr 2019 17:01:08 -0700 Subject: [PATCH 10/13] Style fix. --- .../azure/cli/command_modules/feedback/custom.py | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) 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 3d0b3edfff1..5a0a1fbc31a 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 @@ -114,6 +114,7 @@ def __init__(self, log_file_path, time_now=None): 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: @@ -124,8 +125,6 @@ def __init__(self, log_file_path, time_now=None): self._metadata = self._get_command_metadata_from_file() self._data = None - self.cli_ctx = None - @property def metadata_tup(self): return self._metadata @@ -137,14 +136,12 @@ def command_data_dict(self): 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 "" - try: - return self._command_name # attempt to return cached result - except AttributeError: - pass - args = self.command_data_dict.get("command_args", "") if self.metadata_tup.cmd != self.UNKNOWN_CMD: From a495d80a51b2c35dee70ebe867a0ea20bafe46ca Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Wed, 3 Apr 2019 18:39:45 -0700 Subject: [PATCH 11/13] az feedback no longer shows command duration. Other stylistic updates. --- .../azure/cli/core/azlogging.py | 4 +- src/azure-cli/azure/cli/__main__.py | 14 +- .../cli/command_modules/feedback/custom.py | 124 +++++++----------- .../feedback/tests/latest/test_feedback.py | 8 +- 4 files changed, 62 insertions(+), 88 deletions(-) diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index 5ec3743cf82..0259b6ef0f5 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -167,10 +167,8 @@ def log_cmd_metadata_extension_info(self, extension_name, extension_version): 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, elapsed_time=None): + def end_cmd_metadata_logging(self, exit_code): if self.command_metadata_logger: - if elapsed_time: - self.command_metadata_logger.info("command ran in %.3f seconds.", elapsed_time) self.command_metadata_logger.info("exit code: %s", exit_code) # We have finished metadata logging, remove handler and set command_metadata_handler to None. diff --git a/src/azure-cli/azure/cli/__main__.py b/src/azure-cli/azure/cli/__main__.py index 92f6b6fb633..f168e7d1871 100644 --- a/src/azure-cli/azure/cli/__main__.py +++ b/src/azure-cli/azure/cli/__main__.py @@ -46,8 +46,8 @@ def cli_main(cli, args): telemetry.set_success() elapsed_time = timeit.default_timer() - start_time - az_cli.logging.end_cmd_metadata_logging(exit_code, elapsed_time) + az_cli.logging.end_cmd_metadata_logging(exit_code) sys.exit(exit_code) except KeyboardInterrupt: @@ -55,11 +55,19 @@ def cli_main(cli, args): 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 - az_cli.logging.end_cmd_metadata_logging(exit_code, elapsed_time) except NameError: - az_cli.logging.end_cmd_metadata_logging(exit_code, None) + 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-feedback/azure/cli/command_modules/feedback/custom.py b/src/command_modules/azure-cli-feedback/azure/cli/command_modules/feedback/custom.py index 5a0a1fbc31a..28b5993d1b1 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 @@ -9,6 +9,11 @@ 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 @@ -54,42 +59,35 @@ _ISSUES_TEMPLATE = """ -### **This is an autogenerated template. Please review.** +### **This is an autogenerated template. Please review and update as needed.** ## Describe the bug **Command Name** - `{command_name}` - -**Command Duration** - {command_duration} +`{command_name}` **Errors:** {errors_string} ## To Reproduce: +Steps to reproduce the behavior. Note: Command arguments have been redacted. -**Run:** `{executed_command}` +- `Fill in additional info here` +- `Run: {executed_command}` -## Expected behavior +## Expected Behavior A clear and concise description of what you expected to happen. -## Environment summary - -**Python Info** - {python_info} - -**System Info** - {system_name} - {platform} - {shell} - -**CLI Version** +## Environment Summary +``` +{platform} +{python_info} +{shell} {cli_version} - -## Additional context +``` +## Additional Context Add any other context about the problem here. @@ -146,10 +144,13 @@ def get_command_name_str(self): 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) < 20 else args[:15] + " ..." + 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) @@ -190,30 +191,6 @@ def get_command_time_str(self): return time_str - def get_command_duration_str(self): - if not self.command_data_dict: - return "" - - duration = float(self.command_data_dict.get("duration", -1)) - - if duration < 0: - return "" - - if duration > _ONE_HR_IN_SECS: - hrs, secs = divmod(duration, _ONE_HR_IN_SECS) - hrs = math.floor(hrs) - mins = math.floor(secs / _ONE_MIN_IN_SECS) - duration_str = "Duration: {} hrs {:02} mins".format(hrs, mins) - elif duration > _ONE_MIN_IN_SECS: - mins, secs = divmod(duration, _ONE_MIN_IN_SECS) - mins = math.floor(mins) - secs = math.floor(secs) - duration_str = "Duration: {} mins {:02} secs".format(mins, secs) - else: - duration_str = "Duration: {:.2f} secs".format(duration) - - return duration_str - def _get_command_metadata_from_file(self): if not self._log_file_path: return None @@ -295,22 +272,8 @@ def _get_log_record_list(log_fp, p_id): except (IndexError, ValueError): logger.debug("Couldn't extract exit code from command log %s.", file_name) - # 2. Get the duration of the command. Duration is printed before last log record if any - try: - command_duration_msg = log_record_list[-2].log_msg.strip() - if command_duration_msg.startswith("command ran in"): - words = command_duration_msg.split() - for word in words: - try: - log_data["duration"] = float(word) - break - except ValueError: - continue - except IndexError: - logger.debug("Couldn't extract duration from command log %s.", file_name) - - # 3. If there are any errors, this is a failed command. Log the errors - # 4. Also get extension information. + # 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": @@ -324,10 +287,10 @@ def _get_log_record_list(log_fp, p_id): elif poss_ext_msg.startswith(_EXT_VERS_PREFIX): log_data["extension_version"] = poss_ext_msg[len(_EXT_VERS_PREFIX):].strip() - # 5. Get command args. from first record + # 4. Get command args string. from first record try: - command_args_msg = log_record_list[0].log_msg.strip().lower() - if command_args_msg.startswith("command args:"): + 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: @@ -381,8 +344,7 @@ def _get_parent_proc_name(): return parent.name() return None - format_dict = {"command_name": "", - "command_duration": "", "errors_string": "", + format_dict = {"command_name": "", "errors_string": "", "executed_command": ""} is_ext = False @@ -402,7 +364,15 @@ def _get_parent_proc_name(): extension_info = "\nExtension Name: {}. Version: {}.".format(extension_name, extension_version) is_ext = True - format_dict["command_duration"] = command_log_file.get_command_duration_str() + 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 @@ -410,14 +380,20 @@ def _get_parent_proc_name(): # Get other system information format_dict["cli_version"] = _get_az_version_summary() format_dict["python_info"] = "Python {}".format(platform.python_version()) - format_dict["system_name"] = "OS/System Name: {}".format(platform.system()) - format_dict["platform"] = "Platform Name: {}".format(platform.platform()) + 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 - return _ISSUES_TEMPLATE_PREFIX.format(issues_url), _ISSUES_TEMPLATE.format(**format_dict), 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(): @@ -485,13 +461,12 @@ def _pad_string(my_str, pad_len): command_log_files = command_log_files[-9:] - max_len_dict = dict(name_len=0, success_len=0, time_len=0, duration_len=0) + 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"]) - max_len_dict["duration_len"] = max(len(log_file.get_command_duration_str()), max_len_dict["duration_len"]) print("Recent commands:\n") command_log_files = [None] + command_log_files @@ -502,8 +477,7 @@ def _pad_string(my_str, pad_len): 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) - duration_msg = _pad_string(log_info.get_command_duration_str() + ".", max_len_dict["duration_len"] + 1) - print(" [{}] {}: {} {} {} ".format(i, cmd_name, success_msg, time_msg, duration_msg)) + print(" [{}] {}: {} {}".format(i, cmd_name, success_msg, time_msg)) return command_log_files @@ -560,7 +534,7 @@ def _prompt_issue(recent_command_list): logger.debug(ex) logger.info(body) - open_page_in_browser("https://" + url) + open_page_in_browser(url) return True 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 index db621bbe5ce..fafad62cda6 100644 --- 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 @@ -7,7 +7,6 @@ import logging import os import time -import timeit import unittest from azure.cli.core.azlogging import CommandLoggerContext @@ -138,7 +137,6 @@ def _helper_test_log_contents_correct(self): ext_version = self.cmd("az extension show -n alias").get_output_in_json()["version"] for i, log_file in enumerate(command_log_files): - self.assertTrue("duration" in data_dict) if i >= 2: self.assertEqual(data_dict["extension_name"], "alias") self.assertEqual(data_dict["extension_version"], ext_version) @@ -161,7 +159,6 @@ def _helper_test_build_issue_info(self): for log_file, issue_body in items: self.assertTrue(log_file.get_command_name_str() in issue_body) - self.assertTrue(log_file.get_command_duration_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) @@ -170,8 +167,6 @@ def _ext_installed(ext): return ext in [ext.name for ext in get_extensions()] def _run_cmd(self, command, checks=None, expect_failure=False): - start_time = timeit.default_timer() - cli_ctx = get_dummy_cli() cli_ctx.logging.command_log_dir = self.temp_command_log_dir @@ -183,8 +178,7 @@ def _run_cmd(self, command, checks=None, expect_failure=False): if result.exit_code != 0: logger.error("There was an error during execution.") - elapsed_time = timeit.default_timer() - start_time - cli_ctx.logging.end_cmd_metadata_logging(result.exit_code, elapsed_time) + cli_ctx.logging.end_cmd_metadata_logging(result.exit_code) return result From ae8829ba8df33890666468a753bd5ecc39955e2e Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Wed, 3 Apr 2019 19:23:41 -0700 Subject: [PATCH 12/13] Style fix. --- .../azure/cli/command_modules/feedback/custom.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 28b5993d1b1..51ad1ec8870 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 @@ -390,7 +390,7 @@ def _get_parent_proc_name(): 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`"}) + 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 From 91f8623fa7b737b446208780b84873f56055e636 Mon Sep 17 00:00:00 2001 From: Oluwatosin Adewale Date: Thu, 4 Apr 2019 08:42:27 -0700 Subject: [PATCH 13/13] Pylint, line too long. --- .../azure/cli/command_modules/feedback/custom.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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 51ad1ec8870..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 @@ -390,7 +390,8 @@ def _get_parent_proc_name(): 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`"}) + 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