From 424c3c79dfa329faa9b1c4cb70246a2908e7bdcb Mon Sep 17 00:00:00 2001 From: Xiang Yan Date: Thu, 23 Sep 2021 09:17:27 -0700 Subject: [PATCH] integrate logs (#20300) * integrate logs * update * update * update * update * Update _universal.py * update --- .../core/pipeline/policies/_universal.py | 107 +++++++++---- .../test_http_logging_policy_async.py | 148 ++++++++++-------- .../tests/test_http_logging_policy.py | 148 ++++++++++-------- .../tests/test_certificates_client.py | 30 ++-- .../tests/test_certificates_client_async.py | 30 ++-- .../tests/test_key_client.py | 34 ++-- .../tests/test_keys_async.py | 34 ++-- .../tests/test_secrets_async.py | 30 ++-- .../tests/test_secrets_client.py | 30 ++-- 9 files changed, 346 insertions(+), 245 deletions(-) diff --git a/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py b/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py index 1e8d712bc12d..8f18d04883bb 100644 --- a/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py +++ b/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py @@ -246,6 +246,7 @@ def on_request(self, request): class NetworkTraceLoggingPolicy(SansIOHTTPPolicy): + """The logging policy in the pipeline is used to output HTTP network trace to the configured logger. This accepts both global configuration, and per-request level with "enable_http_logger" @@ -264,7 +265,7 @@ class NetworkTraceLoggingPolicy(SansIOHTTPPolicy): def __init__(self, logging_enable=False, **kwargs): # pylint: disable=unused-argument self.enable_http_logger = logging_enable - def on_request(self, request): + def on_request(self, request): # pylint: disable=too-many-return-statements # type: (PipelineRequest) -> None """Logs HTTP request to the DEBUG logger. @@ -280,27 +281,31 @@ def on_request(self, request): return try: - _LOGGER.debug("Request URL: %r", http_request.url) - _LOGGER.debug("Request method: %r", http_request.method) - _LOGGER.debug("Request headers:") + log_string = "Request URL: '{}'".format(http_request.url) + log_string += "/nRequest method: '{}'".format(http_request.method) + log_string += "/nRequest headers:" for header, value in http_request.headers.items(): - _LOGGER.debug(" %r: %r", header, value) - _LOGGER.debug("Request body:") + log_string += "/n '{}': '{}'".format(header, value) + log_string += "/nRequest 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") + log_string += "/nFile upload" + _LOGGER.debug(log_string) return try: if isinstance(http_request.body, types.AsyncGeneratorType): - _LOGGER.debug("File upload") + log_string += "/nFile upload" + _LOGGER.debug(log_string) return except AttributeError: pass if http_request.body: - _LOGGER.debug(str(http_request.body)) + log_string += "/n{}".format(str(http_request.body)) + _LOGGER.debug(log_string) return - _LOGGER.debug("This request has no body") + log_string += "/nThis request has no body" + _LOGGER.debug(log_string) except Exception as err: # pylint: disable=broad-except _LOGGER.debug("Failed to log request: %r", err) @@ -320,28 +325,29 @@ def on_response(self, request, response): if not _LOGGER.isEnabledFor(logging.DEBUG): return - _LOGGER.debug("Response status: %r", http_response.status_code) - _LOGGER.debug("Response headers:") + log_string = "Response status: '{}'".format(http_response.status_code) + log_string += "/nResponse headers:" for res_header, value in http_response.headers.items(): - _LOGGER.debug(" %r: %r", res_header, value) + log_string += "/n '{}': '{}'".format(res_header, value) # We don't want to log binary data if the response is a file. - _LOGGER.debug("Response content:") + log_string += "/nResponse 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) + log_string += "/nFile attachments: {}".format(filename) elif http_response.headers.get("content-type", "").endswith("octet-stream"): - _LOGGER.debug("Body contains binary data.") + log_string += "/nBody contains binary data." elif http_response.headers.get("content-type", "").startswith("image"): - _LOGGER.debug("Body contains image data.") + log_string += "/nBody contains image data." else: if response.context.options.get('stream', False): - _LOGGER.debug("Body is streamable") + log_string += "/nBody is streamable." else: - _LOGGER.debug(http_response.text()) + log_string += "/n{}".format(http_response.text()) + _LOGGER.debug(log_string) except Exception as err: # pylint: disable=broad-except _LOGGER.debug("Failed to log response: %s", repr(err)) @@ -376,6 +382,7 @@ class HttpLoggingPolicy(SansIOHTTPPolicy): "User-Agent", ]) REDACTED_PLACEHOLDER = "REDACTED" + MULTI_RECORD_LOG = "AZURE_SDK_LOGGING_MULTIRECORD" def __init__(self, logger=None, **kwargs): # pylint: disable=unused-argument self.logger = logger or logging.getLogger( @@ -396,7 +403,7 @@ def _redact_header(self, key, value): ] return value if key.lower() in lower_case_allowed_header_names else HttpLoggingPolicy.REDACTED_PLACEHOLDER - def on_request(self, request): + def on_request(self, request): # pylint: disable=too-many-return-statements # type: (PipelineRequest) -> None """Logs HTTP method, url and headers. :param request: The PipelineRequest object. @@ -420,26 +427,52 @@ def on_request(self, request): 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:") + multi_record = os.environ.get(HttpLoggingPolicy.MULTI_RECORD_LOG, False) + if multi_record: + 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) + if isinstance(http_request.body, types.GeneratorType): + logger.info("File upload") + return + try: + if isinstance(http_request.body, types.AsyncGeneratorType): + logger.info("File upload") + return + except AttributeError: + pass + if http_request.body: + logger.info("A body is sent with the request") + return + logger.info("No body was attached to the request") + return + log_string = "Request URL: '{}'".format(redacted_url) + log_string += "/nRequest method: '{}'".format(http_request.method) + log_string += "/nRequest headers:" for header, value in http_request.headers.items(): value = self._redact_header(header, value) - logger.info(" %r: %r", header, value) + log_string += "/n '{}': '{}'".format(header, value) if isinstance(http_request.body, types.GeneratorType): - logger.info("File upload") + log_string += "/nFile upload" + logger.info(log_string) return try: if isinstance(http_request.body, types.AsyncGeneratorType): - logger.info("File upload") + log_string += "/nFile upload" + logger.info(log_string) return except AttributeError: pass if http_request.body: - logger.info("A body is sent with the request") + log_string += "/nA body is sent with the request" + logger.info(log_string) return - logger.info("No body was attached to the request") - return + log_string += "/nNo body was attached to the request" + logger.info(log_string) + except Exception as err: # pylint: disable=broad-except logger.warning("Failed to log request: %s", repr(err)) @@ -453,15 +486,23 @@ def on_response(self, request, response): if not logger.isEnabledFor(logging.INFO): return - logger.info("Response status: %r", http_response.status_code) - logger.info("Response headers:") + multi_record = os.environ.get(HttpLoggingPolicy.MULTI_RECORD_LOG, False) + if multi_record: + 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) + return + log_string = "Response status: {}".format(http_response.status_code) + log_string += "/nResponse headers:" for res_header, value in http_response.headers.items(): value = self._redact_header(res_header, value) - logger.info(" %r: %r", res_header, value) + log_string += "/n '{}': '{}'".format(res_header, value) + logger.info(log_string) 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. diff --git a/sdk/core/azure-core/tests/async_tests/test_http_logging_policy_async.py b/sdk/core/azure-core/tests/async_tests/test_http_logging_policy_async.py index 640d085103aa..ab8d4ca72b37 100644 --- a/sdk/core/azure-core/tests/async_tests/test_http_logging_policy_async.py +++ b/sdk/core/azure-core/tests/async_tests/test_http_logging_policy_async.py @@ -53,13 +53,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'No body was attached to the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -74,19 +76,23 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 12 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' - assert mock_handler.messages[6].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[7].message == "Request method: 'GET'" - assert mock_handler.messages[8].message == 'Request headers:' - assert mock_handler.messages[9].message == 'No body was attached to the request' - assert mock_handler.messages[10].message == 'Response status: 202' - assert mock_handler.messages[11].message == 'Response headers:' + assert len(mock_handler.messages) == 4 + messages_request1 = mock_handler.messages[0].message.split("/n") + messages_response1 = mock_handler.messages[1].message.split("/n") + messages_request2 = mock_handler.messages[2].message.split("/n") + messages_response2 = mock_handler.messages[3].message.split("/n") + assert messages_request1[0] == "Request URL: 'http://localhost/'" + assert messages_request1[1] == "Request method: 'GET'" + assert messages_request1[2] == 'Request headers:' + assert messages_request1[3] == 'No body was attached to the request' + assert messages_response1[0] == 'Response status: 202' + assert messages_response1[1] == 'Response headers:' + assert messages_request2[0] == "Request URL: 'http://localhost/'" + assert messages_request2[1] == "Request method: 'GET'" + assert messages_request2[2] == 'Request headers:' + assert messages_request2[3] == 'No body was attached to the request' + assert messages_response2[0] == 'Response status: 202' + assert messages_response2[1] == 'Response headers:' mock_handler.reset() @@ -109,25 +115,27 @@ def emit(self, record): 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://localhost/?country=france&city=REDACTED'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == "Request headers:" + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/?country=france&city=REDACTED'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == "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 + messages_request[3], + messages_request[4] ]) == set([ " 'Accept': 'Caramel'", " 'Hate': 'REDACTED'" ]) - assert mock_handler.messages[5].message == 'No body was attached to the request' - assert mock_handler.messages[6].message == "Response status: 202" - assert mock_handler.messages[7].message == "Response headers:" + assert messages_request[5] == 'No body was attached to the request' + assert messages_response[0] == "Response status: 202" + assert messages_response[1] == "Response headers:" # Dict not ordered in Python, exact logging order doesn't matter assert set([ - mock_handler.messages[8].message, - mock_handler.messages[9].message + messages_response[2], + messages_response[3] ]) == set([ " 'Content-Type': 'Caramel'", " 'HateToo': 'REDACTED'" @@ -168,13 +176,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'No body was attached to the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -191,19 +201,23 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 12 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' - assert mock_handler.messages[6].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[7].message == "Request method: 'GET'" - assert mock_handler.messages[8].message == 'Request headers:' - assert mock_handler.messages[9].message == 'No body was attached to the request' - assert mock_handler.messages[10].message == 'Response status: 202' - assert mock_handler.messages[11].message == 'Response headers:' + assert len(mock_handler.messages) == 4 + messages_request1 = mock_handler.messages[0].message.split("/n") + messages_response1 = mock_handler.messages[1].message.split("/n") + messages_request2 = mock_handler.messages[2].message.split("/n") + messages_response2 = mock_handler.messages[3].message.split("/n") + assert messages_request1[0] == "Request URL: 'http://localhost/'" + assert messages_request1[1] == "Request method: 'GET'" + assert messages_request1[2] == 'Request headers:' + assert messages_request1[3] == 'No body was attached to the request' + assert messages_response1[0] == 'Response status: 202' + assert messages_response1[1] == 'Response headers:' + assert messages_request2[0] == "Request URL: 'http://localhost/'" + assert messages_request2[1] == "Request method: 'GET'" + assert messages_request2[2] == 'Request headers:' + assert messages_request2[3] == 'No body was attached to the request' + assert messages_response2[0] == 'Response status: 202' + assert messages_response2[1] == 'Response headers:' mock_handler.reset() @@ -237,13 +251,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'A body is sent with the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'A body is sent with the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -281,12 +297,14 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'File upload' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'File upload' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() diff --git a/sdk/core/azure-core/tests/test_http_logging_policy.py b/sdk/core/azure-core/tests/test_http_logging_policy.py index a745946d4c3e..17f2a61e6953 100644 --- a/sdk/core/azure-core/tests/test_http_logging_policy.py +++ b/sdk/core/azure-core/tests/test_http_logging_policy.py @@ -55,13 +55,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'No body was attached to the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -76,19 +78,23 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 12 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' - assert mock_handler.messages[6].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[7].message == "Request method: 'GET'" - assert mock_handler.messages[8].message == 'Request headers:' - assert mock_handler.messages[9].message == 'No body was attached to the request' - assert mock_handler.messages[10].message == 'Response status: 202' - assert mock_handler.messages[11].message == 'Response headers:' + assert len(mock_handler.messages) == 4 + messages_request1 = mock_handler.messages[0].message.split("/n") + messages_response1 = mock_handler.messages[1].message.split("/n") + messages_request2 = mock_handler.messages[2].message.split("/n") + messages_response2 = mock_handler.messages[3].message.split("/n") + assert messages_request1[0] == "Request URL: 'http://localhost/'" + assert messages_request1[1] == "Request method: 'GET'" + assert messages_request1[2] == 'Request headers:' + assert messages_request1[3] == 'No body was attached to the request' + assert messages_response1[0] == 'Response status: 202' + assert messages_response1[1] == 'Response headers:' + assert messages_request2[0] == "Request URL: 'http://localhost/'" + assert messages_request2[1] == "Request method: 'GET'" + assert messages_request2[2] == 'Request headers:' + assert messages_request2[3] == 'No body was attached to the request' + assert messages_response2[0] == 'Response status: 202' + assert messages_response2[1] == 'Response headers:' mock_handler.reset() @@ -111,25 +117,27 @@ def emit(self, record): 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://localhost/?country=france&city=REDACTED'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == "Request headers:" + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/?country=france&city=REDACTED'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == "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 + messages_request[3], + messages_request[4] ]) == set([ " 'Accept': 'Caramel'", " 'Hate': 'REDACTED'" ]) - assert mock_handler.messages[5].message == 'No body was attached to the request' - assert mock_handler.messages[6].message == "Response status: 202" - assert mock_handler.messages[7].message == "Response headers:" + assert messages_request[5] == 'No body was attached to the request' + assert messages_response[0] == "Response status: 202" + assert messages_response[1] == "Response headers:" # Dict not ordered in Python, exact logging order doesn't matter assert set([ - mock_handler.messages[8].message, - mock_handler.messages[9].message + messages_response[2], + messages_response[3] ]) == set([ " 'Content-Type': 'Caramel'", " 'HateToo': 'REDACTED'" @@ -171,13 +179,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'No body was attached to the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -194,19 +204,23 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 12 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'No body was attached to the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' - assert mock_handler.messages[6].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[7].message == "Request method: 'GET'" - assert mock_handler.messages[8].message == 'Request headers:' - assert mock_handler.messages[9].message == 'No body was attached to the request' - assert mock_handler.messages[10].message == 'Response status: 202' - assert mock_handler.messages[11].message == 'Response headers:' + assert len(mock_handler.messages) == 4 + messages_request1 = mock_handler.messages[0].message.split("/n") + messages_response1 = mock_handler.messages[1].message.split("/n") + messages_request2 = mock_handler.messages[2].message.split("/n") + messages_response2 = mock_handler.messages[3].message.split("/n") + assert messages_request1[0] == "Request URL: 'http://localhost/'" + assert messages_request1[1] == "Request method: 'GET'" + assert messages_request1[2] == 'Request headers:' + assert messages_request1[3] == 'No body was attached to the request' + assert messages_response1[0] == 'Response status: 202' + assert messages_response1[1] == 'Response headers:' + assert messages_request2[0] == "Request URL: 'http://localhost/'" + assert messages_request2[1] == "Request method: 'GET'" + assert messages_request2[2] == 'Request headers:' + assert messages_request2[3] == 'No body was attached to the request' + assert messages_response2[0] == 'Response status: 202' + assert messages_response2[1] == 'Response headers:' mock_handler.reset() @@ -241,13 +255,15 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'A body is sent with the request' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'A body is sent with the request' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() @@ -284,12 +300,14 @@ def emit(self, record): policy.on_response(request, response) assert all(m.levelname == 'INFO' for m in mock_handler.messages) - assert len(mock_handler.messages) == 6 - assert mock_handler.messages[0].message == "Request URL: 'http://localhost/'" - assert mock_handler.messages[1].message == "Request method: 'GET'" - assert mock_handler.messages[2].message == 'Request headers:' - assert mock_handler.messages[3].message == 'File upload' - assert mock_handler.messages[4].message == 'Response status: 202' - assert mock_handler.messages[5].message == 'Response headers:' + assert len(mock_handler.messages) == 2 + messages_request = mock_handler.messages[0].message.split("/n") + messages_response = mock_handler.messages[1].message.split("/n") + assert messages_request[0] == "Request URL: 'http://localhost/'" + assert messages_request[1] == "Request method: 'GET'" + assert messages_request[2] == 'Request headers:' + assert messages_request[3] == 'File upload' + assert messages_response[0] == 'Response status: 202' + assert messages_response[1] == 'Response headers:' mock_handler.reset() diff --git a/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client.py b/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client.py index 91026a5c1ef4..07a5201ecf78 100644 --- a/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client.py +++ b/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client.py @@ -596,13 +596,15 @@ def test_logging_enabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - if body["provider"] == "Test": - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + if body["provider"] == "Test": + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -620,12 +622,14 @@ def test_logging_disabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - assert body["provider"] != "Test", "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + assert body["provider"] != "Test", "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass @only_2016_10_01() @client_setup diff --git a/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client_async.py b/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client_async.py index 9f9c3b6036dd..beb97d41b629 100644 --- a/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client_async.py +++ b/sdk/keyvault/azure-keyvault-certificates/tests/test_certificates_client_async.py @@ -602,13 +602,15 @@ async def test_logging_enabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - if body["provider"] == "Test": - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + if body["provider"] == "Test": + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -626,12 +628,14 @@ async def test_logging_disabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - assert body["provider"] != "Test", "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + assert body["provider"] != "Test", "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass @all_api_versions() @client_setup diff --git a/sdk/keyvault/azure-keyvault-keys/tests/test_key_client.py b/sdk/keyvault/azure-keyvault-keys/tests/test_key_client.py index 384f3e23db77..1609ededad21 100644 --- a/sdk/keyvault/azure-keyvault-keys/tests/test_key_client.py +++ b/sdk/keyvault/azure-keyvault-keys/tests/test_key_client.py @@ -389,14 +389,16 @@ def test_logging_enabled(self, client, is_hsm, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - expected_kty = "RSA-HSM" if is_hsm else "RSA" - if body["kty"] == expected_kty: - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + expected_kty = "RSA-HSM" if is_hsm else "RSA" + if body["kty"] == expected_kty: + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -414,13 +416,15 @@ def test_logging_disabled(self, client, is_hsm, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - expected_kty = "RSA-HSM" if is_hsm else "RSA" - assert body["kty"] != expected_kty, "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + expected_kty = "RSA-HSM" if is_hsm else "RSA" + assert body["kty"] != expected_kty, "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass @only_hsm_7_3_preview() @client_setup diff --git a/sdk/keyvault/azure-keyvault-keys/tests/test_keys_async.py b/sdk/keyvault/azure-keyvault-keys/tests/test_keys_async.py index cecba8d3cf97..17a2604bd223 100644 --- a/sdk/keyvault/azure-keyvault-keys/tests/test_keys_async.py +++ b/sdk/keyvault/azure-keyvault-keys/tests/test_keys_async.py @@ -419,14 +419,16 @@ async def test_logging_enabled(self, client, is_hsm, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - expected_kty = "RSA-HSM" if is_hsm else "RSA" - if body["kty"] == expected_kty: - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + expected_kty = "RSA-HSM" if is_hsm else "RSA" + if body["kty"] == expected_kty: + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -444,13 +446,15 @@ async def test_logging_disabled(self, client, is_hsm, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - expected_kty = "RSA-HSM" if is_hsm else "RSA" - assert body["kty"] != expected_kty, "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + expected_kty = "RSA-HSM" if is_hsm else "RSA" + assert body["kty"] != expected_kty, "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass @only_hsm_7_3_preview() @client_setup diff --git a/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_async.py b/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_async.py index b8c6ff8edb49..ccd5828f3f84 100644 --- a/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_async.py +++ b/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_async.py @@ -291,13 +291,15 @@ async def test_logging_enabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - if body["value"] == "secret-value": - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + if body["value"] == "secret-value": + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -315,12 +317,14 @@ async def test_logging_disabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - assert body["value"] != "secret-value", "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + assert body["value"] != "secret-value", "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass def test_service_headers_allowed_in_logs(): diff --git a/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_client.py b/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_client.py index 82aa6a6ed230..893ac113e5cd 100644 --- a/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_client.py +++ b/sdk/keyvault/azure-keyvault-secrets/tests/test_secrets_client.py @@ -297,13 +297,15 @@ def test_logging_enabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - if body["value"] == "secret-value": - return - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + if body["value"] == "secret-value": + return + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass assert False, "Expected request body wasn't logged" @@ -321,12 +323,14 @@ def test_logging_disabled(self, client, **kwargs): for message in mock_handler.messages: if message.levelname == "DEBUG" and message.funcName == "on_request": - try: - body = json.loads(message.message) - assert body["value"] != "secret-value", "Client request body was logged" - except (ValueError, KeyError): - # this means the message is not JSON or has no kty property - pass + messages_request = message.message.split("/n") + for m in messages_request: + try: + body = json.loads(m) + assert body["value"] != "secret-value", "Client request body was logged" + except (ValueError, KeyError): + # this means the message is not JSON or has no kty property + pass def test_service_headers_allowed_in_logs():