Feature/logging policy manual update

sdk/core/azure-core/HISTORY.md

@@ -10,6 +10,7 @@
 - Tracing: DistributedTracingPolicy now accepts kwargs network_span_namer to change network span name  #7773
 - Tracing: Implementation of AbstractSpan can now use the mixin HttpSpanMixin to get HTTP span update automatically  #7773
 - Tracing: AbstractSpan contract "change_context" introduced  #7773
+- Introduce new policy HttpLoggingPolicy  #7988
 
 ### Bug fixes
 

sdk/core/azure-core/azure/core/pipeline/policies/__init__.py

@@ -35,7 +35,8 @@
     UserAgentPolicy,
     NetworkTraceLoggingPolicy,
     ContentDecodePolicy,
-    ProxyPolicy
+    ProxyPolicy,
+    HttpLoggingPolicy,
 )
 
 __all__ = [
@@ -52,6 +53,7 @@
     'CustomHookPolicy',
     'DistributedTracingPolicy',
     'RequestHistory',
+    'HttpLoggingPolicy',
 ]
 
 #pylint: disable=unused-import

sdk/core/azure-core/azure/core/pipeline/policies/_universal.py

@@ -36,6 +36,7 @@
 import re
 from typing import (Mapping, IO, TypeVar, TYPE_CHECKING, Type, cast, List, Callable, Iterator, # pylint: disable=unused-import
                     Any, Union, Dict, Optional, AnyStr)
