From 7c76eaa7130dfebdc99f6f2c3b5cd2333501169b Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Mon, 5 Feb 2024 22:24:13 -0800 Subject: [PATCH 1/8] First pass --- .../connectors/saas/authenticated_client.py | 65 +++++++++++-------- .../api/service/connectors/saas_connector.py | 42 ++++++++++-- .../service/connectors/saas_query_config.py | 10 +-- 3 files changed, 80 insertions(+), 37 deletions(-) diff --git a/src/fides/api/service/connectors/saas/authenticated_client.py b/src/fides/api/service/connectors/saas/authenticated_client.py index 26450717f2..91212e3a88 100644 --- a/src/fides/api/service/connectors/saas/authenticated_client.py +++ b/src/fides/api/service/connectors/saas/authenticated_client.py @@ -5,7 +5,7 @@ import time from functools import wraps from time import sleep -from typing import TYPE_CHECKING, Any, Callable, List, Optional, Union +from typing import TYPE_CHECKING, Any, Callable, Dict, List, Optional, Union from urllib.parse import urlparse from loguru import logger @@ -214,15 +214,17 @@ def send( response = self.session.send(prepared_request) - log_request_and_response_for_debugging( - prepared_request, response - ) # Dev mode only + ignore_error = self._should_ignore_error( + status_code=response.status_code, errors_to_ignore=ignore_errors + ) + request_details = generate_request_details( + prepared_request, response, ignore_error + ) + if request_details is not None: + logger.bind(**request_details).info("Connector request details") if not response.ok: - if self._should_ignore_error( - status_code=response.status_code, - errors_to_ignore=ignore_errors, - ): + if ignore_error: logger.info( "Ignoring errors on response with status code {} as configured.", response.status_code, @@ -242,25 +244,6 @@ def __init__(self, response: Response): self.response = response -def log_request_and_response_for_debugging( - prepared_request: PreparedRequest, response: Response -) -> None: - """Log SaaS request and response in dev mode only""" - if CONFIG.dev_mode: - logger.info( - "\n\n-----------SAAS REQUEST-----------" - "\n{} {}" - "\nheaders: {}" - "\nbody: {}" - "\nresponse: {}", - prepared_request.method, - prepared_request.url, - prepared_request.headers, - prepared_request.body, - response._content, # pylint: disable=W0212 - ) - - def get_retry_after(response: Response, max_retry_after: int = 300) -> Optional[float]: """Given a Response object, parses Retry-After header and calculates how long we should sleep for""" retry_after = response.headers.get("Retry-After", None) @@ -283,3 +266,31 @@ def get_retry_after(response: Response, max_retry_after: int = 300) -> Optional[ seconds = max(seconds, 0) return min(seconds, max_retry_after) + + +def generate_request_details( + prepared_request: PreparedRequest, response: Response, ignore_error: bool +) -> Dict[str, Any]: + details = { + "status_code": response.status_code, + "method": prepared_request.method, + "url": prepared_request.url, + } + + # add body and response content if in dev mode and present + if CONFIG.dev_mode: + if prepared_request.body is not None: + details["body"] = prepared_request.body + if response.content: + details["response"] = response.content.decode("utf-8") + + # Assign error group only if error should not be ignored + if not ignore_error: + if response.status_code in [401, 403]: + details["error_group"] = "Authentication error" + elif 400 <= response.status_code < 500: + details["error_group"] = "Client error" + elif 500 <= response.status_code: + details["error_group"] = "Server error" + + return details diff --git a/src/fides/api/service/connectors/saas_connector.py b/src/fides/api/service/connectors/saas_connector.py index 50e55ca888..a33f2bc6d5 100644 --- a/src/fides/api/service/connectors/saas_connector.py +++ b/src/fides/api/service/connectors/saas_connector.py @@ -134,7 +134,13 @@ def test_connection(self) -> Optional[ConnectionTestStatus]: self.secrets, ) client: AuthenticatedClient = self.create_client() - client.send(prepared_request, test_request.ignore_errors) + with logger.contextualize( + system_id=( + self.configuration.system.id if self.configuration.system else None + ), + connection_key=self.configuration.key, + ): + client.send(prepared_request, test_request.ignore_errors) self.unset_connector_state() return ConnectionTestStatus.succeeded @@ -150,7 +156,7 @@ def create_client(self) -> AuthenticatedClient: client_config = self.get_client_config() rate_limit_config = self.get_rate_limit_config() - logger.info("Creating client to {}", uri) + logger.debug("Creating client to {}", uri) return AuthenticatedClient( uri, self.configuration, client_config, rate_limit_config ) @@ -284,7 +290,17 @@ def execute_prepared_request( """ client: AuthenticatedClient = self.create_client() - response: Response = client.send(prepared_request, saas_request.ignore_errors) + with logger.contextualize( + system_id=( + self.configuration.system.id if self.configuration.system else None + ), + connection_key=self.configuration.key, + collection=self.current_collection_name, + privacy_request_id=self.current_privacy_request.id, + ): + response: Response = client.send( + prepared_request, saas_request.ignore_errors + ) response = self._handle_errored_response(saas_request, response) response_data = self._unwrap_response_data(saas_request, response) @@ -433,7 +449,15 @@ def mask_data( ) continue raise exc - client.send(prepared_request, masking_request.ignore_errors) + with logger.contextualize( + system_id=( + self.configuration.system.id if self.configuration.system else None + ), + connection_key=self.configuration.key, + collection=self.current_collection_name, + privacy_request_id=self.current_privacy_request.id, + ): + client.send(prepared_request, masking_request.ignore_errors) rows_updated += 1 self.unset_connector_state() @@ -536,7 +560,15 @@ def run_consent_request( continue raise exc client: AuthenticatedClient = self.create_client() - client.send(prepared_request) + with logger.contextualize( + system_id=self.configuration.system.id + if self.configuration.system + else None, + connection_key=self.configuration.key, + collection=self.current_collection_name, + privacy_request_id=self.current_privacy_request.id, + ): + client.send(prepared_request) fired = True self.unset_connector_state() if not fired: diff --git a/src/fides/api/service/connectors/saas_query_config.py b/src/fides/api/service/connectors/saas_query_config.py index c29b4705da..535cb35a55 100644 --- a/src/fides/api/service/connectors/saas_query_config.py +++ b/src/fides/api/service/connectors/saas_query_config.py @@ -105,11 +105,11 @@ def get_erasure_request_by_action( self.endpoints[collection_name].requests, action ) if request: - logger.info( + logger.debug( "Found matching endpoint to {} '{}' collection", action, collection_name ) else: - logger.info( + logger.debug( "Unable to find matching endpoint to {} '{}' collection", action, collection_name, @@ -146,7 +146,7 @@ def get_masking_request(self) -> Optional[SaaSRequest]: # store action name for logging purposes self.action = action_type - logger.info( + logger.debug( "Selecting '{}' action to perform masking request for '{}' collection.", action_type, self.collection_name, @@ -319,7 +319,7 @@ def generate_query( self.action, self.collection_name, self.current_request, param_values # type: ignore ) - logger.info("Populated request params for {}", self.current_request.path) + logger.debug("Populated request params for {}", self.current_request.path) return saas_request_params @@ -450,7 +450,7 @@ def generate_update_request_params( self.action, self.collection_name, update_request, param_values # type: ignore ) - logger.info("Populated request params for {}", update_request.path) + logger.debug("Populated request params for {}", update_request.path) return saas_request_params def all_value_map(self, row: Row) -> Dict[str, Any]: From 6406671404a9212fb5a8e925763fea02933d78c4 Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Tue, 6 Feb 2024 11:34:39 -0800 Subject: [PATCH 2/8] Adding connection error handling + minor cleanup --- .../connectors/saas/authenticated_client.py | 66 +++++-------- .../api/service/connectors/saas_connector.py | 69 +++++--------- src/fides/api/util/logger_context_utils.py | 93 +++++++++++++++++++ 3 files changed, 138 insertions(+), 90 deletions(-) create mode 100644 src/fides/api/util/logger_context_utils.py diff --git a/src/fides/api/service/connectors/saas/authenticated_client.py b/src/fides/api/service/connectors/saas/authenticated_client.py index 91212e3a88..c3ba3a6fc2 100644 --- a/src/fides/api/service/connectors/saas/authenticated_client.py +++ b/src/fides/api/service/connectors/saas/authenticated_client.py @@ -5,7 +5,7 @@ import time from functools import wraps from time import sleep -from typing import TYPE_CHECKING, Any, Callable, Dict, List, Optional, Union +from typing import TYPE_CHECKING, Any, Callable, List, Optional, Union from urllib.parse import urlparse from loguru import logger @@ -21,6 +21,7 @@ RateLimiterPeriod, RateLimiterRequest, ) +from fides.api.util.logger_context_utils import exception_details, request_details from fides.api.util.saas_util import deny_unsafe_hosts from fides.config import CONFIG @@ -100,7 +101,7 @@ def retry_send( # type: ignore def decorator(func: Callable) -> Callable: @wraps(func) def result(*args: Any, **kwargs: Any) -> Response: - self = args[0] + self: AuthenticatedClient = args[0] last_exception: Optional[Union[BaseException, Exception]] = None for attempt in range(retry_count + 1): @@ -129,6 +130,9 @@ def result(*args: Any, **kwargs: Any) -> Response: last_exception = ConnectionException( f"Operational Error connecting to '{self.configuration.key}'{dev_mode_log}" ) + logger.bind(**exception_details(exc, self.uri)).error( + "Connector request failed." + ) # requests library can raise ConnectionError, Timeout or TooManyRedirects # we will not retry these as they don't usually point to intermittent issues break @@ -217,21 +221,25 @@ def send( ignore_error = self._should_ignore_error( status_code=response.status_code, errors_to_ignore=ignore_errors ) - request_details = generate_request_details( - prepared_request, response, ignore_error + context_logger = logger.bind( + **request_details(prepared_request, response, ignore_error) ) - if request_details is not None: - logger.bind(**request_details).info("Connector request details") - if not response.ok: - if ignore_error: - logger.info( - "Ignoring errors on response with status code {} as configured.", - response.status_code, - ) - return response - raise RequestFailureResponseException(response=response) - return response + if response.ok: + context_logger.info("Connector request successful.") + return response + + if ignore_error: + context_logger.info( + "Connector request successful. Ignoring errors on response with status code {} as configured.", + response.status_code, + ) + return response + + context_logger.error( + "Connector request failed with status code {}.", response.status_code + ) + raise RequestFailureResponseException(response=response) class RequestFailureResponseException(FidesopsException): @@ -266,31 +274,3 @@ def get_retry_after(response: Response, max_retry_after: int = 300) -> Optional[ seconds = max(seconds, 0) return min(seconds, max_retry_after) - - -def generate_request_details( - prepared_request: PreparedRequest, response: Response, ignore_error: bool -) -> Dict[str, Any]: - details = { - "status_code": response.status_code, - "method": prepared_request.method, - "url": prepared_request.url, - } - - # add body and response content if in dev mode and present - if CONFIG.dev_mode: - if prepared_request.body is not None: - details["body"] = prepared_request.body - if response.content: - details["response"] = response.content.decode("utf-8") - - # Assign error group only if error should not be ignored - if not ignore_error: - if response.status_code in [401, 403]: - details["error_group"] = "Authentication error" - elif 400 <= response.status_code < 500: - details["error_group"] = "Client error" - elif 500 <= response.status_code: - details["error_group"] = "Server error" - - return details diff --git a/src/fides/api/service/connectors/saas_connector.py b/src/fides/api/service/connectors/saas_connector.py index a33f2bc6d5..7e4af11d27 100644 --- a/src/fides/api/service/connectors/saas_connector.py +++ b/src/fides/api/service/connectors/saas_connector.py @@ -40,6 +40,7 @@ cache_initial_status_and_identities_for_consent_reporting, should_opt_in_to_service, ) +from fides.api.util.logger_context_utils import saas_connector_details from fides.api.util.saas_util import ( CUSTOM_PRIVACY_REQUEST_FIELDS, assign_placeholders, @@ -134,12 +135,7 @@ def test_connection(self) -> Optional[ConnectionTestStatus]: self.secrets, ) client: AuthenticatedClient = self.create_client() - with logger.contextualize( - system_id=( - self.configuration.system.id if self.configuration.system else None - ), - connection_key=self.configuration.key, - ): + with logger.contextualize(**saas_connector_details(self)): client.send(prepared_request, test_request.ignore_errors) self.unset_connector_state() return ConnectionTestStatus.succeeded @@ -181,9 +177,9 @@ def retrieve_data( # 2) The complete set of results for a collection is made up of subsets. For example, to retrieve all tickets # we must change a 'status' query param from 'active' to 'pending' and finally 'closed' read_requests: List[SaaSRequest] = query_config.get_read_requests_by_identity() - delete_request: Optional[ - SaaSRequest - ] = query_config.get_erasure_request_by_action("delete") + delete_request: Optional[SaaSRequest] = ( + query_config.get_erasure_request_by_action("delete") + ) if not read_requests: # if a delete request is specified for this endpoint without a read request @@ -290,14 +286,7 @@ def execute_prepared_request( """ client: AuthenticatedClient = self.create_client() - with logger.contextualize( - system_id=( - self.configuration.system.id if self.configuration.system else None - ), - connection_key=self.configuration.key, - collection=self.current_collection_name, - privacy_request_id=self.current_privacy_request.id, - ): + with logger.contextualize(**saas_connector_details(self)): response: Response = client.send( prepared_request, saas_request.ignore_errors ) @@ -449,14 +438,7 @@ def mask_data( ) continue raise exc - with logger.contextualize( - system_id=( - self.configuration.system.id if self.configuration.system else None - ), - connection_key=self.configuration.key, - collection=self.current_collection_name, - privacy_request_id=self.current_privacy_request.id, - ): + with logger.contextualize(**saas_connector_details(self)): client.send(prepared_request, masking_request.ignore_errors) rows_updated += 1 @@ -513,9 +495,9 @@ def run_consent_request( f"Skipping consent propagation for node {node.address.value} - no actionable consent preferences to propagate" ) - matching_consent_requests: List[ - SaaSRequest - ] = self._get_consent_requests_by_preference(should_opt_in) + matching_consent_requests: List[SaaSRequest] = ( + self._get_consent_requests_by_preference(should_opt_in) + ) query_config.action = ( "opt_in" if should_opt_in else "opt_out" @@ -560,14 +542,7 @@ def run_consent_request( continue raise exc client: AuthenticatedClient = self.create_client() - with logger.contextualize( - system_id=self.configuration.system.id - if self.configuration.system - else None, - connection_key=self.configuration.key, - collection=self.current_collection_name, - privacy_request_id=self.current_privacy_request.id, - ): + with logger.contextualize(**saas_connector_details(self)): client.send(prepared_request) fired = True self.unset_connector_state() @@ -632,10 +607,10 @@ def _invoke_read_request_override( Contains error handling for uncaught exceptions coming out of the override. """ - override_function: Callable[ - ..., Union[List[Row], int] - ] = SaaSRequestOverrideFactory.get_override( - override_function_name, SaaSRequestType.READ + override_function: Callable[..., Union[List[Row], int]] = ( + SaaSRequestOverrideFactory.get_override( + override_function_name, SaaSRequestType.READ + ) ) try: return override_function( @@ -672,10 +647,10 @@ def _invoke_masking_request_override( Includes the necessary data preparations for override input and has error handling for uncaught exceptions coming out of the override """ - override_function: Callable[ - ..., Union[List[Row], int] - ] = SaaSRequestOverrideFactory.get_override( - override_function_name, SaaSRequestType(query_config.action) + override_function: Callable[..., Union[List[Row], int]] = ( + SaaSRequestOverrideFactory.get_override( + override_function_name, SaaSRequestType(query_config.action) + ) ) try: # if using a saas override, we still need to use the core framework @@ -704,9 +679,9 @@ def _invoke_masking_request_override( def _get_consent_requests_by_preference(self, opt_in: bool) -> List[SaaSRequest]: """Helper to either pull out the opt-in requests or the opt out requests that were defined.""" - consent_requests: Optional[ - ConsentRequestMap - ] = self.saas_config.consent_requests + consent_requests: Optional[ConsentRequestMap] = ( + self.saas_config.consent_requests + ) if not consent_requests: return [] diff --git a/src/fides/api/util/logger_context_utils.py b/src/fides/api/util/logger_context_utils.py new file mode 100644 index 0000000000..5fbfb3445f --- /dev/null +++ b/src/fides/api/util/logger_context_utils.py @@ -0,0 +1,93 @@ +from enum import Enum +from typing import TYPE_CHECKING, Any, Dict, Optional + +from requests import PreparedRequest, Response +from requests.exceptions import ( # pylint: disable=redefined-builtin + ConnectionError, + ConnectTimeout, + ReadTimeout, + SSLError, + TooManyRedirects, +) + +if TYPE_CHECKING: + from fides.api.service.connectors.saas_connector import SaaSConnector + +from fides.config import CONFIG + + +class ErrorGroup(Enum): + """A collection of user-friendly error labels to be used in contextualized logs.""" + + network_error = "Network/protocol error" + authentication_error = "Authentication error" + client_error = "Client-side error" + server_error = "Server-side error" + + +def saas_connector_details(connector: "SaaSConnector") -> Dict[str, Any]: + """Maps the system and connection info details. Includes the collection and privacy request ID if available.""" + + details = { + "system_id": ( + connector.configuration.system.id + if connector.configuration.system + else None + ), + "connection_key": connector.configuration.key, + } + if connector.current_collection_name: + details["collection"] = connector.current_collection_name + if connector.current_privacy_request: + details["privacy_request_id"] = connector.current_privacy_request.id + return details + + +def request_details( + prepared_request: PreparedRequest, + response: Optional[Response] = None, + ignore_error: bool = False, +) -> Dict[str, Any]: + """Maps the request details and includes response details when "dev mode" is enabled.""" + + details = { + "method": prepared_request.method, + "url": prepared_request.url, + } + if CONFIG.dev_mode and prepared_request.body is not None: + details["body"] = prepared_request.body + + if response is not None: + if CONFIG.dev_mode and response.content: + details["response"] = response.content.decode("utf-8") + + details["status_code"] = response.status_code + + # assign error group only if error should not be ignored + if not ignore_error: + if response.status_code in [401, 403]: + details["error_group"] = ErrorGroup.authentication_error.value + elif 400 <= response.status_code < 500: + details["error_group"] = ErrorGroup.client_error.value + elif 500 <= response.status_code: + details["error_group"] = ErrorGroup.server_error.value + return details + + +def exception_details(exception: Exception, url: str) -> Dict[str, Any]: + """Maps select connection exceptions to user-friendly error details.""" + + details = {"error_group": ErrorGroup.network_error.value} + if isinstance(exception, ConnectTimeout): + details["error_details"] = f"Timeout occurred connecting to {url}." + elif isinstance(exception, ReadTimeout): + details["error_details"] = ( + f"Timeout occurred waiting for a response from {url}." + ) + elif isinstance(exception, SSLError): + details["error_details"] = f"SSL exception occurred connecting to {url}." + elif isinstance(exception, TooManyRedirects): + details["error_details"] = f"Too many redirects occurred connecting to {url}." + elif isinstance(exception, ConnectionError): + details["error_details"] = f"Unable to connect to {url}." + return details From cfdc47d41260daece3afae41622ed6696ef711aa Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Fri, 9 Feb 2024 13:49:31 -0800 Subject: [PATCH 3/8] Adding test --- .../api/service/connectors/saas_connector.py | 13 +- src/fides/api/util/logger_context_utils.py | 13 +- tests/conftest.py | 2 +- .../saas/connector_runner.py | 29 +++- .../test_privacy_request_logging.py | 162 ++++++++++++++++++ 5 files changed, 205 insertions(+), 14 deletions(-) create mode 100644 tests/ops/integration_tests/test_privacy_request_logging.py diff --git a/src/fides/api/service/connectors/saas_connector.py b/src/fides/api/service/connectors/saas_connector.py index 7e4af11d27..bd3dd7d4fd 100644 --- a/src/fides/api/service/connectors/saas_connector.py +++ b/src/fides/api/service/connectors/saas_connector.py @@ -16,6 +16,7 @@ from fides.api.models.policy import Policy from fides.api.models.privacy_request import PrivacyRequest from fides.api.schemas.limiter.rate_limit_config import RateLimitConfig +from fides.api.schemas.policy import ActionType from fides.api.schemas.saas.saas_config import ( ClientConfig, ConsentRequestMap, @@ -286,7 +287,9 @@ def execute_prepared_request( """ client: AuthenticatedClient = self.create_client() - with logger.contextualize(**saas_connector_details(self)): + with logger.contextualize( + **saas_connector_details(self, action_type=ActionType.access) + ): response: Response = client.send( prepared_request, saas_request.ignore_errors ) @@ -438,7 +441,9 @@ def mask_data( ) continue raise exc - with logger.contextualize(**saas_connector_details(self)): + with logger.contextualize( + **saas_connector_details(self, action_type=ActionType.erasure) + ): client.send(prepared_request, masking_request.ignore_errors) rows_updated += 1 @@ -542,7 +547,9 @@ def run_consent_request( continue raise exc client: AuthenticatedClient = self.create_client() - with logger.contextualize(**saas_connector_details(self)): + with logger.contextualize( + **saas_connector_details(self, action_type=ActionType.consent) + ): client.send(prepared_request) fired = True self.unset_connector_state() diff --git a/src/fides/api/util/logger_context_utils.py b/src/fides/api/util/logger_context_utils.py index 5fbfb3445f..5796c1caf6 100644 --- a/src/fides/api/util/logger_context_utils.py +++ b/src/fides/api/util/logger_context_utils.py @@ -10,6 +10,8 @@ TooManyRedirects, ) +from fides.api.schemas.policy import ActionType + if TYPE_CHECKING: from fides.api.service.connectors.saas_connector import SaaSConnector @@ -25,17 +27,22 @@ class ErrorGroup(Enum): server_error = "Server-side error" -def saas_connector_details(connector: "SaaSConnector") -> Dict[str, Any]: +def saas_connector_details( + connector: "SaaSConnector", + action_type: Optional[ActionType], +) -> Dict[str, Any]: """Maps the system and connection info details. Includes the collection and privacy request ID if available.""" details = { - "system_id": ( - connector.configuration.system.id + "system_key": ( + connector.configuration.system.fides_key if connector.configuration.system else None ), "connection_key": connector.configuration.key, } + if action_type: + details["action_type"] = action_type.value if connector.current_collection_name: details["collection"] = connector.current_collection_name if connector.current_privacy_request: diff --git a/tests/conftest.py b/tests/conftest.py index 02777a57b4..66a114ad8c 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -218,7 +218,7 @@ def enable_override_vendor_purposes_api_set(db): @pytest.fixture def loguru_caplog(caplog): - handler_id = logger.add(caplog.handler, format="{message}") + handler_id = logger.add(caplog.handler, format="{message} | {extra}") yield caplog logger.remove(handler_id) diff --git a/tests/ops/integration_tests/saas/connector_runner.py b/tests/ops/integration_tests/saas/connector_runner.py index 960162a645..143d5d3e99 100644 --- a/tests/ops/integration_tests/saas/connector_runner.py +++ b/tests/ops/integration_tests/saas/connector_runner.py @@ -90,11 +90,15 @@ async def access_request( self, access_policy: Policy, identities: Dict[str, Any], + privacy_request_id: Optional[str] = None, ) -> Dict[str, List[Row]]: """Access request for a given access policy and identities""" fides_key = self.connection_config.key privacy_request = PrivacyRequest( - id=f"test_{fides_key}_access_request_{random.randint(0, 1000)}" + id=( + privacy_request_id + or f"test_{fides_key}_access_request_{random.randint(0, 1000)}" + ) ) identity = Identity(**identities) privacy_request.cache_identity(identity) @@ -131,6 +135,7 @@ async def strict_erasure_request( access_policy: Policy, erasure_policy: Policy, identities: Dict[str, Any], + privacy_request_id: Optional[str] = None, ) -> Tuple[Dict, Dict]: """ Erasure request with masking_strict set to true, @@ -142,7 +147,7 @@ async def strict_erasure_request( CONFIG.execution.masking_strict = True access_results, erasure_results = await self._base_erasure_request( - access_policy, erasure_policy, identities + access_policy, erasure_policy, identities, privacy_request_id ) # reset masking_strict value @@ -154,6 +159,7 @@ async def non_strict_erasure_request( access_policy: Policy, erasure_policy: Policy, identities: Dict[str, Any], + privacy_request_id: Optional[str] = None, ) -> Tuple[Dict, Dict]: """ Erasure request with masking_strict set to false, @@ -166,7 +172,7 @@ async def non_strict_erasure_request( CONFIG.execution.masking_strict = False access_results, erasure_results = await self._base_erasure_request( - access_policy, erasure_policy, identities + access_policy, erasure_policy, identities, privacy_request_id ) # reset masking_strict value @@ -215,13 +221,19 @@ async def old_consent_request( return {"opt_in": opt_in.popitem()[1], "opt_out": opt_out.popitem()[1]} async def new_consent_request( - self, consent_policy: Policy, identities: Dict[str, Any] + self, + consent_policy: Policy, + identities: Dict[str, Any], + privacy_request_id: Optional[str] = None, ): """ Consent requests using privacy preference history (new workflow) """ privacy_request = PrivacyRequest( - id=f"test_{self.connection_config.key}_new_consent_request_{random.randint(0, 1000)}", + id=( + privacy_request_id + or f"test_{self.connection_config.key}_new_consent_request_{random.randint(0, 1000)}" + ), status=PrivacyRequestStatus.pending, ) privacy_request.save(self.db) @@ -256,10 +268,14 @@ async def _base_erasure_request( access_policy: Policy, erasure_policy: Policy, identities: Dict[str, Any], + privacy_request_id: Optional[str] = None, ) -> Tuple[Dict, Dict]: fides_key = self.connection_config.key privacy_request = PrivacyRequest( - id=f"test_{fides_key}_access_request_{random.randint(0, 1000)}" + id=( + privacy_request_id + or f"test_{fides_key}_access_request_{random.randint(0, 1000)}" + ) ) identity = Identity(**identities) privacy_request.cache_identity(identity) @@ -413,7 +429,6 @@ def _privacy_preference_history( "privacy_request_id": privacy_request.id, "preference": "opt_in" if opt_in else "opt_out", "privacy_notice_history_id": privacy_notice.histories[0].id, - "provided_identity_id": provided_identity.id, }, check_name=False, ) diff --git a/tests/ops/integration_tests/test_privacy_request_logging.py b/tests/ops/integration_tests/test_privacy_request_logging.py new file mode 100644 index 0000000000..f26ef02560 --- /dev/null +++ b/tests/ops/integration_tests/test_privacy_request_logging.py @@ -0,0 +1,162 @@ +from typing import Generator +from unittest import mock + +import pytest +from requests import Response + +from fides.api.common_exceptions import ClientUnsuccessfulException +from fides.api.util.logger_context_utils import ErrorGroup +from fides.common.api.scope_registry import PRIVACY_REQUEST_CREATE +from fides.common.api.v1.urn_registry import PRIVACY_REQUESTS, V1_URL_PREFIX +from fides.config import CONFIG + + +@pytest.mark.integration_saas +class TestPrivacyRequestLogging: + """ + This test sets up the necessary connection configs (using the *_runner fixtures) + to test an access, erasure, and consent connector. It then creates access, erasure, + and consent privacy requests to verify that the contextualized logs are being + output correctly for each action type. + """ + + @pytest.fixture + def url(self) -> str: + return V1_URL_PREFIX + PRIVACY_REQUESTS + + @pytest.fixture + def mock_send(self) -> Generator: + with mock.patch( + "fides.api.service.connectors.saas.authenticated_client.Session.send" + ) as mock_send: + mock_response = Response() + mock_response.status_code = 401 + mock_send.return_value = mock_response + yield mock_send + + @pytest.mark.usefixtures("zendesk_runner") + def test_access_error_logs( + self, + mock_send, + api_client, + url, + generate_auth_header, + policy, + loguru_caplog, + provided_identity_value, + ): + response = api_client.post( + url, + headers=generate_auth_header(scopes=[PRIVACY_REQUEST_CREATE]), + json=[ + { + "policy_key": policy.key, + "identity": {"email": provided_identity_value}, + } + ], + ) + + privacy_request = response.json()["succeeded"][0] + + extra = { + "system_key": None, + "connection_key": "zendesk_instance", + "action_type": "access", + "collection": "user", + "privacy_request_id": privacy_request["id"], + "method": "GET", + "url": "https://ethyca-test.zendesk.com/api/v2/users/search.json?query=test%40example.com", + "status_code": 401, + "error_group": ErrorGroup.authentication_error.value, + } + + assert ( + f"Connector request failed with status code 401. | {str(extra)}" + in loguru_caplog.text + ) + + @pytest.mark.usefixtures("typeform_runner") + async def test_erasure_error_logs( + self, + mock_send, + api_client, + url, + generate_auth_header, + erasure_policy, + loguru_caplog, + typeform_secrets, + provided_identity_value, + ): + masking_strict = CONFIG.execution.masking_strict + CONFIG.execution.masking_strict = False + + response = api_client.post( + url, + headers=generate_auth_header(scopes=[PRIVACY_REQUEST_CREATE]), + json=[ + { + "policy_key": erasure_policy.key, + "identity": {"email": provided_identity_value}, + } + ], + ) + + privacy_request = response.json()["succeeded"][0] + + extra = { + "system_key": None, + "connection_key": "typeform_instance", + "action_type": "erasure", + "collection": "user", + "privacy_request_id": privacy_request["id"], + "method": "DELETE", + "url": f"https://api.typeform.com/rtbf/{typeform_secrets['account_id']}/responses", + "body": '["test@example.com"]\n', + "status_code": 401, + "error_group": ErrorGroup.authentication_error.value, + } + + assert ( + f"Connector request failed with status code 401. | {str(extra)}" + in loguru_caplog.text + ) + + CONFIG.execution.masking_strict = masking_strict + + @pytest.mark.usefixtures("klaviyo_runner") + async def test_consent_error_logs( + self, + mock_send, + klaviyo_runner, + api_client, + url, + generate_auth_header, + consent_policy, + provided_identity_and_consent_request, + loguru_caplog, + provided_identity_value, + ): + with pytest.raises(ClientUnsuccessfulException): + await klaviyo_runner.new_consent_request( + consent_policy, + {"email": provided_identity_value}, + privacy_request_id="123", + ) + + extra = { + "system_key": None, + "connection_key": "klaviyo_instance", + "action_type": "consent", + "collection": "klaviyo_instance", + "privacy_request_id": "123", + "method": "POST", + "url": "https://a.klaviyo.com/api/profile-suppression-bulk-delete-jobs/", + "body": '{\n "data": {\n "type": "profile-suppression-bulk-delete-job",\n "attributes": {\n "profiles": {\n "data": [\n {\n "type": "profile",\n "attributes": {\n "email": "test@email.com"\n }\n }\n ]\n }\n }\n }\n}\n', + "status_code": 401, + "error_group": ErrorGroup.authentication_error.value, + } + + assert ( + f"Connector request failed with status code 401. | {str(extra)}" + in loguru_caplog.text + ) From 448a9ef297ee499a5263426cf041f8e87144eda7 Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Fri, 9 Feb 2024 15:39:56 -0800 Subject: [PATCH 4/8] Adding unit tests --- .../connectors/saas/authenticated_client.py | 11 +- .../api/service/connectors/saas_connector.py | 34 ++--- src/fides/api/util/logger_context_utils.py | 14 +- tests/ops/util/test_logger_context_utils.py | 128 ++++++++++++++++++ 4 files changed, 160 insertions(+), 27 deletions(-) create mode 100644 tests/ops/util/test_logger_context_utils.py diff --git a/src/fides/api/service/connectors/saas/authenticated_client.py b/src/fides/api/service/connectors/saas/authenticated_client.py index c3ba3a6fc2..8a8626c110 100644 --- a/src/fides/api/service/connectors/saas/authenticated_client.py +++ b/src/fides/api/service/connectors/saas/authenticated_client.py @@ -21,7 +21,10 @@ RateLimiterPeriod, RateLimiterRequest, ) -from fides.api.util.logger_context_utils import exception_details, request_details +from fides.api.util.logger_context_utils import ( + connection_exception_details, + request_details, +) from fides.api.util.saas_util import deny_unsafe_hosts from fides.config import CONFIG @@ -130,9 +133,9 @@ def result(*args: Any, **kwargs: Any) -> Response: last_exception = ConnectionException( f"Operational Error connecting to '{self.configuration.key}'{dev_mode_log}" ) - logger.bind(**exception_details(exc, self.uri)).error( - "Connector request failed." - ) + logger.bind( + **connection_exception_details(exc, self.uri) + ).error("Connector request failed.") # requests library can raise ConnectionError, Timeout or TooManyRedirects # we will not retry these as they don't usually point to intermittent issues break diff --git a/src/fides/api/service/connectors/saas_connector.py b/src/fides/api/service/connectors/saas_connector.py index bd3dd7d4fd..e76d4dd1df 100644 --- a/src/fides/api/service/connectors/saas_connector.py +++ b/src/fides/api/service/connectors/saas_connector.py @@ -178,9 +178,9 @@ def retrieve_data( # 2) The complete set of results for a collection is made up of subsets. For example, to retrieve all tickets # we must change a 'status' query param from 'active' to 'pending' and finally 'closed' read_requests: List[SaaSRequest] = query_config.get_read_requests_by_identity() - delete_request: Optional[SaaSRequest] = ( - query_config.get_erasure_request_by_action("delete") - ) + delete_request: Optional[ + SaaSRequest + ] = query_config.get_erasure_request_by_action("delete") if not read_requests: # if a delete request is specified for this endpoint without a read request @@ -500,9 +500,9 @@ def run_consent_request( f"Skipping consent propagation for node {node.address.value} - no actionable consent preferences to propagate" ) - matching_consent_requests: List[SaaSRequest] = ( - self._get_consent_requests_by_preference(should_opt_in) - ) + matching_consent_requests: List[ + SaaSRequest + ] = self._get_consent_requests_by_preference(should_opt_in) query_config.action = ( "opt_in" if should_opt_in else "opt_out" @@ -614,10 +614,10 @@ def _invoke_read_request_override( Contains error handling for uncaught exceptions coming out of the override. """ - override_function: Callable[..., Union[List[Row], int]] = ( - SaaSRequestOverrideFactory.get_override( - override_function_name, SaaSRequestType.READ - ) + override_function: Callable[ + ..., Union[List[Row], int] + ] = SaaSRequestOverrideFactory.get_override( + override_function_name, SaaSRequestType.READ ) try: return override_function( @@ -654,10 +654,10 @@ def _invoke_masking_request_override( Includes the necessary data preparations for override input and has error handling for uncaught exceptions coming out of the override """ - override_function: Callable[..., Union[List[Row], int]] = ( - SaaSRequestOverrideFactory.get_override( - override_function_name, SaaSRequestType(query_config.action) - ) + override_function: Callable[ + ..., Union[List[Row], int] + ] = SaaSRequestOverrideFactory.get_override( + override_function_name, SaaSRequestType(query_config.action) ) try: # if using a saas override, we still need to use the core framework @@ -686,9 +686,9 @@ def _invoke_masking_request_override( def _get_consent_requests_by_preference(self, opt_in: bool) -> List[SaaSRequest]: """Helper to either pull out the opt-in requests or the opt out requests that were defined.""" - consent_requests: Optional[ConsentRequestMap] = ( - self.saas_config.consent_requests - ) + consent_requests: Optional[ + ConsentRequestMap + ] = self.saas_config.consent_requests if not consent_requests: return [] diff --git a/src/fides/api/util/logger_context_utils.py b/src/fides/api/util/logger_context_utils.py index 5796c1caf6..9e6f17add3 100644 --- a/src/fides/api/util/logger_context_utils.py +++ b/src/fides/api/util/logger_context_utils.py @@ -11,12 +11,11 @@ ) from fides.api.schemas.policy import ActionType +from fides.config import CONFIG if TYPE_CHECKING: from fides.api.service.connectors.saas_connector import SaaSConnector -from fides.config import CONFIG - class ErrorGroup(Enum): """A collection of user-friendly error labels to be used in contextualized logs.""" @@ -29,7 +28,7 @@ class ErrorGroup(Enum): def saas_connector_details( connector: "SaaSConnector", - action_type: Optional[ActionType], + action_type: Optional[ActionType] = None, ) -> Dict[str, Any]: """Maps the system and connection info details. Includes the collection and privacy request ID if available.""" @@ -57,7 +56,7 @@ def request_details( ) -> Dict[str, Any]: """Maps the request details and includes response details when "dev mode" is enabled.""" - details = { + details: Dict[str, Any] = { "method": prepared_request.method, "url": prepared_request.url, } @@ -81,10 +80,13 @@ def request_details( return details -def exception_details(exception: Exception, url: str) -> Dict[str, Any]: +def connection_exception_details(exception: Exception, url: str) -> Dict[str, Any]: """Maps select connection exceptions to user-friendly error details.""" - details = {"error_group": ErrorGroup.network_error.value} + details = { + "error_group": ErrorGroup.network_error.value, + "error_details": f"Unknown exception connecting to {url}.", + } if isinstance(exception, ConnectTimeout): details["error_details"] = f"Timeout occurred connecting to {url}." elif isinstance(exception, ReadTimeout): diff --git a/tests/ops/util/test_logger_context_utils.py b/tests/ops/util/test_logger_context_utils.py new file mode 100644 index 0000000000..e6e7e2eaf1 --- /dev/null +++ b/tests/ops/util/test_logger_context_utils.py @@ -0,0 +1,128 @@ +import pytest +from requests import PreparedRequest, Request, Response + +from fides.api.models.privacy_request import PrivacyRequest +from fides.api.schemas.policy import ActionType +from fides.api.service.connectors.saas_connector import SaaSConnector +from fides.api.util.logger_context_utils import ( + ErrorGroup, + request_details, + saas_connector_details, +) + + +class TestLoggerContestUtils: + @pytest.fixture + def prepared_request(self) -> PreparedRequest: + return Request( + method="POST", + url="https://test/users", + headers={"Content-type": "application/json"}, + params={"a": "b"}, + data={"name": "test"}, + ).prepare() + + def test_saas_connector_details(self, saas_example_connection_config, system): + saas_example_connection_config.system_id = system.id + connector = SaaSConnector(saas_example_connection_config) + connector.current_collection_name = "customer" + connector.current_privacy_request = PrivacyRequest(id="123") + assert saas_connector_details(connector, action_type=ActionType.access) == { + "system_key": system.fides_key, + "connection_key": "saas_connector_example", + "action_type": "access", + "collection": "customer", + "privacy_request_id": "123", + } + + def test_request_details(self, prepared_request): + response = Response() + response.status_code = 200 + response._content = "test response".encode() + + assert request_details(prepared_request, response) == { + "method": "POST", + "url": "https://test/users?a=b", + "body": "name=test", + "response": "test response", + "status_code": 200, + } + + @pytest.mark.usefixtures("test_config_dev_mode_disabled") + def test_request_details_dev_mode_disabled(self, prepared_request): + response = Response() + response.status_code = 200 + response._content = "test response".encode() + + assert request_details(prepared_request, response) == { + "method": "POST", + "url": "https://test/users?a=b", + "status_code": 200, + } + + @pytest.mark.parametrize( + "ignore_error, status_code, error_group", + [ + (True, 401, ErrorGroup.authentication_error.value), + (True, 403, ErrorGroup.authentication_error.value), + (True, 400, ErrorGroup.client_error.value), + (True, 500, ErrorGroup.server_error.value), + (False, 401, ErrorGroup.authentication_error.value), + (False, 403, ErrorGroup.authentication_error.value), + (False, 400, ErrorGroup.client_error.value), + (False, 500, ErrorGroup.server_error.value), + ], + ) + def test_request_details_with_errors( + self, ignore_error, status_code, error_group, prepared_request + ): + response = Response() + response.status_code = status_code + response._content = "test response".encode() + + expected_detail = { + "method": "POST", + "url": "https://test/users?a=b", + "body": "name=test", + "response": "test response", + "status_code": status_code, + } + if not ignore_error: + expected_detail["error_group"] = error_group + + assert ( + request_details(prepared_request, response, ignore_error) == expected_detail + ) + + @pytest.mark.parametrize( + "ignore_error, status_code, error_group", + [ + (True, 401, ErrorGroup.authentication_error.value), + (True, 403, ErrorGroup.authentication_error.value), + (True, 400, ErrorGroup.client_error.value), + (True, 500, ErrorGroup.server_error.value), + (False, 401, ErrorGroup.authentication_error.value), + (False, 403, ErrorGroup.authentication_error.value), + (False, 400, ErrorGroup.client_error.value), + (False, 500, ErrorGroup.server_error.value), + ], + ) + @pytest.mark.usefixtures("test_config_dev_mode_disabled") + def test_request_details_with_errors_dev_mode_disabled( + self, ignore_error, status_code, error_group, prepared_request + ): + response = Response() + response.status_code = status_code + response._content = "test response".encode() + + expected_detail = { + "method": "POST", + "url": "https://test/users?a=b", + "status_code": status_code, + } + if not ignore_error: + expected_detail["error_group"] = error_group + + assert ( + request_details(prepared_request, response, ignore_error) == expected_detail + ) From 21398a95922a7e8de3c56c4a9000e264f6d5a74a Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Fri, 9 Feb 2024 15:46:27 -0800 Subject: [PATCH 5/8] Adding enum for logger context keys --- src/fides/api/util/logger_context_utils.py | 42 ++++++++++++++++------ 1 file changed, 31 insertions(+), 11 deletions(-) diff --git a/src/fides/api/util/logger_context_utils.py b/src/fides/api/util/logger_context_utils.py index 9e6f17add3..0232cc6a58 100644 --- a/src/fides/api/util/logger_context_utils.py +++ b/src/fides/api/util/logger_context_utils.py @@ -17,6 +17,12 @@ from fides.api.service.connectors.saas_connector import SaaSConnector +class LoggerContextKeys(Enum): + privacy_request_id = "privacy_request_id" + error_group = "error_group" + error_details = "error_details" + + class ErrorGroup(Enum): """A collection of user-friendly error labels to be used in contextualized logs.""" @@ -45,7 +51,9 @@ def saas_connector_details( if connector.current_collection_name: details["collection"] = connector.current_collection_name if connector.current_privacy_request: - details["privacy_request_id"] = connector.current_privacy_request.id + details[LoggerContextKeys.privacy_request_id.value] = ( + connector.current_privacy_request.id + ) return details @@ -72,11 +80,17 @@ def request_details( # assign error group only if error should not be ignored if not ignore_error: if response.status_code in [401, 403]: - details["error_group"] = ErrorGroup.authentication_error.value + details[LoggerContextKeys.error_group.value] = ( + ErrorGroup.authentication_error.value + ) elif 400 <= response.status_code < 500: - details["error_group"] = ErrorGroup.client_error.value + details[LoggerContextKeys.error_group.value] = ( + ErrorGroup.client_error.value + ) elif 500 <= response.status_code: - details["error_group"] = ErrorGroup.server_error.value + details[LoggerContextKeys.error_group.value] = ( + ErrorGroup.server_error.value + ) return details @@ -84,19 +98,25 @@ def connection_exception_details(exception: Exception, url: str) -> Dict[str, An """Maps select connection exceptions to user-friendly error details.""" details = { - "error_group": ErrorGroup.network_error.value, - "error_details": f"Unknown exception connecting to {url}.", + LoggerContextKeys.error_group.value: ErrorGroup.network_error.value, + LoggerContextKeys.error_details.value: f"Unknown exception connecting to {url}.", } if isinstance(exception, ConnectTimeout): - details["error_details"] = f"Timeout occurred connecting to {url}." + details[LoggerContextKeys.error_details.value] = ( + f"Timeout occurred connecting to {url}." + ) elif isinstance(exception, ReadTimeout): - details["error_details"] = ( + details[LoggerContextKeys.error_details.value] = ( f"Timeout occurred waiting for a response from {url}." ) elif isinstance(exception, SSLError): - details["error_details"] = f"SSL exception occurred connecting to {url}." + details[LoggerContextKeys.error_details.value] = ( + f"SSL exception occurred connecting to {url}." + ) elif isinstance(exception, TooManyRedirects): - details["error_details"] = f"Too many redirects occurred connecting to {url}." + details[LoggerContextKeys.error_details.value] = ( + f"Too many redirects occurred connecting to {url}." + ) elif isinstance(exception, ConnectionError): - details["error_details"] = f"Unable to connect to {url}." + details[LoggerContextKeys.error_details.value] = f"Unable to connect to {url}." return details From 8dcda3e196f85d2e5a230631c827abf3cbeaee6d Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Tue, 13 Feb 2024 13:02:35 -0800 Subject: [PATCH 6/8] Finalizing implementation --- src/fides/api/graph/traversal.py | 6 +- src/fides/api/models/privacy_request.py | 9 +- .../api/service/connectors/saas_connector.py | 44 ++--- src/fides/api/util/logger_context_utils.py | 161 +++++++++++------- .../test_privacy_request_logging.py | 20 +-- tests/ops/util/test_logger_context_utils.py | 84 +++++++-- 6 files changed, 212 insertions(+), 112 deletions(-) diff --git a/src/fides/api/graph/traversal.py b/src/fides/api/graph/traversal.py index 7d99520376..fddd39a9b3 100644 --- a/src/fides/api/graph/traversal.py +++ b/src/fides/api/graph/traversal.py @@ -17,13 +17,14 @@ ) from fides.api.graph.graph import DatasetGraph, Edge, Node from fides.api.util.collection_util import Row, append +from fides.api.util.logger_context_utils import Contextualizable, LoggerContextKeys from fides.api.util.matching_queue import MatchingQueue Datastore = Dict[CollectionAddress, List[Row]] """A type expressing retrieved rows of data from a specified collection""" -class TraversalNode: +class TraversalNode(Contextualizable): """Base traversal traversal_node type. This type will never be used directly.""" def __init__(self, node: Node): @@ -161,6 +162,9 @@ def debug(self) -> Dict[str, Any]: "to": {k: set(v) for k, v in to.items()}, } + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + return {LoggerContextKeys.collection: self.node.collection.name} + def artificial_traversal_node(address: CollectionAddress) -> TraversalNode: """generate an 'artificial' traversal_node pointing to the given address. This is used to diff --git a/src/fides/api/models/privacy_request.py b/src/fides/api/models/privacy_request.py index 346f2ada20..d94618194e 100644 --- a/src/fides/api/models/privacy_request.py +++ b/src/fides/api/models/privacy_request.py @@ -65,6 +65,7 @@ from fides.api.util.cache import ( FidesopsRedis, get_all_cache_keys_for_privacy_request, + get_all_masking_secret_cache_keys_for_privacy_request, get_async_task_tracking_cache_key, get_cache, get_custom_privacy_request_field_cache_key, @@ -76,6 +77,7 @@ from fides.api.util.collection_util import Row from fides.api.util.constants import API_DATE_FORMAT from fides.api.util.identity_verification import IdentityVerificationMixin +from fides.api.util.logger_context_utils import Contextualizable, LoggerContextKeys from fides.common.api.scope_registry import PRIVACY_REQUEST_CALLBACK_RESUME from fides.config import CONFIG @@ -181,7 +183,9 @@ def generate_request_callback_jwe(webhook: PolicyPreWebhook) -> str: ) -class PrivacyRequest(IdentityVerificationMixin, Base): # pylint: disable=R0904 +class PrivacyRequest( + IdentityVerificationMixin, Contextualizable, Base +): # pylint: disable=R0904 """ The DB ORM model to describe current and historic PrivacyRequests. A privacy request is a database record representing the request's @@ -950,6 +954,9 @@ def error_processing(self, db: Session) -> None: db=db, data={"message_sent": False, "privacy_request_id": self.id} ) + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + return {LoggerContextKeys.privacy_request_id: self.id} + class PrivacyRequestError(Base): """The DB ORM model to track PrivacyRequests error message status.""" diff --git a/src/fides/api/service/connectors/saas_connector.py b/src/fides/api/service/connectors/saas_connector.py index e76d4dd1df..195f97b73f 100644 --- a/src/fides/api/service/connectors/saas_connector.py +++ b/src/fides/api/service/connectors/saas_connector.py @@ -41,7 +41,11 @@ cache_initial_status_and_identities_for_consent_reporting, should_opt_in_to_service, ) -from fides.api.util.logger_context_utils import saas_connector_details +from fides.api.util.logger_context_utils import ( + Contextualizable, + LoggerContextKeys, + log_context, +) from fides.api.util.saas_util import ( CUSTOM_PRIVACY_REQUEST_FIELDS, assign_placeholders, @@ -49,9 +53,19 @@ ) -class SaaSConnector(BaseConnector[AuthenticatedClient]): +class SaaSConnector(BaseConnector[AuthenticatedClient], Contextualizable): """A connector type to integrate with third-party SaaS APIs""" + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + return { + LoggerContextKeys.system_key: ( + self.configuration.system.fides_key + if self.configuration.system + else None + ), + LoggerContextKeys.connection_key: self.configuration.key, + } + def __init__(self, configuration: ConnectionConfig): super().__init__(configuration) required_saas_config = configuration.get_saas_config() @@ -125,6 +139,7 @@ def unset_connector_state(self) -> None: self.current_privacy_request = None self.current_saas_request = None + @log_context def test_connection(self) -> Optional[ConnectionTestStatus]: """Generates and executes a test connection based on the SaaS config""" test_request: SaaSRequest = self.saas_config.test_request @@ -136,8 +151,7 @@ def test_connection(self) -> Optional[ConnectionTestStatus]: self.secrets, ) client: AuthenticatedClient = self.create_client() - with logger.contextualize(**saas_connector_details(self)): - client.send(prepared_request, test_request.ignore_errors) + client.send(prepared_request, test_request.ignore_errors) self.unset_connector_state() return ConnectionTestStatus.succeeded @@ -158,6 +172,7 @@ def create_client(self) -> AuthenticatedClient: uri, self.configuration, client_config, rate_limit_config ) + @log_context(action_type=ActionType.access.value) def retrieve_data( self, node: TraversalNode, @@ -287,12 +302,7 @@ def execute_prepared_request( """ client: AuthenticatedClient = self.create_client() - with logger.contextualize( - **saas_connector_details(self, action_type=ActionType.access) - ): - response: Response = client.send( - prepared_request, saas_request.ignore_errors - ) + response: Response = client.send(prepared_request, saas_request.ignore_errors) response = self._handle_errored_response(saas_request, response) response_data = self._unwrap_response_data(saas_request, response) @@ -378,6 +388,7 @@ def process_response_data( return rows + @log_context(action_type=ActionType.erasure.value) def mask_data( self, node: TraversalNode, @@ -434,17 +445,14 @@ def mask_data( ) except ValueError as exc: if masking_request.skip_missing_param_values: - logger.info( + logger.debug( "Skipping optional masking request on node {}: {}", node.address.value, exc, ) continue raise exc - with logger.contextualize( - **saas_connector_details(self, action_type=ActionType.erasure) - ): - client.send(prepared_request, masking_request.ignore_errors) + client.send(prepared_request, masking_request.ignore_errors) rows_updated += 1 self.unset_connector_state() @@ -467,6 +475,7 @@ def relevant_consent_identities( related_identities[identity_type] = identity_value return related_identities + @log_context(action_type=ActionType.consent.value) def run_consent_request( self, node: TraversalNode, @@ -547,10 +556,7 @@ def run_consent_request( continue raise exc client: AuthenticatedClient = self.create_client() - with logger.contextualize( - **saas_connector_details(self, action_type=ActionType.consent) - ): - client.send(prepared_request) + client.send(prepared_request) fired = True self.unset_connector_state() if not fired: diff --git a/src/fides/api/util/logger_context_utils.py b/src/fides/api/util/logger_context_utils.py index 0232cc6a58..175a491ba5 100644 --- a/src/fides/api/util/logger_context_utils.py +++ b/src/fides/api/util/logger_context_utils.py @@ -1,6 +1,9 @@ +from abc import abstractmethod from enum import Enum -from typing import TYPE_CHECKING, Any, Dict, Optional +from functools import wraps +from typing import Any, Callable, Dict, Optional +from loguru import logger from requests import PreparedRequest, Response from requests.exceptions import ( # pylint: disable=redefined-builtin ConnectionError, @@ -10,51 +13,80 @@ TooManyRedirects, ) -from fides.api.schemas.policy import ActionType from fides.config import CONFIG -if TYPE_CHECKING: - from fides.api.service.connectors.saas_connector import SaaSConnector - class LoggerContextKeys(Enum): - privacy_request_id = "privacy_request_id" - error_group = "error_group" + action_type = "action_type" + status_code = "status_code" + body = "body" + collection = "collection" + connection_key = "connection_key" error_details = "error_details" + error_group = "error_group" + method = "method" + privacy_request_id = "privacy_request_id" + response = "response" + system_key = "system_key" + url = "url" class ErrorGroup(Enum): """A collection of user-friendly error labels to be used in contextualized logs.""" - network_error = "Network/protocol error" - authentication_error = "Authentication error" - client_error = "Client-side error" - server_error = "Server-side error" - - -def saas_connector_details( - connector: "SaaSConnector", - action_type: Optional[ActionType] = None, -) -> Dict[str, Any]: - """Maps the system and connection info details. Includes the collection and privacy request ID if available.""" - - details = { - "system_key": ( - connector.configuration.system.fides_key - if connector.configuration.system - else None - ), - "connection_key": connector.configuration.key, - } - if action_type: - details["action_type"] = action_type.value - if connector.current_collection_name: - details["collection"] = connector.current_collection_name - if connector.current_privacy_request: - details[LoggerContextKeys.privacy_request_id.value] = ( - connector.current_privacy_request.id - ) - return details + network_error = "NetworkError" + authentication_error = "AuthenticationError" + client_error = "ClientSideError" + server_error = "ServerSideError" + + +class Contextualizable: + """ + An abstract base class that defines a contract for classes which can provide + contextual information for logging purposes. + + Subclasses of Contextualizable must implement the get_log_context method, + which should return a dictionary of context information relevant to the object. + This context will be used by the log_context decorator to add additional + information to log messages. + """ + + @abstractmethod + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + pass + + +def log_context( + _func: Optional[Callable] = None, **additional_context: Any +) -> Callable: + """ + A decorator that adds context information to log messages. It extracts context from + the arguments of the decorated function and from any specified additional context. + Optional additional context is provided through keyword arguments. + """ + + def decorator(func: Callable) -> Callable: + @wraps(func) + def wrapper(*args: Any, **kwargs: Any) -> Any: + context = dict(additional_context) + for arg in args: + if isinstance(arg, Contextualizable): + arg_context = arg.get_log_context() + # get values from enums + context.update( + { + key.value if isinstance(key, Enum) else key: value + for key, value in arg_context.items() + } + ) + with logger.contextualize(**context): + return func(*args, **kwargs) + + return wrapper + + if _func is None: + return decorator + return decorator(_func) def request_details( @@ -62,35 +94,37 @@ def request_details( response: Optional[Response] = None, ignore_error: bool = False, ) -> Dict[str, Any]: - """Maps the request details and includes response details when "dev mode" is enabled.""" + """ + Maps the request details and includes response details when "dev mode" is enabled. + """ details: Dict[str, Any] = { - "method": prepared_request.method, - "url": prepared_request.url, + LoggerContextKeys.method.value: prepared_request.method, + LoggerContextKeys.url.value: prepared_request.url, } if CONFIG.dev_mode and prepared_request.body is not None: - details["body"] = prepared_request.body + details[LoggerContextKeys.body.value] = prepared_request.body if response is not None: if CONFIG.dev_mode and response.content: - details["response"] = response.content.decode("utf-8") + details[LoggerContextKeys.response.value] = response.content.decode("utf-8") - details["status_code"] = response.status_code + details[LoggerContextKeys.status_code.value] = response.status_code # assign error group only if error should not be ignored if not ignore_error: if response.status_code in [401, 403]: - details[LoggerContextKeys.error_group.value] = ( - ErrorGroup.authentication_error.value - ) + details[ + LoggerContextKeys.error_group.value + ] = ErrorGroup.authentication_error.value elif 400 <= response.status_code < 500: - details[LoggerContextKeys.error_group.value] = ( - ErrorGroup.client_error.value - ) + details[ + LoggerContextKeys.error_group.value + ] = ErrorGroup.client_error.value elif 500 <= response.status_code: - details[LoggerContextKeys.error_group.value] = ( - ErrorGroup.server_error.value - ) + details[ + LoggerContextKeys.error_group.value + ] = ErrorGroup.server_error.value return details @@ -100,23 +134,24 @@ def connection_exception_details(exception: Exception, url: str) -> Dict[str, An details = { LoggerContextKeys.error_group.value: ErrorGroup.network_error.value, LoggerContextKeys.error_details.value: f"Unknown exception connecting to {url}.", + LoggerContextKeys.status_code.value: None, } if isinstance(exception, ConnectTimeout): - details[LoggerContextKeys.error_details.value] = ( - f"Timeout occurred connecting to {url}." - ) + details[ + LoggerContextKeys.error_details.value + ] = f"Timeout occurred connecting to {url}." elif isinstance(exception, ReadTimeout): - details[LoggerContextKeys.error_details.value] = ( - f"Timeout occurred waiting for a response from {url}." - ) + details[ + LoggerContextKeys.error_details.value + ] = f"Timeout occurred waiting for a response from {url}." elif isinstance(exception, SSLError): - details[LoggerContextKeys.error_details.value] = ( - f"SSL exception occurred connecting to {url}." - ) + details[ + LoggerContextKeys.error_details.value + ] = f"SSL exception occurred connecting to {url}." elif isinstance(exception, TooManyRedirects): - details[LoggerContextKeys.error_details.value] = ( - f"Too many redirects occurred connecting to {url}." - ) + details[ + LoggerContextKeys.error_details.value + ] = f"Too many redirects occurred connecting to {url}." elif isinstance(exception, ConnectionError): details[LoggerContextKeys.error_details.value] = f"Unable to connect to {url}." return details diff --git a/tests/ops/integration_tests/test_privacy_request_logging.py b/tests/ops/integration_tests/test_privacy_request_logging.py index f26ef02560..606ee5e499 100644 --- a/tests/ops/integration_tests/test_privacy_request_logging.py +++ b/tests/ops/integration_tests/test_privacy_request_logging.py @@ -7,7 +7,11 @@ from fides.api.common_exceptions import ClientUnsuccessfulException from fides.api.util.logger_context_utils import ErrorGroup from fides.common.api.scope_registry import PRIVACY_REQUEST_CREATE -from fides.common.api.v1.urn_registry import PRIVACY_REQUESTS, V1_URL_PREFIX +from fides.common.api.v1.urn_registry import ( + CONSENT_REQUEST, + PRIVACY_REQUESTS, + V1_URL_PREFIX, +) from fides.config import CONFIG @@ -59,13 +63,13 @@ def test_access_error_logs( privacy_request = response.json()["succeeded"][0] extra = { + "action_type": "access", "system_key": None, "connection_key": "zendesk_instance", - "action_type": "access", "collection": "user", "privacy_request_id": privacy_request["id"], "method": "GET", - "url": "https://ethyca-test.zendesk.com/api/v2/users/search.json?query=test%40example.com", + "url": "https://ethyca-test.zendesk.com/api/v2/users/search.json?query=test%40email.com", "status_code": 401, "error_group": ErrorGroup.authentication_error.value, } @@ -104,14 +108,14 @@ async def test_erasure_error_logs( privacy_request = response.json()["succeeded"][0] extra = { + "action_type": "erasure", "system_key": None, "connection_key": "typeform_instance", - "action_type": "erasure", "collection": "user", "privacy_request_id": privacy_request["id"], "method": "DELETE", "url": f"https://api.typeform.com/rtbf/{typeform_secrets['account_id']}/responses", - "body": '["test@example.com"]\n', + "body": '["test@email.com"]\n', "status_code": 401, "error_group": ErrorGroup.authentication_error.value, } @@ -128,11 +132,7 @@ async def test_consent_error_logs( self, mock_send, klaviyo_runner, - api_client, - url, - generate_auth_header, consent_policy, - provided_identity_and_consent_request, loguru_caplog, provided_identity_value, ): @@ -144,9 +144,9 @@ async def test_consent_error_logs( ) extra = { + "action_type": "consent", "system_key": None, "connection_key": "klaviyo_instance", - "action_type": "consent", "collection": "klaviyo_instance", "privacy_request_id": "123", "method": "POST", diff --git a/tests/ops/util/test_logger_context_utils.py b/tests/ops/util/test_logger_context_utils.py index e6e7e2eaf1..d84964f861 100644 --- a/tests/ops/util/test_logger_context_utils.py +++ b/tests/ops/util/test_logger_context_utils.py @@ -1,17 +1,78 @@ +from typing import Any, Dict + import pytest +from loguru import logger from requests import PreparedRequest, Request, Response -from fides.api.models.privacy_request import PrivacyRequest -from fides.api.schemas.policy import ActionType -from fides.api.service.connectors.saas_connector import SaaSConnector from fides.api.util.logger_context_utils import ( + Contextualizable, ErrorGroup, + LoggerContextKeys, + log_context, request_details, - saas_connector_details, ) -class TestLoggerContestUtils: +class TestLogContextDecorator: + def test_log_context_without_contextualizable_params(self, loguru_caplog): + @log_context + def func(): + logger.info("returning") + return + + func() + + assert loguru_caplog.records[0].extra == {} + + def test_log_context_with_contextualizable_params(self, loguru_caplog): + class LoggableClass(Contextualizable): + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + return {LoggerContextKeys.privacy_request_id: "123"} + + @log_context + def func(param: LoggableClass): + logger.info("returning") + return param + + func(LoggableClass()) + + assert loguru_caplog.records[0].extra == { + LoggerContextKeys.privacy_request_id.value: "123" + } + + def test_log_context_with_additional_context(self, loguru_caplog): + @log_context(one_more_thing="456") + def func(): + logger.info("returning") + return + + func() + + assert loguru_caplog.records[0].extra == { + "one_more_thing": "456", + } + + def test_log_context_with_contextualizable_params_and_additional_context( + self, loguru_caplog + ): + class LoggableClass(Contextualizable): + def get_log_context(self) -> Dict[LoggerContextKeys, Any]: + return {LoggerContextKeys.privacy_request_id: "123"} + + @log_context(one_more_thing="456") + def func(param: LoggableClass): + logger.info("returning") + return param + + func(LoggableClass()) + + assert loguru_caplog.records[0].extra == { + LoggerContextKeys.privacy_request_id.value: "123", + "one_more_thing": "456", + } + + +class TestDetailFunctions: @pytest.fixture def prepared_request(self) -> PreparedRequest: return Request( @@ -22,19 +83,6 @@ def prepared_request(self) -> PreparedRequest: data={"name": "test"}, ).prepare() - def test_saas_connector_details(self, saas_example_connection_config, system): - saas_example_connection_config.system_id = system.id - connector = SaaSConnector(saas_example_connection_config) - connector.current_collection_name = "customer" - connector.current_privacy_request = PrivacyRequest(id="123") - assert saas_connector_details(connector, action_type=ActionType.access) == { - "system_key": system.fides_key, - "connection_key": "saas_connector_example", - "action_type": "access", - "collection": "customer", - "privacy_request_id": "123", - } - def test_request_details(self, prepared_request): response = Response() response.status_code = 200 From 28ca13c116034f029f3d58b7811a188c050b02a3 Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Tue, 13 Feb 2024 13:04:11 -0800 Subject: [PATCH 7/8] Removing unused import --- src/fides/api/models/privacy_request.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/fides/api/models/privacy_request.py b/src/fides/api/models/privacy_request.py index d94618194e..9f670771cd 100644 --- a/src/fides/api/models/privacy_request.py +++ b/src/fides/api/models/privacy_request.py @@ -65,7 +65,6 @@ from fides.api.util.cache import ( FidesopsRedis, get_all_cache_keys_for_privacy_request, - get_all_masking_secret_cache_keys_for_privacy_request, get_async_task_tracking_cache_key, get_cache, get_custom_privacy_request_field_cache_key, From 0129d081ab483000e2674ae4dc794e76011bf49d Mon Sep 17 00:00:00 2001 From: Adrian Galvan Date: Wed, 14 Feb 2024 11:32:50 -0800 Subject: [PATCH 8/8] Updating change log --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d987e9be7d..920a33475c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,7 @@ The types of changes are: - Access and erasure support for Talkable [#4589](https://github.com/ethyca/fides/pull/4589) - Support temporary credentials in AWS generate + scan features [#4607](https://github.com/ethyca/fides/pull/4603), [#4608](https://github.com/ethyca/fides/pull/4608) - Add ability to store and read Fides cookie in Base64 format [#4556](https://github.com/ethyca/fides/pull/4556) +- Structured logging for SaaS connector requests [#4594](https://github.com/ethyca/fides/pull/4594) ### Fixed