{Logging} Redact token headers from SDK HTTP log

src/azure-cli-core/azure/cli/core/commands/client_factory.py

@@ -123,13 +123,6 @@ def _prepare_client_kwargs_track2(cli_ctx):
     # Prepare connection_verify to change SSL verification behavior, used by ConnectionConfiguration
     client_kwargs.update(_debug.change_ssl_cert_verification_track2())
 
-    # Enable NetworkTraceLoggingPolicy which logs all headers (except Authorization) without being redacted
-    client_kwargs['logging_enable'] = True
-
-    # Disable ARMHttpLoggingPolicy which logs only allowed headers
-    # from azure.core.pipeline.policies import SansIOHTTPPolicy
-    # client_kwargs['http_logging_policy'] = SansIOHTTPPolicy()
-
     # Prepare User-Agent header, used by UserAgentPolicy
     client_kwargs['user_agent'] = get_az_user_agent()
 
@@ -157,6 +150,39 @@ def _prepare_client_kwargs_track2(cli_ctx):
     if 'x-ms-client-request-id' in cli_ctx.data['headers']:
         client_kwargs['request_id'] = cli_ctx.data['headers']['x-ms-client-request-id']
 
+    # Replace NetworkTraceLoggingPolicy to redact 'Authorization' and 'x-ms-authorization-auxiliary' headers.
+    #   NetworkTraceLoggingPolicy: log raw network trace, with all headers.
+    from azure.cli.core.sdk.policies import SafeNetworkTraceLoggingPolicy
+    client_kwargs['logging_policy'] = SafeNetworkTraceLoggingPolicy()
+
+    # Disable ARMHttpLoggingPolicy.
+    #   ARMHttpLoggingPolicy: Only log allowed information.
+    from azure.core.pipeline.policies import SansIOHTTPPolicy
+    client_kwargs['http_logging_policy'] = SansIOHTTPPolicy()
+
+    return client_kwargs
+
+
+def _prepare_mgmt_client_kwargs_track2(cli_ctx, cred):
+    """Prepare kwargs for Track 2 SDK mgmt client."""
+    client_kwargs = _prepare_client_kwargs_track2(cli_ctx)
+
+    from azure.cli.core.util import resource_to_scopes
+    # Track 2 SDK maintains `scopes` and passes `scopes` to get_token.
+    scopes = resource_to_scopes(cli_ctx.cloud.endpoints.active_directory_resource_id)
+
+    client_kwargs['credential_scopes'] = scopes
+
+    # Track 2 currently lacks the ability to take external credentials.
+    #   https://github.com/Azure/azure-sdk-for-python/issues/8313
+    # As a temporary workaround, manually add external tokens to 'x-ms-authorization-auxiliary' header.
+    #   https://docs.microsoft.com/en-us/azure/azure-resource-manager/management/authenticate-multi-tenant
+    if getattr(cred, "_external_tenant_token_retriever", None):
+        *_, external_tenant_tokens = cred.get_all_tokens(*scopes)
+        # Hard-code scheme to 'Bearer' as _BearerTokenCredentialPolicyBase._update_headers does.
+        client_kwargs['headers']['x-ms-authorization-auxiliary'] = \
+            ', '.join("Bearer {}".format(t[1]) for t in external_tenant_tokens)
+
     return client_kwargs
 
 
@@ -172,7 +198,6 @@ def _get_mgmt_service_client(cli_ctx,
                              aux_tenants=None,
                              **kwargs):
     from azure.cli.core._profile import Profile
-    from azure.cli.core.util import resource_to_scopes
     logger.debug('Getting management service client client_type=%s', client_type.__name__)
     resource = resource or cli_ctx.cloud.endpoints.active_directory_resource_id
     profile = Profile(cli_ctx=cli_ctx)
