From b9f3b6ebea216a384226f666e8c6e3aa29b6300c Mon Sep 17 00:00:00 2001 From: Daniel Mil Date: Tue, 19 Apr 2022 09:56:12 -0700 Subject: [PATCH 1/3] Add logging for request headers --- .../combination/test_api_with_authorizers.py | 9 +++++ integration/config/logger_configurations.py | 13 +++++++ integration/helpers/base_test.py | 11 +++++- integration/helpers/request_utils.py | 38 +++++++++++++++++++ pytest.ini | 3 +- 5 files changed, 71 insertions(+), 3 deletions(-) create mode 100644 integration/config/logger_configurations.py create mode 100644 integration/helpers/request_utils.py diff --git a/integration/combination/test_api_with_authorizers.py b/integration/combination/test_api_with_authorizers.py index 4d6975d64..35b3901a5 100644 --- a/integration/combination/test_api_with_authorizers.py +++ b/integration/combination/test_api_with_authorizers.py @@ -1,13 +1,19 @@ from unittest.case import skipIf +import logging import requests +from integration.config.logger_configurations import LoggerConfigurations from integration.helpers.base_test import BaseTest from integration.helpers.deployer.utils.retry import retry from integration.helpers.exception import StatusCodeError +from integration.helpers.request_utils import RequestUtils from integration.helpers.resource import current_region_does_not_support from integration.config.service_names import COGNITO +LOG = logging.getLogger(__name__) +LoggerConfigurations.configure_request_logging(LOG) + @skipIf(current_region_does_not_support([COGNITO]), "Cognito is not supported in this testing region") class TestApiWithAuthorizers(BaseTest): @@ -441,6 +447,9 @@ def verify_authorized_request( headers = {header_key: header_value} response = requests.get(url, headers=headers) status = response.status_code + amazon_headers = RequestUtils(response).get_amazon_headers() + LOG.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) + if status != expected_status_code: raise StatusCodeError( "Request to {} failed with status: {}, expected status: {}".format(url, status, expected_status_code) diff --git a/integration/config/logger_configurations.py b/integration/config/logger_configurations.py new file mode 100644 index 000000000..d6d6c664f --- /dev/null +++ b/integration/config/logger_configurations.py @@ -0,0 +1,13 @@ +# Logger configurations +import logging + + +class LoggerConfigurations: + @staticmethod + def configure_request_logging(logger): + console_handler = logging.StreamHandler() + console_handler.setFormatter( + logging.Formatter("%(asctime)s %(message)s | Status: %(status)s | Headers: %(headers)s ") + ) + console_handler.setLevel(logging.INFO) + logger.addHandler(console_handler) diff --git a/integration/helpers/base_test.py b/integration/helpers/base_test.py index 785b2af54..183742683 100644 --- a/integration/helpers/base_test.py +++ b/integration/helpers/base_test.py @@ -6,9 +6,11 @@ import pytest import requests +from integration.config.logger_configurations import LoggerConfigurations from integration.helpers.client_provider import ClientProvider from integration.helpers.deployer.exceptions.exceptions import ThrottlingError from integration.helpers.deployer.utils.retry import retry_with_exponential_backoff_and_jitter +from integration.helpers.request_utils import RequestUtils from integration.helpers.resource import generate_suffix, create_bucket, verify_stack_resources from integration.helpers.s3_uploader import S3Uploader from integration.helpers.yaml_utils import dump_yaml, load_yaml @@ -28,6 +30,8 @@ from integration.helpers.file_resources import FILE_TO_S3_URI_MAP, CODE_KEY_TO_FILE_MAP LOG = logging.getLogger(__name__) +REQUEST_LOG = logging.getLogger(f"{__name__}.requests") +LoggerConfigurations.configure_request_logging(REQUEST_LOG) STACK_NAME_PREFIX = "sam-integ-stack-" S3_BUCKET_PREFIX = "sam-integ-bucket-" @@ -507,9 +511,12 @@ def verify_get_request_response(self, url, expected_status_code): expected_status_code : string the expected status code """ - print("Making request to " + url) + REQUEST_LOG.info("Making request to " + url) response = requests.get(url) - self.assertEqual(response.status_code, expected_status_code, " must return HTTP " + str(expected_status_code)) + status = response.status_code + amazon_headers = RequestUtils(response).get_amazon_headers() + REQUEST_LOG.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) + self.assertEqual(status, expected_status_code, " must return HTTP " + str(expected_status_code)) return response def get_default_test_template_parameters(self): diff --git a/integration/helpers/request_utils.py b/integration/helpers/request_utils.py new file mode 100644 index 000000000..3046a890f --- /dev/null +++ b/integration/helpers/request_utils.py @@ -0,0 +1,38 @@ +# Utils for requests + +# Relevant headers that should be captured for debugging +AMAZON_HEADERS = [ + "x-amzn-requestid", + "x-amz-apigw-id", + "x-amz-cf-id", + "x-amzn-errortype", + "apigw-requestid", +] + + +class RequestUtils: + + def __init__(self, response): + self.response = response + self.headers = self._normalize_response_headers() + + def get_amazon_headers(self): + """ + Get a list of relevant amazon headers that could be useful for debugging + """ + amazon_headers = {} + for header, header_val in self.headers.items(): + if header in AMAZON_HEADERS: + amazon_headers[header] = header_val + return amazon_headers + + def _normalize_response_headers(self): + """ + API gateway can return headers with letters in different cases i.e. x-amzn-requestid or x-amzn-requestId + We make them all lowercase here to more easily match them up + """ + if self.response is None or not self.response.headers: + # Need to check for response is None here since the __bool__ method checks 200 <= status < 400 + return {} + + return dict((k.lower(), v) for k, v in self.response.headers.items()) diff --git a/pytest.ini b/pytest.ini index 257206172..d567f28ac 100644 --- a/pytest.ini +++ b/pytest.ini @@ -7,4 +7,5 @@ env = AWS_DEFAULT_REGION = ap-southeast-1 markers = slow: marks tests as slow (deselect with '-m "not slow"') - +log_cli = 1 +log_cli_level = INFO From f4fe0943f2ad67f885cc21bd4f60f149119d26f1 Mon Sep 17 00:00:00 2001 From: Daniel Mil Date: Tue, 26 Apr 2022 09:38:39 -0700 Subject: [PATCH 2/3] Generalize request logic with logging --- integration/combination/test_api_settings.py | 4 +++ integration/config/logger_configurations.py | 4 +-- integration/helpers/base_test.py | 12 ++------- integration/helpers/request_utils.py | 26 +++++++++++++++++--- 4 files changed, 30 insertions(+), 16 deletions(-) diff --git a/integration/combination/test_api_settings.py b/integration/combination/test_api_settings.py index 5752ba9ae..f6fabbd9e 100644 --- a/integration/combination/test_api_settings.py +++ b/integration/combination/test_api_settings.py @@ -1,5 +1,7 @@ import hashlib +from integration.config.logger_configurations import CustomLoggers + try: from pathlib import Path except ImportError: @@ -10,6 +12,8 @@ from integration.helpers.base_test import BaseTest +REQUEST_LOG = CustomLoggers.get_request_logger(__name__) + class TestApiSettings(BaseTest): def test_method_settings(self): diff --git a/integration/config/logger_configurations.py b/integration/config/logger_configurations.py index d6d6c664f..94919f6b4 100644 --- a/integration/config/logger_configurations.py +++ b/integration/config/logger_configurations.py @@ -2,9 +2,9 @@ import logging -class LoggerConfigurations: +class CustomLoggers: @staticmethod - def configure_request_logging(logger): + def configure_request_logger(logger): console_handler = logging.StreamHandler() console_handler.setFormatter( logging.Formatter("%(asctime)s %(message)s | Status: %(status)s | Headers: %(headers)s ") diff --git a/integration/helpers/base_test.py b/integration/helpers/base_test.py index 183742683..75d91c11b 100644 --- a/integration/helpers/base_test.py +++ b/integration/helpers/base_test.py @@ -4,9 +4,7 @@ import botocore import pytest -import requests -from integration.config.logger_configurations import LoggerConfigurations from integration.helpers.client_provider import ClientProvider from integration.helpers.deployer.exceptions.exceptions import ThrottlingError from integration.helpers.deployer.utils.retry import retry_with_exponential_backoff_and_jitter @@ -30,8 +28,6 @@ from integration.helpers.file_resources import FILE_TO_S3_URI_MAP, CODE_KEY_TO_FILE_MAP LOG = logging.getLogger(__name__) -REQUEST_LOG = logging.getLogger(f"{__name__}.requests") -LoggerConfigurations.configure_request_logging(REQUEST_LOG) STACK_NAME_PREFIX = "sam-integ-stack-" S3_BUCKET_PREFIX = "sam-integ-bucket-" @@ -511,12 +507,8 @@ def verify_get_request_response(self, url, expected_status_code): expected_status_code : string the expected status code """ - REQUEST_LOG.info("Making request to " + url) - response = requests.get(url) - status = response.status_code - amazon_headers = RequestUtils(response).get_amazon_headers() - REQUEST_LOG.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) - self.assertEqual(status, expected_status_code, " must return HTTP " + str(expected_status_code)) + response = RequestUtils().do_get_request_with_logging(url) + self.assertEqual(response.status_code, expected_status_code, " must return HTTP " + str(expected_status_code)) return response def get_default_test_template_parameters(self): diff --git a/integration/helpers/request_utils.py b/integration/helpers/request_utils.py index 3046a890f..58e52af43 100644 --- a/integration/helpers/request_utils.py +++ b/integration/helpers/request_utils.py @@ -1,4 +1,13 @@ # Utils for requests +import logging + +import requests + +from integration.config.logger_configurations import CustomLoggers + + +REQUEST_LOGGER = logging.getLogger(__name__) +CustomLoggers.configure_request_logger(REQUEST_LOGGER) # Relevant headers that should be captured for debugging AMAZON_HEADERS = [ @@ -12,11 +21,11 @@ class RequestUtils: - def __init__(self, response): - self.response = response - self.headers = self._normalize_response_headers() + def __init__(self): + self.response = None + self.headers = None - def get_amazon_headers(self): + def _get_amazon_headers(self): """ Get a list of relevant amazon headers that could be useful for debugging """ @@ -36,3 +45,12 @@ def _normalize_response_headers(self): return {} return dict((k.lower(), v) for k, v in self.response.headers.items()) + + def do_get_request_with_logging(self, url): + REQUEST_LOGGER.info("Making request to " + url) + self.response = requests.get(url) + self.headers = self._normalize_response_headers() + status = self.response.status_code + amazon_headers = self._get_amazon_headers() + REQUEST_LOGGER.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) + return self.response From be9b931d22fc549c7e8c35fab6b13fd459503f9d Mon Sep 17 00:00:00 2001 From: Daniel Mil Date: Mon, 2 May 2022 14:30:13 -0700 Subject: [PATCH 3/3] Add wrapper for get requests --- integration/combination/test_api_settings.py | 7 +---- .../test_api_with_authorizer_apikey.py | 10 ++----- .../combination/test_api_with_authorizers.py | 14 ++-------- integration/config/logger_configurations.py | 5 ++-- integration/helpers/base_test.py | 28 +++++++++++++++++-- integration/helpers/request_utils.py | 27 +++--------------- integration/single/test_basic_api.py | 7 ++--- integration/single/test_basic_function.py | 4 +-- .../test_function_with_http_api_and_auth.py | 24 ++++++++++------ 9 files changed, 57 insertions(+), 69 deletions(-) diff --git a/integration/combination/test_api_settings.py b/integration/combination/test_api_settings.py index f6fabbd9e..5e1f11c0d 100644 --- a/integration/combination/test_api_settings.py +++ b/integration/combination/test_api_settings.py @@ -1,19 +1,14 @@ import hashlib -from integration.config.logger_configurations import CustomLoggers - try: from pathlib import Path except ImportError: from pathlib2 import Path -import requests from parameterized import parameterized from integration.helpers.base_test import BaseTest -REQUEST_LOG = CustomLoggers.get_request_logger(__name__) - class TestApiSettings(BaseTest): def test_method_settings(self): @@ -162,7 +157,7 @@ def test_implicit_api_settings(self): def verify_binary_media_request(self, url, expected_status_code): headers = {"accept": "image/png"} - response = requests.get(url, headers=headers) + response = BaseTest.do_get_request_with_logging(url, headers) status = response.status_code expected_file_path = str(Path(self.code_dir, "AWS_logo_RGB.png")) diff --git a/integration/combination/test_api_with_authorizer_apikey.py b/integration/combination/test_api_with_authorizer_apikey.py index c0a11cbbc..436945f5f 100644 --- a/integration/combination/test_api_with_authorizer_apikey.py +++ b/integration/combination/test_api_with_authorizer_apikey.py @@ -1,12 +1,6 @@ -from unittest.case import skipIf - -import requests - from integration.helpers.base_test import BaseTest from integration.helpers.deployer.utils.retry import retry from integration.helpers.exception import StatusCodeError -from integration.helpers.resource import current_region_does_not_support -from integration.config.service_names import COGNITO class TestApiWithAuthorizerApiKey(BaseTest): @@ -82,10 +76,10 @@ def verify_authorized_request( header_value=None, ): if not header_key or not header_value: - response = requests.get(url) + response = BaseTest.do_get_request_with_logging(url) else: headers = {header_key: header_value} - response = requests.get(url, headers=headers) + response = BaseTest.do_get_request_with_logging(url, headers) status = response.status_code if status != expected_status_code: raise StatusCodeError( diff --git a/integration/combination/test_api_with_authorizers.py b/integration/combination/test_api_with_authorizers.py index 35b3901a5..3d0ce02dc 100644 --- a/integration/combination/test_api_with_authorizers.py +++ b/integration/combination/test_api_with_authorizers.py @@ -1,19 +1,11 @@ from unittest.case import skipIf -import logging -import requests - -from integration.config.logger_configurations import LoggerConfigurations from integration.helpers.base_test import BaseTest from integration.helpers.deployer.utils.retry import retry from integration.helpers.exception import StatusCodeError -from integration.helpers.request_utils import RequestUtils from integration.helpers.resource import current_region_does_not_support from integration.config.service_names import COGNITO -LOG = logging.getLogger(__name__) -LoggerConfigurations.configure_request_logging(LOG) - @skipIf(current_region_does_not_support([COGNITO]), "Cognito is not supported in this testing region") class TestApiWithAuthorizers(BaseTest): @@ -442,13 +434,11 @@ def verify_authorized_request( header_value=None, ): if not header_key or not header_value: - response = requests.get(url) + response = BaseTest.do_get_request_with_logging(url) else: headers = {header_key: header_value} - response = requests.get(url, headers=headers) + response = BaseTest.do_get_request_with_logging(url, headers) status = response.status_code - amazon_headers = RequestUtils(response).get_amazon_headers() - LOG.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) if status != expected_status_code: raise StatusCodeError( diff --git a/integration/config/logger_configurations.py b/integration/config/logger_configurations.py index 94919f6b4..d51f98885 100644 --- a/integration/config/logger_configurations.py +++ b/integration/config/logger_configurations.py @@ -2,12 +2,13 @@ import logging -class CustomLoggers: +class LoggingConfiguration: @staticmethod def configure_request_logger(logger): console_handler = logging.StreamHandler() + console_handler.setLevel(logging.INFO) console_handler.setFormatter( logging.Formatter("%(asctime)s %(message)s | Status: %(status)s | Headers: %(headers)s ") ) - console_handler.setLevel(logging.INFO) logger.addHandler(console_handler) + logger.propagate = False diff --git a/integration/helpers/base_test.py b/integration/helpers/base_test.py index 75d91c11b..2dfd2a99d 100644 --- a/integration/helpers/base_test.py +++ b/integration/helpers/base_test.py @@ -1,10 +1,12 @@ import logging import os +import requests import shutil import botocore import pytest +from integration.config.logger_configurations import LoggingConfiguration from integration.helpers.client_provider import ClientProvider from integration.helpers.deployer.exceptions.exceptions import ThrottlingError from integration.helpers.deployer.utils.retry import retry_with_exponential_backoff_and_jitter @@ -28,6 +30,10 @@ from integration.helpers.file_resources import FILE_TO_S3_URI_MAP, CODE_KEY_TO_FILE_MAP LOG = logging.getLogger(__name__) + +REQUEST_LOGGER = logging.getLogger(f"{__name__}.requests") +LoggingConfiguration.configure_request_logger(REQUEST_LOGGER) + STACK_NAME_PREFIX = "sam-integ-stack-" S3_BUCKET_PREFIX = "sam-integ-bucket-" @@ -496,7 +502,7 @@ def verify_stack(self, end_state="CREATE_COMPLETE"): if error: self.fail(error) - def verify_get_request_response(self, url, expected_status_code): + def verify_get_request_response(self, url, expected_status_code, headers=None): """ Verify if the get request to a certain url return the expected status code @@ -506,8 +512,10 @@ def verify_get_request_response(self, url, expected_status_code): the url for the get request expected_status_code : string the expected status code + headers : dict + headers to use in request """ - response = RequestUtils().do_get_request_with_logging(url) + response = BaseTest.do_get_request_with_logging(url, headers) self.assertEqual(response.status_code, expected_status_code, " must return HTTP " + str(expected_status_code)) return response @@ -546,3 +554,19 @@ def generate_parameter(key, value, previous_value=False, resolved_value="string" "ResolvedValue": resolved_value, } return parameter + + @staticmethod + def do_get_request_with_logging(url, headers=None): + """ + Perform a get request to an APIGW endpoint and log relevant info + Parameters + ---------- + url : string + the url for the get request + headers : dict + headers to use in request + """ + response = requests.get(url, headers=headers) if headers else requests.get(url) + amazon_headers = RequestUtils(response).get_amazon_headers() + REQUEST_LOGGER.info("Request made to " + url, extra={"status": response.status_code, "headers": amazon_headers}) + return response diff --git a/integration/helpers/request_utils.py b/integration/helpers/request_utils.py index 58e52af43..655d7ae8a 100644 --- a/integration/helpers/request_utils.py +++ b/integration/helpers/request_utils.py @@ -1,13 +1,4 @@ # Utils for requests -import logging - -import requests - -from integration.config.logger_configurations import CustomLoggers - - -REQUEST_LOGGER = logging.getLogger(__name__) -CustomLoggers.configure_request_logger(REQUEST_LOGGER) # Relevant headers that should be captured for debugging AMAZON_HEADERS = [ @@ -20,12 +11,11 @@ class RequestUtils: + def __init__(self, response): + self.response = response + self.headers = self._normalize_response_headers() - def __init__(self): - self.response = None - self.headers = None - - def _get_amazon_headers(self): + def get_amazon_headers(self): """ Get a list of relevant amazon headers that could be useful for debugging """ @@ -45,12 +35,3 @@ def _normalize_response_headers(self): return {} return dict((k.lower(), v) for k, v in self.response.headers.items()) - - def do_get_request_with_logging(self, url): - REQUEST_LOGGER.info("Making request to " + url) - self.response = requests.get(url) - self.headers = self._normalize_response_headers() - status = self.response.status_code - amazon_headers = self._get_amazon_headers() - REQUEST_LOGGER.info("Calling API Gateway", extra={"status": status, "headers": amazon_headers}) - return self.response diff --git a/integration/single/test_basic_api.py b/integration/single/test_basic_api.py index 9eb00ecb8..402fd054f 100644 --- a/integration/single/test_basic_api.py +++ b/integration/single/test_basic_api.py @@ -2,7 +2,6 @@ from unittest.case import skipIf from integration.helpers.base_test import BaseTest -import requests from integration.helpers.resource import current_region_does_not_support from integration.config.service_names import MODE @@ -40,17 +39,17 @@ def test_basic_api_with_mode(self): stack_output = self.get_stack_outputs() api_endpoint = stack_output.get("ApiEndpoint") - response = requests.get(f"{api_endpoint}/get") + response = BaseTest.do_get_request_with_logging(f"{api_endpoint}/get") self.assertEqual(response.status_code, 200) # Removes get from the API self.update_and_verify_stack(file_path="single/basic_api_with_mode_update") - response = requests.get(f"{api_endpoint}/get") + response = BaseTest.do_get_request_with_logging(f"{api_endpoint}/get") # API Gateway by default returns 403 if a path do not exist retries = 20 while retries > 0: retries -= 1 - response = requests.get(f"{api_endpoint}/get") + response = BaseTest.do_get_request_with_logging(f"{api_endpoint}/get") if response.status_code != 500: break time.sleep(5) diff --git a/integration/single/test_basic_function.py b/integration/single/test_basic_function.py index 5277ac9c5..51be19b77 100644 --- a/integration/single/test_basic_function.py +++ b/integration/single/test_basic_function.py @@ -1,7 +1,5 @@ from unittest.case import skipIf -import requests - from integration.config.service_names import KMS, XRAY, ARM from integration.helpers.resource import current_region_does_not_support from parameterized import parameterized @@ -42,7 +40,7 @@ def test_function_with_http_api_events(self, file_name): endpoint = self.get_api_v2_endpoint("MyHttpApi") - self.assertEqual(requests.get(endpoint).text, self.FUNCTION_OUTPUT) + self.assertEqual(BaseTest.do_get_request_with_logging(endpoint).text, self.FUNCTION_OUTPUT) @parameterized.expand( [ diff --git a/integration/single/test_function_with_http_api_and_auth.py b/integration/single/test_function_with_http_api_and_auth.py index c1e5546d2..02cd368bb 100644 --- a/integration/single/test_function_with_http_api_and_auth.py +++ b/integration/single/test_function_with_http_api_and_auth.py @@ -1,5 +1,3 @@ -import requests -from parameterized import parameterized from integration.helpers.base_test import BaseTest @@ -16,14 +14,22 @@ def test_function_with_http_api_and_auth(self): self.create_and_verify_stack("function_with_http_api_events_and_auth") implicitEndpoint = self.get_api_v2_endpoint("ServerlessHttpApi") - self.assertEqual(requests.get(implicitEndpoint + "/default-auth").text, self.FUNCTION_OUTPUT) - self.assertEqual(requests.get(implicitEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT) + self.assertEqual( + BaseTest.do_get_request_with_logging(implicitEndpoint + "/default-auth").text, self.FUNCTION_OUTPUT + ) + self.assertEqual(BaseTest.do_get_request_with_logging(implicitEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT) defaultIamEndpoint = self.get_api_v2_endpoint("MyDefaultIamAuthHttpApi") - self.assertEqual(requests.get(defaultIamEndpoint + "/no-auth").text, self.FUNCTION_OUTPUT) - self.assertEqual(requests.get(defaultIamEndpoint + "/default-auth").text, IAM_AUTH_OUTPUT) - self.assertEqual(requests.get(defaultIamEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT) + self.assertEqual( + BaseTest.do_get_request_with_logging(defaultIamEndpoint + "/no-auth").text, self.FUNCTION_OUTPUT + ) + self.assertEqual( + BaseTest.do_get_request_with_logging(defaultIamEndpoint + "/default-auth").text, IAM_AUTH_OUTPUT + ) + self.assertEqual(BaseTest.do_get_request_with_logging(defaultIamEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT) iamEnabledEndpoint = self.get_api_v2_endpoint("MyIamAuthEnabledHttpApi") - self.assertEqual(requests.get(iamEnabledEndpoint + "/default-auth").text, self.FUNCTION_OUTPUT) - self.assertEqual(requests.get(iamEnabledEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT) + self.assertEqual( + BaseTest.do_get_request_with_logging(iamEnabledEndpoint + "/default-auth").text, self.FUNCTION_OUTPUT + ) + self.assertEqual(BaseTest.do_get_request_with_logging(iamEnabledEndpoint + "/iam-auth").text, IAM_AUTH_OUTPUT)