-
Notifications
You must be signed in to change notification settings - Fork 2.9k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[wip] az feedback #8829
[wip] az feedback #8829
Changes from 9 commits
26a3ddf
3019d1c
bdb8e92
89dbd85
a08113b
0598b71
a840d12
045eede
4429056
74a8da0
a495d80
ae8829b
91f8623
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -23,11 +23,173 @@ | |
|
||
""" | ||
|
||
from knack.log import CLILogging | ||
import os | ||
import logging | ||
import datetime | ||
|
||
CLI_LOGGER_NAME = 'az' | ||
from knack.log import CLILogging, get_logger | ||
from knack.util import ensure_dir | ||
from azure.cli.core.commands.events import EVENT_INVOKER_PRE_CMD_TBL_TRUNCATE | ||
|
||
|
||
_UNKNOWN_COMMAND = "unknown_command" | ||
_CMD_LOG_LINE_PREFIX = "CMD-LOG-LINE-BEGIN" | ||
|
||
|
||
class AzCliLogging(CLILogging): | ||
_COMMAND_METADATA_LOGGER = 'az_command_data_logger' | ||
|
||
def __init__(self, name, cli_ctx=None): | ||
super(AzCliLogging, self).__init__(name, cli_ctx) | ||
self.command_log_dir = os.path.join(cli_ctx.config.config_dir, 'commands') | ||
self.command_logger_handler = None | ||
self.command_metadata_logger = None | ||
self.cli_ctx.register_event(EVENT_INVOKER_PRE_CMD_TBL_TRUNCATE, AzCliLogging.init_command_file_logging) | ||
|
||
def get_command_log_dir(self): | ||
return self.command_log_dir | ||
|
||
@staticmethod | ||
def init_command_file_logging(cli_ctx, **kwargs): | ||
def _delete_old_logs(log_dir): | ||
""" | ||
Periodically delete the 5 oldest command log files, ensuring that only the history of the last | ||
25 commands (or less) are kept. | ||
""" | ||
|
||
# get log file names and sort them from newest to oldest file. | ||
log_file_names = [file for file in os.listdir(log_dir) if file.endswith(".log")] | ||
sorted_files = sorted(log_file_names, reverse=True) | ||
|
||
# if we have too many files, delete the 5 last / oldest command log files. | ||
if len(sorted_files) > 25: | ||
for file in sorted_files[-5:]: | ||
try: | ||
os.remove(os.path.join(log_dir, file)) | ||
except OSError: # FileNotFoundError introduced in Python 3 | ||
continue | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. So this... keeps the number of files between 5 and 25? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. keeps files between 0 and 20 / 25. I could rename the variable to clarify that the files are in reverse order. I wanted to make removing the files an infrequent operation that removes a bulk of unnecessary commands. Maybe I could fine tune this. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Add comments so we understand the logic. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. @tjprescott, you were right, there was a bug. I have fixed it. |
||
|
||
# if tab-completion and not command don't log to file. | ||
if not cli_ctx.data.get('completer_active', False): | ||
self = cli_ctx.logging | ||
args = kwargs['args'] | ||
|
||
cmd_logger = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER) | ||
|
||
self._init_command_logfile_handlers(cmd_logger, args) # pylint: disable=protected-access | ||
get_logger(__name__).debug("metadata file logging enabled - writing logs to '%s'.", self.command_log_dir) | ||
|
||
_delete_old_logs(self.command_log_dir) | ||
|
||
def _init_command_logfile_handlers(self, command_metadata_logger, args): | ||
|
||
ensure_dir(self.command_log_dir) | ||
command = self.cli_ctx.invocation._rudimentary_get_command(args) or _UNKNOWN_COMMAND # pylint: disable=protected-access, line-too-long | ||
command_str = command.replace(" ", "_") | ||
if command_str.lower() == "feedback": | ||
return | ||
|
||
date_str = str(datetime.datetime.now().date()) | ||
time = datetime.datetime.now().time() | ||
time_str = "{:02}-{:02}-{:02}".format(time.hour, time.minute, time.second) | ||
|
||
log_name = "{}.{}.{}.{}.{}".format(date_str, time_str, command_str, os.getpid(), "log") | ||
|
||
log_file_path = os.path.join(self.command_log_dir, log_name) | ||
|
||
logfile_handler = logging.FileHandler(log_file_path) | ||
|
||
lfmt = logging.Formatter(_CMD_LOG_LINE_PREFIX + ' %(process)d | %(asctime)s | %(levelname)s | %(name)s | %(message)s') # pylint: disable=line-too-long | ||
logfile_handler.setFormatter(lfmt) | ||
logfile_handler.setLevel(logging.DEBUG) | ||
command_metadata_logger.addHandler(logfile_handler) | ||
|
||
self.command_logger_handler = logfile_handler | ||
self.command_metadata_logger = command_metadata_logger | ||
|
||
args = AzCliLogging._get_clean_args(command if command != _UNKNOWN_COMMAND else None, args) | ||
command_metadata_logger.info("command args: %s", " ".join(args)) | ||
|
||
@staticmethod | ||
def _get_clean_args(command, args): # TODO: add test for this function | ||
# based on AzCliCommandInvoker._extract_parameter_names(args) | ||
# note: name start with more than 2 '-' will be treated as value e.g. certs in PEM format | ||
|
||
# if no command provided, try to guess the intended command. This does not work for positionals | ||
if not command: | ||
command_list = [] | ||
for arg in args: | ||
if arg.startswith('-') and not arg.startswith('---') and len(arg) > 1: | ||
break | ||
command_list.append(arg) | ||
command = " ".join(command_list) | ||
|
||
command = command.split() | ||
cleaned_args = [] | ||
placeholder = "{}" | ||
for i, arg in enumerate(args): | ||
# while this token a part of the command add it. | ||
# Note: if 'command' is none first positional would be captured. | ||
if i < len(command): | ||
cleaned_args.append(arg) | ||
continue | ||
|
||
# if valid optional name | ||
if arg.startswith('-') and not arg.startswith('---') and len(arg) > 1: | ||
|
||
# if short option with or without "=" | ||
if not arg.startswith("--"): | ||
opt = arg[:2] # get opt | ||
|
||
opt = opt + "=" if len(arg) > 2 and arg[2] == "=" else opt # append '=' if necessary | ||
opt = opt + placeholder if (len(arg) > 2 and arg[2] != "=") or len( | ||
arg) > 3 else opt # append placeholder if argument with optional | ||
cleaned_args.append(opt) | ||
continue | ||
|
||
# otherwise if long option with "=" | ||
if "=" in arg: | ||
opt, _ = arg.split('=', 1) | ||
cleaned_args.append(opt + "=" + placeholder) | ||
continue | ||
|
||
cleaned_args.append(arg) | ||
continue | ||
|
||
# else if positional or optional argument / value | ||
else: | ||
cleaned_args.append(placeholder) | ||
|
||
return cleaned_args | ||
|
||
def log_cmd_metadata_extension_info(self, extension_name, extension_version): | ||
if self.command_metadata_logger: | ||
self.command_metadata_logger.info("extension name: %s", extension_name) | ||
self.command_metadata_logger.info("extension version: %s", extension_version) | ||
|
||
def end_cmd_metadata_logging(self, exit_code, 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) | ||
|
||
# We have finished metadata logging, remove handler and set command_metadata_handler to None. | ||
# crucial to remove handler as in python logger objects are shared which can affect testing of this logger | ||
# we do not want duplicate handlers to be added in subsequent calls of _init_command_logfile_handlers | ||
self.command_metadata_logger.removeHandler(self.command_logger_handler) | ||
self.command_metadata_logger = None | ||
|
||
|
||
class CommandLoggerContext(object): | ||
def __init__(self, module_logger): | ||
self.logger = module_logger | ||
self.hdlr = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER) # pylint: disable=protected-access | ||
|
||
def __enter__(self): | ||
if self.hdlr: | ||
self.logger.addHandler(self.hdlr) # add command metadata handler | ||
return self | ||
|
||
pass | ||
def __exit__(self, exc_type, exc_val, exc_tb): | ||
if self.hdlr: | ||
self.logger.removeHandler(self.hdlr) |
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -20,48 +20,42 @@ | |
COMPONENT_PREFIX = 'azure-cli-' | ||
|
||
|
||
def handle_exception(ex, cli_ctx=None): | ||
def handle_exception(ex): | ||
# For error code, follow guidelines at https://docs.python.org/2/library/sys.html#sys.exit, | ||
from msrestazure.azure_exceptions import CloudError | ||
from msrest.exceptions import HttpOperationError | ||
if isinstance(ex, (CLIError, CloudError)): | ||
logger.error(ex.args[0]) | ||
return ex.args[1] if len(ex.args) >= 2 else 1 | ||
if isinstance(ex, KeyboardInterrupt): | ||
return 1 | ||
if isinstance(ex, HttpOperationError): | ||
try: | ||
response_dict = json.loads(ex.response.text) | ||
error = response_dict['error'] | ||
|
||
# ARM should use ODATA v4. So should try this first. | ||
# http://docs.oasis-open.org/odata/odata-json-format/v4.0/os/odata-json-format-v4.0-os.html#_Toc372793091 | ||
if isinstance(error, dict): | ||
code = "{} - ".format(error.get('code', 'Unknown Code')) | ||
message = error.get('message', ex) | ||
logger.error("%s%s", code, message) | ||
else: | ||
logger.error(error) | ||
from azure.cli.core.azlogging import CommandLoggerContext | ||
|
||
except (ValueError, KeyError): | ||
logger.error(ex) | ||
return 1 | ||
with CommandLoggerContext(logger): | ||
|
||
# Otherwise, unhandled exception. Direct users to create an issue. | ||
is_extension = False | ||
if cli_ctx: | ||
try: | ||
if cli_ctx.invocation.data['command_extension_name']: | ||
is_extension = True | ||
except (AttributeError, KeyError): | ||
pass | ||
|
||
issue_url = "https://aka.ms/azcli/ext/issues" if is_extension else "https://aka.ms/azcli/issues" | ||
logger.error("The command failed with an unexpected error. Here is the traceback:\n") | ||
logger.exception(ex) | ||
logger.warning("\nTo open an issue, please visit: %s", issue_url) | ||
if isinstance(ex, (CLIError, CloudError)): | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. this section should be exactly the same, except that we use the command logger context and we no longer print the issues url but direct users to use az feedback. |
||
logger.error(ex.args[0]) | ||
return ex.args[1] if len(ex.args) >= 2 else 1 | ||
if isinstance(ex, KeyboardInterrupt): | ||
return 1 | ||
if isinstance(ex, HttpOperationError): | ||
try: | ||
response_dict = json.loads(ex.response.text) | ||
error = response_dict['error'] | ||
|
||
# ARM should use ODATA v4. So should try this first. | ||
# http://docs.oasis-open.org/odata/odata-json-format/v4.0/os/odata-json-format-v4.0-os.html#_Toc372793091 | ||
if isinstance(error, dict): | ||
code = "{} - ".format(error.get('code', 'Unknown Code')) | ||
message = error.get('message', ex) | ||
logger.error("%s%s", code, message) | ||
else: | ||
logger.error(error) | ||
|
||
except (ValueError, KeyError): | ||
logger.error(ex) | ||
return 1 | ||
|
||
logger.error("The command failed with an unexpected error. Here is the traceback:\n") | ||
logger.exception(ex) | ||
logger.warning("\nTo open an issue, please run: 'az feedback'") | ||
|
||
return 1 | ||
return 1 | ||
|
||
|
||
# pylint: disable=inconsistent-return-statements | ||
|
@@ -351,7 +345,7 @@ def open_page_in_browser(url): | |
if _is_wsl(platform_name, release): # windows 10 linux subsystem | ||
try: | ||
return subprocess.call(['cmd.exe', '/c', "start {}".format(url.replace('&', '^&'))]) | ||
except FileNotFoundError: # WSL might be too old | ||
except OSError: # WSL might be too old # FileNotFoundError introduced in Python 3 | ||
pass | ||
elif platform_name == 'darwin': | ||
# handle 2 things: | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -72,7 +72,9 @@ | |
'six', | ||
'tabulate>=0.7.7', | ||
'wheel==0.30.0', | ||
'azure-mgmt-resource==2.1.0' | ||
'azure-mgmt-resource==2.1.0', | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. In general, our setup.py files should contain a range of acceptable versions, instead of one pinned version. Not doing this causes issues like #6973. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. makes sense! |
||
'pyperclip>=1.7.0', | ||
'psutil>=5.6.1' | ||
] | ||
|
||
with open('README.rst', 'r', encoding='utf-8') as f: | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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 | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Why do we log the time for each command? I worry this may attract more perf related issues being raised. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think this was brought up in the meeting with @yugangw-msft and @achandmsft. I think the rational was to help customers notice / point out situations were commands are much slower than usual. I suppose we just saw it as general command related information. If perf really is a problem (esp. on the CLI side) moving forward then I think it doesn't hurt to give customers and ourselves more clarity regarding it. If it really is a problem then we eventually have to address it. I guess we could discuss this more when I am back from the conference. |
||
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) | ||
raise ex | ||
finally: | ||
telemetry.conclude() |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Could you point me to where you found this secret-sauce? It looks promising (seeing as we haven't historically been too sensitive to image size) but I want to make sure that I understand the consequences of adding this dependency.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@marstr, this is the github issue / comment that helped me out.