diff --git a/src/azure-cli-core/azure/cli/core/azclierror.py b/src/azure-cli-core/azure/cli/core/azclierror.py index 297b42bf9bb..02f9757e101 100644 --- a/src/azure-cli-core/azure/cli/core/azclierror.py +++ b/src/azure-cli-core/azure/cli/core/azclierror.py @@ -70,16 +70,16 @@ def print_error(self): if self.exception_trace: logger.exception(self.exception_trace) - # print recommendations to action - if self.recommendations: - for recommendation in self.recommendations: - print(recommendation, file=sys.stderr) - - if self.aladdin_recommendations: - print('\nTRY THIS:', file=sys.stderr) - for recommendation, description in self.aladdin_recommendations: - print_styled_text(recommendation, file=sys.stderr) - print_styled_text(description, file=sys.stderr) + # print recommendations to action + if self.recommendations: + for recommendation in self.recommendations: + print(recommendation, file=sys.stderr) + + if self.aladdin_recommendations: + print('\nTRY THIS:', file=sys.stderr) + for recommendation, description in self.aladdin_recommendations: + print_styled_text(recommendation, file=sys.stderr) + print_styled_text(description, file=sys.stderr) def send_telemetry(self): telemetry.set_error_type(self.__class__.__name__) diff --git a/src/azure-cli-core/azure/cli/core/azlogging.py b/src/azure-cli-core/azure/cli/core/azlogging.py index d2c3fbf1064..ae4b1e580bd 100644 --- a/src/azure-cli-core/azure/cli/core/azlogging.py +++ b/src/azure-cli-core/azure/cli/core/azlogging.py @@ -39,7 +39,7 @@ class AzCliLogging(CLILogging): - _COMMAND_METADATA_LOGGER = 'az_command_data_logger' + COMMAND_METADATA_LOGGER = 'az_command_data_logger' def __init__(self, name, cli_ctx=None): super(AzCliLogging, self).__init__(name, cli_ctx) @@ -86,16 +86,13 @@ def _delete_old_logs(log_dir): self = cli_ctx.logging args = kwargs['args'] - cmd_logger = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER) + metadata_logger = logging.getLogger(AzCliLogging.COMMAND_METADATA_LOGGER) - # overwrite CLILogging._is_file_log_enabled() from knack + # Overwrite the default of knack.log.CLILogging._is_file_log_enabled() to True self.file_log_enabled = cli_ctx.config.getboolean('logging', 'enable_log_file', fallback=True) if self.file_log_enabled: - 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) - + self._init_command_logfile_handlers(metadata_logger, args) # pylint: disable=protected-access _delete_old_logs(self.command_log_dir) def _init_command_logfile_handlers(self, command_metadata_logger, args): @@ -113,12 +110,15 @@ def _init_command_logfile_handlers(self, command_metadata_logger, args): log_name = "{}.{}.{}.{}.{}".format(date_str, time_str, command_str, os.getpid(), "log") log_file_path = os.path.join(self.command_log_dir, log_name) + get_logger(__name__).debug("metadata file logging enabled - writing logs to '%s'.", log_file_path) 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 should always accept all levels regardless of the root logger level. + command_metadata_logger.setLevel(logging.DEBUG) command_metadata_logger.addHandler(logfile_handler) self.command_logger_handler = logfile_handler @@ -201,15 +201,23 @@ def end_cmd_metadata_logging(self, exit_code): # leave it non '-' prefix to not class CommandLoggerContext: + """A context manager during which error logs are also written to az_command_data_logger for + `az feedback` usage. + """ def __init__(self, module_logger): - self.logger = module_logger - self.hdlr = logging.getLogger(AzCliLogging._COMMAND_METADATA_LOGGER) # pylint: disable=protected-access + metadata_logger = logging.getLogger(AzCliLogging.COMMAND_METADATA_LOGGER) + original_error = module_logger.error + + # Duplicate error logging to metadata logger + def error_duplicated(*args, **kwargs): + original_error(*args, **kwargs) + metadata_logger.error(*args, **kwargs) + from unittest import mock + self.mock_cm = mock.patch.object(module_logger, 'error', error_duplicated) def __enter__(self): - if self.hdlr: - self.logger.addHandler(self.hdlr) # add command metadata handler + self.mock_cm.__enter__() return self def __exit__(self, exc_type, exc_val, exc_tb): - if self.hdlr: - self.logger.removeHandler(self.hdlr) + self.mock_cm.__exit__(exc_type, exc_val, exc_tb) diff --git a/src/azure-cli-core/azure/cli/core/tests/test_parser.py b/src/azure-cli-core/azure/cli/core/tests/test_parser.py index b7f21ce261e..4590cc31e29 100644 --- a/src/azure-cli-core/azure/cli/core/tests/test_parser.py +++ b/src/azure-cli-core/azure/cli/core/tests/test_parser.py @@ -209,8 +209,10 @@ def test_parser_error_spellchecker(self): choice_lists = [] original_get_close_matches = difflib.get_close_matches - def mock_log_error(_, msg): - logger_msgs.append(msg) + def mock_log_error(logger_self, msg): + # Only intercept 'cli.azure.cli.core.azclierror' logger and ignore 'az_command_data_logger' + if logger_self.name.startswith('cli'): + logger_msgs.append(msg) def mock_get_close_matches(*args, **kwargs): choice_lists.append(original_get_close_matches(*args, **kwargs)) diff --git a/src/azure-cli-core/azure/cli/core/util.py b/src/azure-cli-core/azure/cli/core/util.py index 50c19b33802..5584deac4fa 100644 --- a/src/azure-cli-core/azure/cli/core/util.py +++ b/src/azure-cli-core/azure/cli/core/util.py @@ -58,7 +58,6 @@ def handle_exception(ex): # pylint: disable=too-many-locals, too-many-statement from jmespath.exceptions import JMESPathError from msrestazure.azure_exceptions import CloudError from msrest.exceptions import HttpOperationError, ValidationError, ClientRequestError - from azure.cli.core.azlogging import CommandLoggerContext from azure.common import AzureException from azure.core.exceptions import AzureError from requests.exceptions import SSLError, HTTPError @@ -69,89 +68,88 @@ def handle_exception(ex): # pylint: disable=too-many-locals, too-many-statement # Print the traceback and exception message logger.debug(traceback.format_exc()) - with CommandLoggerContext(logger): - error_msg = getattr(ex, 'message', str(ex)) - exit_code = 1 + error_msg = getattr(ex, 'message', str(ex)) + exit_code = 1 - if isinstance(ex, azclierror.AzCLIError): - az_error = ex + if isinstance(ex, azclierror.AzCLIError): + az_error = ex - elif isinstance(ex, JMESPathError): - error_msg = "Invalid jmespath query supplied for `--query`: {}".format(error_msg) - az_error = azclierror.InvalidArgumentValueError(error_msg) - az_error.set_recommendation(QUERY_REFERENCE) + elif isinstance(ex, JMESPathError): + error_msg = "Invalid jmespath query supplied for `--query`: {}".format(error_msg) + az_error = azclierror.InvalidArgumentValueError(error_msg) + az_error.set_recommendation(QUERY_REFERENCE) - elif isinstance(ex, SSLError): - az_error = azclierror.AzureConnectionError(error_msg) - az_error.set_recommendation(SSLERROR_TEMPLATE) + elif isinstance(ex, SSLError): + az_error = azclierror.AzureConnectionError(error_msg) + az_error.set_recommendation(SSLERROR_TEMPLATE) - elif isinstance(ex, CloudError): - if extract_common_error_message(ex): - error_msg = extract_common_error_message(ex) - status_code = str(getattr(ex, 'status_code', 'Unknown Code')) - AzCLIErrorType = get_error_type_by_status_code(status_code) - az_error = AzCLIErrorType(error_msg) - - elif isinstance(ex, ValidationError): - az_error = azclierror.ValidationError(error_msg) - - elif isinstance(ex, CLIError): - # TODO: Fine-grained analysis here - az_error = azclierror.UnclassifiedUserFault(error_msg) - - elif isinstance(ex, AzureError): - if extract_common_error_message(ex): - error_msg = extract_common_error_message(ex) - AzCLIErrorType = get_error_type_by_azure_error(ex) - az_error = AzCLIErrorType(error_msg) - - elif isinstance(ex, AzureException): - if is_azure_connection_error(error_msg): - az_error = azclierror.AzureConnectionError(error_msg) - else: - # TODO: Fine-grained analysis here for Unknown error - az_error = azclierror.UnknownError(error_msg) - - elif isinstance(ex, ClientRequestError): - if is_azure_connection_error(error_msg): - az_error = azclierror.AzureConnectionError(error_msg) - elif isinstance(ex.inner_exception, SSLError): - # When msrest encounters SSLError, msrest wraps SSLError in ClientRequestError - az_error = azclierror.AzureConnectionError(error_msg) - az_error.set_recommendation(SSLERROR_TEMPLATE) - else: - az_error = azclierror.ClientRequestError(error_msg) + elif isinstance(ex, CloudError): + if extract_common_error_message(ex): + error_msg = extract_common_error_message(ex) + status_code = str(getattr(ex, 'status_code', 'Unknown Code')) + AzCLIErrorType = get_error_type_by_status_code(status_code) + az_error = AzCLIErrorType(error_msg) - elif isinstance(ex, HttpOperationError): - message, _ = extract_http_operation_error(ex) - if message: - error_msg = message - status_code = str(getattr(ex.response, 'status_code', 'Unknown Code')) - AzCLIErrorType = get_error_type_by_status_code(status_code) - az_error = AzCLIErrorType(error_msg) + elif isinstance(ex, ValidationError): + az_error = azclierror.ValidationError(error_msg) - elif isinstance(ex, HTTPError): - status_code = str(getattr(ex.response, 'status_code', 'Unknown Code')) - AzCLIErrorType = get_error_type_by_status_code(status_code) - az_error = AzCLIErrorType(error_msg) + elif isinstance(ex, CLIError): + # TODO: Fine-grained analysis here + az_error = azclierror.UnclassifiedUserFault(error_msg) - elif isinstance(ex, KeyboardInterrupt): - error_msg = 'Keyboard interrupt is captured.' - az_error = azclierror.ManualInterrupt(error_msg) + elif isinstance(ex, AzureError): + if extract_common_error_message(ex): + error_msg = extract_common_error_message(ex) + AzCLIErrorType = get_error_type_by_azure_error(ex) + az_error = AzCLIErrorType(error_msg) + elif isinstance(ex, AzureException): + if is_azure_connection_error(error_msg): + az_error = azclierror.AzureConnectionError(error_msg) else: - error_msg = "The command failed with an unexpected error. Here is the traceback:" - az_error = azclierror.CLIInternalError(error_msg) - az_error.set_exception_trace(ex) - az_error.set_recommendation("To open an issue, please run: 'az feedback'") - - if isinstance(az_error, azclierror.ResourceNotFoundError): - exit_code = 3 + # TODO: Fine-grained analysis here for Unknown error + az_error = azclierror.UnknownError(error_msg) - az_error.print_error() - az_error.send_telemetry() - - return exit_code + elif isinstance(ex, ClientRequestError): + if is_azure_connection_error(error_msg): + az_error = azclierror.AzureConnectionError(error_msg) + elif isinstance(ex.inner_exception, SSLError): + # When msrest encounters SSLError, msrest wraps SSLError in ClientRequestError + az_error = azclierror.AzureConnectionError(error_msg) + az_error.set_recommendation(SSLERROR_TEMPLATE) + else: + az_error = azclierror.ClientRequestError(error_msg) + + elif isinstance(ex, HttpOperationError): + message, _ = extract_http_operation_error(ex) + if message: + error_msg = message + status_code = str(getattr(ex.response, 'status_code', 'Unknown Code')) + AzCLIErrorType = get_error_type_by_status_code(status_code) + az_error = AzCLIErrorType(error_msg) + + elif isinstance(ex, HTTPError): + status_code = str(getattr(ex.response, 'status_code', 'Unknown Code')) + AzCLIErrorType = get_error_type_by_status_code(status_code) + az_error = AzCLIErrorType(error_msg) + + elif isinstance(ex, KeyboardInterrupt): + error_msg = 'Keyboard interrupt is captured.' + az_error = azclierror.ManualInterrupt(error_msg) + + else: + error_msg = "The command failed with an unexpected error. Here is the traceback:" + az_error = azclierror.CLIInternalError(error_msg) + az_error.set_exception_trace(ex) + az_error.set_recommendation("To open an issue, please run: 'az feedback'") + + if isinstance(az_error, azclierror.ResourceNotFoundError): + exit_code = 3 + + az_error.print_error() + az_error.send_telemetry() + + return exit_code def extract_common_error_message(ex): diff --git a/src/azure-cli/azure/cli/command_modules/feedback/tests/latest/test_feedback.py b/src/azure-cli/azure/cli/command_modules/feedback/tests/latest/test_feedback.py index 35d21fc5025..5885513171e 100644 --- a/src/azure-cli/azure/cli/command_modules/feedback/tests/latest/test_feedback.py +++ b/src/azure-cli/azure/cli/command_modules/feedback/tests/latest/test_feedback.py @@ -8,7 +8,7 @@ import os import time import unittest - +from unittest import mock from knack.events import EVENT_CLI_POST_EXECUTE from azure.cli.core.azlogging import CommandLoggerContext @@ -138,7 +138,7 @@ def _helper_test_log_contents_correct(self): # 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].strip()) + self.assertEqual("The extension alias is not installed.", data_dict["errors"][0].strip()) self.assertEqual(data_dict["command_args"], "extension remove -n {}") # check successful cli command @@ -192,22 +192,18 @@ def _run_cmd(self, command, checks=None, expect_failure=False): cli_ctx = get_dummy_cli() cli_ctx.logging.command_log_dir = self.temp_command_log_dir - # hotfix here for untouch feedback's code to avoid introducing possible break change. - # unregister the event for auto closing CLI's file logging after execute() is done - cli_ctx.unregister_event(EVENT_CLI_POST_EXECUTE, cli_ctx.logging.deinit_cmd_metadata_logging) - - # 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): - result = execute(cli_ctx, command, expect_failure=expect_failure).assert_with_checks(checks) + # azure.cli.core.util.handle_exception is mocked by azure.cli.testsdk.patches.patch_main_exception_handler + # Patch it again so that errors are properly written to command log file. + from azure.cli.core.util import handle_exception + original_handle_exception = handle_exception - if result.exit_code != 0: - logger.error("There was an error during execution.") - - # close it manually because we unregister the deinit_cmd_metadata_logging - # callback from EVENT_CLI_POST_EXECUTE event - cli_ctx.logging.end_cmd_metadata_logging(result.exit_code) + def _handle_exception_with_log(ex, *args, **kwargs): + with CommandLoggerContext(logger): + logger.error(ex) + original_handle_exception(*args, **kwargs) + with mock.patch('azure.cli.core.util.handle_exception', _handle_exception_with_log): + result = execute(cli_ctx, command, expect_failure=expect_failure).assert_with_checks(checks) return result