@@ -191,18 +216,7 @@ def _get_mgmt_service_client(cli_ctx,
         client_kwargs.update(kwargs)
 
     if is_track2(client_type):
-        client_kwargs.update(_prepare_client_kwargs_track2(cli_ctx))
-        client_kwargs['credential_scopes'] = resource_to_scopes(resource)
-
-        # Track 2 currently lacks the ability to take external credentials.
-        #   https://github.com/Azure/azure-sdk-for-python/issues/8313
-        # As a temporary workaround, manually add external tokens to 'x-ms-authorization-auxiliary' header.
-        #   https://docs.microsoft.com/en-us/azure/azure-resource-manager/management/authenticate-multi-tenant
-        if getattr(cred, "_external_tenant_token_retriever", None):
-            *_, external_tenant_tokens = cred.get_all_tokens(*resource_to_scopes(resource))
-            # Hard-code scheme to 'Bearer' as _BearerTokenCredentialPolicyBase._update_headers does.
-            client_kwargs['headers']['x-ms-authorization-auxiliary'] = \
-                ', '.join("Bearer {}".format(t[1]) for t in external_tenant_tokens)
+        client_kwargs.update(_prepare_mgmt_client_kwargs_track2(cli_ctx, cred))
 
     if subscription_bound:
         client = client_type(cred, subscription_id, **client_kwargs)

src/azure-cli-core/azure/cli/core/sdk/policies.py

@@ -0,0 +1,98 @@
+# --------------------------------------------------------------------------------------------
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License. See License.txt in the project root for license information.
+# --------------------------------------------------------------------------------------------
+
+import logging
+import re
+import types
+
+from azure.core.pipeline.policies import SansIOHTTPPolicy
+from knack.log import get_logger
+
+_LOGGER = get_logger(__name__)
+
+
+class SafeNetworkTraceLoggingPolicy(SansIOHTTPPolicy):
+    """The logging policy that redacts specified headers.
+    Based on azure.core.pipeline.policies._universal.NetworkTraceLoggingPolicy
+    """
+
+    def __init__(self, headers_to_redact=None):
+        """
+        :param list[str] headers_to_redact: headers that should be redacted from the log.
+          Default to 'Authorization', 'x-ms-authorization-auxiliary'.
+        """
+        if headers_to_redact is not None:
+            self.headers_to_redact = headers_to_redact
+        else:
+            self.headers_to_redact = ['authorization', 'x-ms-authorization-auxiliary']
+
+    def on_request(self, request):
+        http_request = request.http_request
+        options = request.context.options
+        logging_enable = options.pop("logging_enable", True)
+        request.context["logging_enable"] = logging_enable
+        if logging_enable:
+            if not _LOGGER.isEnabledFor(logging.DEBUG):
+                return
+
+            try:
+                _LOGGER.debug("Request URL: %r", http_request.url)
+                _LOGGER.debug("Request method: %r", http_request.method)
+                _LOGGER.debug("Request headers:")
+                for header, value in http_request.headers.items():
+                    if header.lower() in self.headers_to_redact:
+                        value = '*****'
+                    _LOGGER.debug("    %r: %r", header, value)
+                _LOGGER.debug("Request body:")
+
+                # We don't want to log the binary data of a file upload.
+                if isinstance(http_request.body, types.GeneratorType):
+                    _LOGGER.debug("File upload")
+                    return
+                try:
+                    if isinstance(http_request.body, types.AsyncGeneratorType):
+                        _LOGGER.debug("File upload")
+                        return
+                except AttributeError:
+                    pass
+                if http_request.body:
+                    _LOGGER.debug(str(http_request.body))
+                    return
+                _LOGGER.debug("This request has no body")
+            except Exception as err:  # pylint: disable=broad-except
+                _LOGGER.debug("Failed to log request: %r", err)
+
+    def on_response(self, request, response):  # pylint: disable=unused-argument, no-self-use
+        http_response = response.http_response
+        try:
+            logging_enable = response.context["logging_enable"]
+            if logging_enable:
+                if not _LOGGER.isEnabledFor(logging.DEBUG):
+                    return
+
+                _LOGGER.debug("Response status: %r", http_response.status_code)
+                _LOGGER.debug("Response headers:")
+                for res_header, value in http_response.headers.items():
+                    _LOGGER.debug("    %r: %r", res_header, value)
+
+                # We don't want to log binary data if the response is a file.
+                _LOGGER.debug("Response content:")
+                pattern = re.compile(r'attachment; ?filename=["\w.]+', re.IGNORECASE)
+                header = http_response.headers.get('content-disposition')
+
+                if header and pattern.match(header):
+                    filename = header.partition('=')[2]
+                    _LOGGER.debug("File attachments: %s", filename)
+                elif http_response.headers.get("content-type", "").endswith("octet-stream"):
+                    _LOGGER.debug("Body contains binary data.")
+                elif http_response.headers.get("content-type", "").startswith("image"):
+                    _LOGGER.debug("Body contains image data.")
+                else:
+                    if response.context.options.get('stream', False):
+                        _LOGGER.debug("Body is streamable")
+                    else:
+                        _LOGGER.debug(response.http_response.text())
+        except Exception as err:  # pylint: disable=broad-except
+            _LOGGER.debug("Failed to log response: %s", repr(err))

src/azure-cli-core/setup.py

@@ -46,7 +46,6 @@
     'argcomplete~=1.8',
     'azure-cli-telemetry==1.0.6.*',
     'azure-common~=1.1',
-    'azure-core==1.12.0',
     'azure-mgmt-core>=1.2.0,<2.0.0',
     'colorama~=0.4.1',
     'cryptography>=3.2,<3.4',

src/azure-cli/requirements.py3.Darwin.txt

@@ -9,7 +9,7 @@ azure-cli-core==2.22.0
 azure-cli-telemetry==1.0.6
 azure-cli==2.22.0
 azure-common==1.1.22
-azure-core==1.12.0
+azure-core==1.13.0
 azure-cosmos==3.2.0
 azure-datalake-store==0.0.49
 azure-functions-devops-build==0.0.22

src/azure-cli/requirements.py3.Linux.txt

@@ -9,7 +9,7 @@ azure-cli-core==2.22.0
 azure-cli-telemetry==1.0.6
 azure-cli==2.22.0
 azure-common==1.1.22
-azure-core==1.12.0
+azure-core==1.13.0
 azure-cosmos==3.2.0
 azure-datalake-store==0.0.49
 azure-functions-devops-build==0.0.22

src/azure-cli/requirements.py3.windows.txt

@@ -9,7 +9,7 @@ azure-cli-core==2.22.0
 azure-cli-telemetry==1.0.6
 azure-cli==2.22.0
 azure-common==1.1.22
-azure-core==1.12.0
+azure-core==1.13.0
 azure-cosmos==3.2.0
 azure-datalake-store==0.0.49
 azure-functions-devops-build==0.0.22