Stops the request from being logged twice (Azure#40767)

* Stops the request from being logged twice

Sometimes the request was logged twice, this makes it so it will only be logged once. Issue was that we have to call on_request in on_response when we have filters in order to make them have matching filterable attributes. Previously we were always calling on_request from on_response regardless if there was a filter and we always passed the extra log attributes which causes the request to be logged twice. Another part of the fix is to also check for filters both at the logger wide level and at an individual handler level.

* Update test_cosmos_http_logging_policy.py

* Update _cosmos_http_logging_policy.py

Author: bambriz

sdk/cosmos/azure-cosmos/azure/cosmos/_cosmos_http_logging_policy.py

@@ -99,6 +99,7 @@ def _redact_header(self, key: str, value: str) -> str:
 
     def on_request(
             # pylint: disable=too-many-return-statements, too-many-statements, too-many-nested-blocks, too-many-branches
+            # pylint: disable=too-many-locals
             self, request: PipelineRequest[HTTPRequestType]
     ) -> None:
         """Logs HTTP method, url and headers.
@@ -109,6 +110,16 @@ def on_request(
 
             http_request = request.http_request
             request.context["start_time"] = time.time()
+            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 filtered is applied, and we are not calling on request from on response, just return to avoid logging
+            # the request again
+            filter_applied = (logger.filters) or any(bool(h.filters) for h in logger.handlers)
+            if filter_applied and 'logger_attributes' not in request.context:
+                return
             operation_type = http_request.headers.get('x-ms-thinclient-proxy-operation-type')
             try:
                 url = request.http_request.url
@@ -127,11 +138,7 @@ def on_request(
                     colls_index = url_parts.index('colls')
                     if colls_index + 1 < len(url_parts):
                         collection_name = url_parts[url_parts.index('colls') + 1]
-            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:
@@ -144,11 +151,9 @@ def on_request(
 
                 multi_record = os.environ.get(HttpLoggingPolicy.MULTI_RECORD_LOG, False)
 
-                if 'logger_attributes' in request.context:
+                if filter_applied and 'logger_attributes' in request.context:
                     cosmos_logger_attributes = request.context['logger_attributes']
                     cosmos_logger_attributes['is_request'] = True
-                elif logger.filters:
-                    return
                 else:
                     cosmos_logger_attributes = {
                         'duration': None,
@@ -220,7 +225,7 @@ def on_request(
             return
         super().on_request(request)
 
-    def on_response(  # pylint: disable=too-many-statements, too-many-branches
+    def on_response(  # pylint: disable=too-many-statements, too-many-branches, too-many-locals
             self,
             request: PipelineRequest[HTTPRequestType],
             response: PipelineResponse[HTTPRequestType, HTTPResponseType],
@@ -259,9 +264,10 @@ def on_response(  # pylint: disable=too-many-statements, too-many-branches
 
             options = context.options
             logger = context.setdefault("logger", options.pop("logger", self.logger))
-
-            context["logger_attributes"] = log_data.copy()
-            self.on_request(request)
+            filter_applied = bool(logger.filters) or any(bool(h.filters) for h in logger.handlers)
+            if filter_applied:
+                context["logger_attributes"] = log_data.copy()
+                self.on_request(request)
 
             try:
                 if not logger.isEnabledFor(logging.INFO):

sdk/cosmos/azure-cosmos/tests/test_cosmos_http_logging_policy.py

@@ -10,7 +10,7 @@
 import pytest
 
 import azure.cosmos.cosmos_client as cosmos_client
-from azure.cosmos.container import ContainerProxy
+from azure.cosmos import PartitionKey, ContainerProxy
 import test_config
 from _fault_injection_transport import FaultInjectionTransport
 from test_fault_injection_transport import TestFaultInjectionTransport
@@ -35,6 +35,12 @@ def reset(self):
     def emit(self, record):
         self.messages.append(record)
 
+class FilterStatusCode(logging.Filter):
+    def filter(self, record):
+        if hasattr(record, 'status_code') and record.status_code >= 400:
+            return True
+        return False
+
 CONFIG = test_config.TestConfig
 L1 = "Location1"
 L2 = "Location2"
@@ -83,8 +89,15 @@ def setUpClass(cls):
                 "tests.")
         cls.mock_handler_default = MockHandler()
         cls.mock_handler_diagnostic = MockHandler()
+        cls.mock_handler_filtered_diagnostic = MockHandler()
+
+        # Add filter to the filtered diagnostics handler
+
+        cls.mock_handler_filtered_diagnostic.addFilter(FilterStatusCode())
         cls.logger_default = create_logger("testloggerdefault", cls.mock_handler_default)
         cls.logger_diagnostic = create_logger("testloggerdiagnostic", cls.mock_handler_diagnostic)
+        cls.logger_filtered_diagnostic = create_logger("testloggerfiltereddiagnostic",
+                                                       cls.mock_handler_filtered_diagnostic)
         cls.client_default = cosmos_client.CosmosClient(cls.host, cls.masterKey,
                                                         consistency_level="Session",
                                                         connection_policy=cls.connectionPolicy,
@@ -94,6 +107,11 @@ def setUpClass(cls):
                                                            connection_policy=cls.connectionPolicy,
                                                            logger=cls.logger_diagnostic,
                                                            enable_diagnostics_logging=True)
+        cls.client_filtered_diagnostic = cosmos_client.CosmosClient(cls.host, cls.masterKey,
+                                                                    consistency_level="Session",
+                                                                    connection_policy=cls.connectionPolicy,
+                                                                    logger=cls.logger_filtered_diagnostic,
+                                                                    enable_diagnostics_logging=True)
 
     def test_default_http_logging_policy(self):
         # Test if we can log into from creating a database
@@ -118,22 +136,26 @@ def test_cosmos_http_logging_policy(self):
         database_id = "database_test-" + str(uuid.uuid4())
         self.client_diagnostic.create_database(id=database_id)
         assert all(m.levelname == 'INFO' for m in self.mock_handler_diagnostic.messages)
-        messages_request = self.mock_handler_diagnostic.messages[1]
-        messages_response = self.mock_handler_diagnostic.messages[2]
-        elapsed_time = messages_request.duration
+        # Check that we made a databaseaccount read request only once and that we only logged it once
+        messages_request = self.mock_handler_diagnostic.messages[0]
+        messages_response = self.mock_handler_diagnostic.messages[1]
+        elapsed_time = messages_response.duration
         assert "databaseaccount" == messages_request.resource_type
         assert messages_request.verb == "GET"
-        assert 200 == messages_request.status_code
+        assert 200 == messages_response.status_code
         assert "Read" == messages_request.operation_type
         assert elapsed_time is not None
         assert "Response headers" in messages_response.message
+        # Verify we only have a total of 4 logged messages: 2 from databaseaccount read and 2 from create database
+        assert len(self.mock_handler_diagnostic.messages) == 4
         # Test if we can log into from creating a database
-        messages_request = self.mock_handler_diagnostic.messages[4]
-        messages_response = self.mock_handler_diagnostic.messages[5]
-        elapsed_time = messages_request.duration
+        # The request to create database should follow the databaseaccount read request immediately
+        messages_request = self.mock_handler_diagnostic.messages[2]
+        messages_response = self.mock_handler_diagnostic.messages[3]
+        elapsed_time = messages_response.duration
         assert "dbs" == messages_request.resource_type
         assert messages_request.verb == "POST"
-        assert 201 == messages_request.status_code
+        assert 201 == messages_response.status_code
         assert messages_request.operation_type == "Create"
         assert elapsed_time is not None
         assert "Response headers" in messages_response.message
@@ -145,14 +167,14 @@ def test_cosmos_http_logging_policy(self):
         except:
             pass
         assert all(m.levelname == 'INFO' for m in self.mock_handler_diagnostic.messages)
-        messages_request = self.mock_handler_diagnostic.messages[1]
-        messages_response = self.mock_handler_diagnostic.messages[2]
-        elapsed_time = messages_request.duration
+        messages_request = self.mock_handler_diagnostic.messages[0]
+        messages_response = self.mock_handler_diagnostic.messages[1]
+        elapsed_time = messages_response.duration
         assert "dbs" == messages_request.resource_type
         assert messages_request.operation_type == "Create"
         assert 'Request headers:' in messages_request.msg
         assert 'A body is sent with the request' in messages_request.msg
-        assert messages_request.status_code == 409
+        assert messages_response.status_code == 409
         assert elapsed_time is not None
         assert "Response headers" in messages_response.msg
 
@@ -161,6 +183,49 @@ def test_cosmos_http_logging_policy(self):
 
         self.mock_handler_diagnostic.reset()
 
+    def test_filtered_diagnostics_logging_policy(self):
+        # Test if we can log errors with the filtered diagnostics logger
+        database_id = "database_test-" + str(uuid.uuid4())
+        container_id = "container_test-" + str(uuid.uuid4())
+        self.client_filtered_diagnostic.create_database(id=database_id)
+        database = self.client_filtered_diagnostic.get_database_client(database_id)
+        database.create_container(id=container_id, partition_key=PartitionKey(path="/pk"))
+
+        # Try to read an item that doesn't exist
+        try:
+            container = database.get_container_client(container_id)
+            container.read_item(item="nonexistent_item", partition_key="nonexistent_pk")
+        except:
+            pass
+
+        # Assert that the filtered logger only captured the error
+        request_log = self.mock_handler_filtered_diagnostic.messages[0]
+        response_log = self.mock_handler_filtered_diagnostic.messages[1]
+        assert response_log.status_code == 404
+        assert request_log.resource_type == "docs"
+        assert request_log.operation_type == "Read"
+        assert len(self.mock_handler_filtered_diagnostic.messages) == 2
+
+        self.mock_handler_filtered_diagnostic.reset()
+
+        # Try to create an item with an invalid partition key
+        try:
+            container.create_item(body={"FakeProperty": "item1", "NotPk": None})
+        except:
+            pass
+
+        # Assert that the filtered logger captured the error
+        request_log = self.mock_handler_filtered_diagnostic.messages[0]
+        response_log = self.mock_handler_filtered_diagnostic.messages[1]
+        assert response_log.status_code == 400
+        assert request_log.resource_type == "docs"
+        assert request_log.operation_type == "Create"
+        assert len(self.mock_handler_filtered_diagnostic.messages) == 2
+
+        # Clean up
+        self.client_filtered_diagnostic.delete_database(database_id)
+        self.mock_handler_filtered_diagnostic.reset()
+
     def test_client_settings(self):
         # Test data
         all_locations = [L1, L2]