{Log} Adapt az_command_data_logger to Knack 0.8.0 (Azure#17324)

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__)

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)

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))

src/azure-cli-core/azure/cli/core/util.py

@@ -56,7 +56,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
@@ -67,89 +66,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):

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