+from six.moves import urllib
 
 from azure.core import __version__  as azcore_version
 from azure.core.exceptions import (
@@ -267,6 +268,106 @@ def on_response(self, request, response):
                 _LOGGER.debug("Failed to log response: %s", repr(err))
 
 
+class HttpLoggingPolicy(SansIOHTTPPolicy):
+    """The Pipeline policy that handles logging of HTTP requests and responses.
+    """
+
+    DEFAULT_HEADERS_WHITELIST = set([
+        "x-ms-client-request-id",
+        "x-ms-return-client-request-id",
+        "traceparent",
+        "Accept",
+        "Cache-Control",
+        "Connection",
+        "Content-Length",
+        "Content-Type",
+        "Date",
+        "ETag",
+        "Expires",
+        "If-Match",
+        "If-Modified-Since",
+        "If-None-Match",
+        "If-Unmodified-Since",
+        "Last-Modified",
+        "Pragma",
+        "Request-Id",
+        "Retry-After",
+        "Server",
+        "Transfer-Encoding",
+        "User-Agent"
+    ])
+    REDACTED_PLACEHOLDER = "REDACTED"
+
+    def __init__(self, logger=None, **kwargs):  # pylint: disable=unused-argument
+        self.logger = logger or logging.getLogger(
+            "azure.core.pipeline.policies.http_logging_policy"
+        )
+        self.allowed_query_params = set()
+        self.allowed_header_namers = set(HttpLoggingPolicy.DEFAULT_HEADERS_WHITELIST)
+
+    def _redact_query_param(self, key, value):
+        lower_case_allowed_query_params = [
+            param.lower() for param in self.allowed_query_params
+        ]
+        return value if key.lower() in lower_case_allowed_query_params else HttpLoggingPolicy.REDACTED_PLACEHOLDER
+
+    def _redact_header(self, key, value):
+        lower_case_allowed_header_namers = [
+            header.lower() for header in self.allowed_header_namers
+        ]
+        return value if key.lower() in lower_case_allowed_header_namers else HttpLoggingPolicy.REDACTED_PLACEHOLDER
+
+    def on_request(self, request):
+        # type: (PipelineRequest) -> None
+        """Logs HTTP method, url and headers.
+        :param request: The PipelineRequest object.
+        :type request: ~azure.core.pipeline.PipelineRequest
+        """
+        http_request = request.http_request
+        options = request.context.options
+        # Get logger in my context first (request has been retried)
+        # then read from kwargs (pop if that's the case)
+        # then use my instance logger
+        logger = request.context.setdefault("logger", options.pop("logger", self.logger))
+
+        if not logger.isEnabledFor(logging.INFO):
+            return
+
+        try:
+            parsed_url = list(urllib.parse.urlparse(http_request.url))
+            parsed_qp = urllib.parse.parse_qsl(parsed_url[4], keep_blank_values=True)
+            filtered_qp = [(key, self._redact_query_param(key, value)) for key, value in parsed_qp]
+            # 4 is query
+            parsed_url[4] = "&".join(["=".join(part) for part in filtered_qp])
+            redacted_url = urllib.parse.urlunparse(parsed_url)
+
+            logger.info("Request URL: %r", redacted_url)
+            logger.info("Request method: %r", http_request.method)
+            logger.info("Request headers:")
+            for header, value in http_request.headers.items():
+                value = self._redact_header(header, value)
+                logger.info("    %r: %r", header, value)
+        except Exception as err:  # pylint: disable=broad-except
+            logger.warning("Failed to log request: %s", repr(err))
+
+    def on_response(self, request, response):
+        # type: (PipelineRequest, PipelineResponse) -> None
+        http_response = response.http_response
+        logger = response.context.get("logger")
+
+        if not logger.isEnabledFor(logging.INFO):
+            return
+
+        try:
+            logger.info("Response status: %r", http_response.status_code)
+            logger.info("Response headers:")
+            for res_header, value in http_response.headers.items():
+                value = self._redact_header(res_header, value)
+                logger.info("    %r: %r", res_header, value)
+        except Exception as err:  # pylint: disable=broad-except
+            logger.warning("Failed to log response: %s", repr(err))
+
+
 class ContentDecodePolicy(SansIOHTTPPolicy):
     """Policy for decoding unstreamed response content.
     """

sdk/core/azure-core/tests/test_universal_pipeline.py

@@ -24,6 +24,7 @@
 # THE SOFTWARE.
 #
 #--------------------------------------------------------------------------
+import logging
 try:
     from unittest import mock
 except ImportError:
@@ -49,7 +50,8 @@
 from azure.core.pipeline.policies import (
     NetworkTraceLoggingPolicy,
     ContentDecodePolicy,
-    UserAgentPolicy
+    UserAgentPolicy,
+    HttpLoggingPolicy,
 )
 
 def test_user_agent():
@@ -192,3 +194,179 @@ def body(self):
     raw_deserializer.on_response(None, response)
     result = response.context["deserialized_data"]
     assert result["success"] is True
+
+
+def test_http_logger():
+
+    class MockHandler(logging.Handler):
+        def __init__(self):
+            super(MockHandler, self).__init__()
+            self.messages = []
+        def reset(self):
+            self.messages = []
+        def emit(self, record):
+            self.messages.append(record)
+    mock_handler = MockHandler()
+
+    logger = logging.getLogger("testlogger")
+    logger.addHandler(mock_handler)
+    logger.setLevel(logging.DEBUG)
+
+    policy = HttpLoggingPolicy(logger=logger)
+
+    universal_request = HttpRequest('GET', 'http://127.0.0.1/')
+    http_response = HttpResponse(universal_request, None)
+    http_response.status_code = 202
+    request = PipelineRequest(universal_request, PipelineContext(None))
+
+    # Basics
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    assert all(m.levelname == 'INFO' for m in mock_handler.messages)
+    assert len(mock_handler.messages) == 5
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+
+    mock_handler.reset()
+
+    # Let's make this request a failure, retried twice
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    assert all(m.levelname == 'INFO' for m in mock_handler.messages)
+    assert len(mock_handler.messages) == 10
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+
+    mock_handler.reset()
+
+    # Headers and query parameters
+
+    policy.allowed_query_params = ['country']
+
+    universal_request.headers = {
+        "Accept": "Caramel",
+        "Hate": "Chocolat",
+    }
+    http_response.headers = {
+        "Content-Type": "Caramel",
+        "HateToo": "Chocolat",
+    }
+    universal_request.url = "http://127.0.0.1/?country=france&city=aix"
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    assert all(m.levelname == 'INFO' for m in mock_handler.messages)
+    assert len(mock_handler.messages) == 9
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/?country=france&city=REDACTED'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == "Request headers:"
+    # Dict not ordered in Python, exact logging order doesn't matter
+    assert set([
+        mock_handler.messages[3].message,
+        mock_handler.messages[4].message
+    ]) == set([
+        "    'Accept': 'Caramel'",
+        "    'Hate': 'REDACTED'"
+    ])
+    assert mock_handler.messages[5].message == "Response status: 202"
+    assert mock_handler.messages[6].message == "Response headers:"
+    # Dict not ordered in Python, exact logging order doesn't matter
+    assert set([
+        mock_handler.messages[7].message,
+        mock_handler.messages[8].message
+    ]) == set([
+        "    'Content-Type': 'Caramel'",
+        "    'HateToo': 'REDACTED'"
+    ])
+
+    mock_handler.reset()
+
+def test_http_logger_operation_level():
+
+    class MockHandler(logging.Handler):
+        def __init__(self):
+            super(MockHandler, self).__init__()
+            self.messages = []
+        def reset(self):
+            self.messages = []
+        def emit(self, record):
+            self.messages.append(record)
+    mock_handler = MockHandler()
+
+    logger = logging.getLogger("testlogger")
+    logger.addHandler(mock_handler)
+    logger.setLevel(logging.DEBUG)
+
+    policy = HttpLoggingPolicy()
+    kwargs={'logger': logger}
+
+    universal_request = HttpRequest('GET', 'http://127.0.0.1/')
+    http_response = HttpResponse(universal_request, None)
+    http_response.status_code = 202
+    request = PipelineRequest(universal_request, PipelineContext(None, **kwargs))
+
+    # Basics
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    assert all(m.levelname == 'INFO' for m in mock_handler.messages)
+    assert len(mock_handler.messages) == 5
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+
+    mock_handler.reset()
+
+    # Let's make this request a failure, retried twice
+
+    request = PipelineRequest(universal_request, PipelineContext(None, **kwargs))
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    policy.on_request(request)
+    response = PipelineResponse(request, http_response, request.context)
+    policy.on_response(request, response)
+
+    assert all(m.levelname == 'INFO' for m in mock_handler.messages)
+    assert len(mock_handler.messages) == 10
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+    assert mock_handler.messages[0].message == "Request URL: 'http://127.0.0.1/'"
+    assert mock_handler.messages[1].message == "Request method: 'GET'"
+    assert mock_handler.messages[2].message == 'Request headers:'
+    assert mock_handler.messages[3].message == 'Response status: 202'
+    assert mock_handler.messages[4].message == 'Response headers:'
+
+    mock_handler.reset()