diff --git a/pyctuator/impl/fastapi_pyctuator.py b/pyctuator/impl/fastapi_pyctuator.py index 484c502..572cd67 100644 --- a/pyctuator/impl/fastapi_pyctuator.py +++ b/pyctuator/impl/fastapi_pyctuator.py @@ -159,13 +159,12 @@ def _create_record( request_time: datetime, response_time: datetime, ) -> TraceRecord: - response_delta_time = response_time - request_time new_record: TraceRecord = TraceRecord( request_time, None, None, TraceRequest(request.method, str(request.url), self._create_headers_dictionary(request.headers)), TraceResponse(response.status_code, self._create_headers_dictionary(response.headers)), - int(response_delta_time.microseconds / 1000), + int((response_time.timestamp() - request_time.timestamp()) * 1000), ) return new_record diff --git a/pyctuator/impl/flask_pyctuator.py b/pyctuator/impl/flask_pyctuator.py index 3e8eff0..e9be3db 100644 --- a/pyctuator/impl/flask_pyctuator.py +++ b/pyctuator/impl/flask_pyctuator.py @@ -120,7 +120,7 @@ def get_logfile() -> Tuple[Response, int]: range_header: str = request.headers.environ.get('HTTP_RANGE') if not range_header: response: Response = make_response(pyctuator_impl.logfile.log_messages.get_range()) - return response, HTTPStatus.OK.value + return response, HTTPStatus.OK str_res, start, end = pyctuator_impl.logfile.get_logfile(range_header) @@ -129,7 +129,7 @@ def get_logfile() -> Tuple[Response, int]: resp.headers["Accept-Ranges"] = "bytes" resp.headers["Content-Range"] = f"bytes {start}-{end}/{end}" - return resp, HTTPStatus.PARTIAL_CONTENT.value + return resp, HTTPStatus.PARTIAL_CONTENT @flask_blueprint.route("/trace") @flask_blueprint.route("/httptrace") @@ -150,13 +150,12 @@ def record_request_and_response( request_time: datetime, response_time: datetime, ) -> None: - response_delta_time = response_time - request_time new_record = TraceRecord( request_time, None, None, TraceRequest(request.method, str(request.url), self._create_headers_dictionary_flask(request.headers)), TraceResponse(response.status_code, self._create_headers_dictionary_flask(response.headers)), - int(response_delta_time.microseconds / 1000), + int((response_time.timestamp() - request_time.timestamp()) * 1000), ) self.pyctuator_impl.http_tracer.add_record(record=new_record) diff --git a/tests/fast_api_test_server.py b/tests/fast_api_test_server.py index 05e051c..4b5d6fd 100644 --- a/tests/fast_api_test_server.py +++ b/tests/fast_api_test_server.py @@ -1,6 +1,7 @@ import logging import threading import time +from typing import Optional from fastapi import FastAPI from starlette.requests import Request @@ -39,7 +40,13 @@ def logfile_test_repeater(repeated_string: str) -> str: @self.app.get("/httptrace_test_url") # pylint: disable=unused-variable - def get_httptrace_test_url(request: Request) -> Response: + def get_httptrace_test_url(request: Request, sleep_sec: Optional[int]) -> Response: + # Sleep if requested to sleep - used for asserting httptraces timing + if sleep_sec: + logging.info("Sleeping %s seconds before replying", sleep_sec) + time.sleep(sleep_sec) + + # Echo 'User-Data' header as 'resp-data' - used for asserting headers are captured properly return Response(headers={"resp-data": str(request.headers.get("User-Data"))}, content="my content") def start(self) -> None: diff --git a/tests/flask_test_server.py b/tests/flask_test_server.py index df8d0fd..8557fe4 100644 --- a/tests/flask_test_server.py +++ b/tests/flask_test_server.py @@ -36,15 +36,22 @@ def shutdown() -> str: @self.app.route("/logfile_test_repeater") # pylint: disable=unused-variable def logfile_test_repeater() -> str: - repeated_string: str = str(request.args.get('repeated_string')) + repeated_string: str = str(request.args.get("repeated_string")) logging.error(repeated_string) return repeated_string @self.app.route("/httptrace_test_url", methods=["GET"]) # pylint: disable=unused-variable def get_httptrace_test_url() -> Response: + # Sleep if requested to sleep - used for asserting httptraces timing + sleep_sec = request.args.get("sleep_sec") + if sleep_sec: + logging.info("Sleeping %s seconds before replying", sleep_sec) + time.sleep(int(sleep_sec)) + + # Echo 'User-Data' header as 'resp-data' - used for asserting headers are captured properly resp = Response() - resp.headers["resp-data"] = str(request.headers.get('User-Data')) + resp.headers["resp-data"] = str(request.headers.get("User-Data")) return resp def start(self) -> None: diff --git a/tests/test_pyctuator_e2e.py b/tests/test_pyctuator_e2e.py index 89f5416..96424de 100644 --- a/tests/test_pyctuator_e2e.py +++ b/tests/test_pyctuator_e2e.py @@ -42,7 +42,7 @@ def test_response_content_type(endpoints: Endpoints, registration_tracker: Regis actuator_endpoint_url = asdict(endpoints)[actuator_endpoint] logging.info("Testing content type of %s (%s)", actuator_endpoint, actuator_endpoint_url) response = requests.get(actuator_endpoint_url) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.headers.get("Content-Type", response.headers.get("content-type")) == SBA_V2_CONTENT_TYPE # Issue requests to non-actuator endpoints and verify the correct content-type is returned @@ -73,7 +73,7 @@ def test_response_content_type(endpoints: Endpoints, registration_tracker: Regis @pytest.mark.mark_self_endpoint def test_self_endpoint(endpoints: Endpoints) -> None: response = requests.get(endpoints.pyctuator) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.json()["_links"] is not None @@ -82,7 +82,7 @@ def test_self_endpoint(endpoints: Endpoints) -> None: def test_env_endpoint(endpoints: Endpoints) -> None: actual_key, actual_value = list(os.environ.items())[3] response = requests.get(endpoints.env) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK property_sources = response.json()["propertySources"] assert property_sources system_properties = [source for source in property_sources if source["name"] == "systemEnvironment"] @@ -90,7 +90,7 @@ def test_env_endpoint(endpoints: Endpoints) -> None: assert system_properties[0]["properties"][actual_key]["value"] == actual_value response = requests.get(endpoints.info) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.json()["app"] is not None @@ -102,7 +102,7 @@ def test_health_endpoint_with_psutil(endpoints: Endpoints, monkeypatch: MonkeyPa # Verify that the diskSpace health check is returning some reasonable values response = requests.get(endpoints.health) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.json()["status"] == "UP" disk_space_health = response.json()["details"]["diskSpace"] assert disk_space_health["status"] == "UP" @@ -120,7 +120,7 @@ def mock_disk_usage(path: str) -> MockDiskUsage: monkeypatch.setattr(psutil, "disk_usage", mock_disk_usage) response = requests.get(endpoints.health) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.json()["status"] == "DOWN" disk_space_health = response.json()["details"]["diskSpace"] assert disk_space_health["status"] == "DOWN" @@ -137,7 +137,7 @@ def test_diskspace_no_psutil(endpoints: Endpoints) -> None: # Verify that the diskSpace health check is returning some reasonable values response = requests.get(endpoints.health) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.json()["status"] == "UP" assert "diskSpace" not in response.json()["details"] @@ -149,20 +149,20 @@ def test_metrics_endpoint(endpoints: Endpoints) -> None: pytest.importorskip("psutil") response = requests.get(endpoints.metrics) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK metric_names = response.json()["names"] assert "memory.rss" in metric_names assert "thread.count" in metric_names response = requests.get(f"{endpoints.metrics}/memory.rss") - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK metric_json = response.json() assert metric_json["name"] == "memory.rss" assert metric_json["measurements"][0]["statistic"] == "VALUE" assert metric_json["measurements"][0]["value"] > 10000 response = requests.get(f"{endpoints.metrics}/thread.count") - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK metric_json = response.json() assert metric_json["name"] == "thread.count" assert metric_json["measurements"][0]["statistic"] == "COUNT" @@ -210,7 +210,7 @@ def test_threads_endpoint(endpoints: Endpoints) -> None: @pytest.mark.mark_loggers_endpoint def test_loggers_endpoint(endpoints: Endpoints) -> None: response = requests.get(endpoints.loggers) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK # levels section loggers_levels = response.json()["levels"] @@ -226,7 +226,7 @@ def test_loggers_endpoint(endpoints: Endpoints) -> None: assert hasattr(logger_obj, "level") # Individual Get logger route response = requests.get(f"{endpoints.loggers}/{logger}") - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert "configuredLevel" in json.loads(response.content) assert "effectiveLevel" in json.loads(response.content) # Set logger level @@ -240,7 +240,7 @@ def test_loggers_endpoint(endpoints: Endpoints) -> None: response = requests.post(f"{endpoints.loggers}/{logger}", data=post_data) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK # Perform get logger level to Validate set logger level succeeded response = requests.get(f"{endpoints.loggers}/{logger}") assert json.loads(response.content)["configuredLevel"] == random_log_level @@ -254,14 +254,14 @@ def test_logfile_endpoint(endpoints: Endpoints) -> None: endpoints.root + "logfile_test_repeater", params={"repeated_string": thirsty_str} ) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK response = requests.get(endpoints.logfile) - assert response.status_code == HTTPStatus.OK.value + assert response.status_code == HTTPStatus.OK assert response.text.find(thirsty_str) >= 0 response = requests.get(endpoints.logfile, headers={"Range": "bytes=-307200"}) # Immitate SBA's 1st request - assert response.status_code == HTTPStatus.PARTIAL_CONTENT.value + assert response.status_code == HTTPStatus.PARTIAL_CONTENT @pytest.mark.usefixtures("boot_admin_server", "pyctuator_server") @@ -270,9 +270,11 @@ def test_traces_endpoint(endpoints: Endpoints) -> None: response = requests.get(endpoints.httptrace) assert response.status_code == 200 - # Create request with header + # Create a request with header user_header = "my header test" requests.get(endpoints.root + "httptrace_test_url", headers={"User-Data": user_header}) + + # Get the captured httptraces response = requests.get(endpoints.httptrace) response_traces = response.json()["traces"] trace = next(x for x in response_traces if x["request"]["uri"].endswith("httptrace_test_url")) @@ -283,3 +285,13 @@ def test_traces_endpoint(endpoints: Endpoints) -> None: # Assert timestamp is formatted in ISO format datetime.fromisoformat(trace["timestamp"]) + + # Assert that the "time taken" (i.e. the time the server spent processing the request) is less than 100ms + assert int(trace["timeTaken"]) < 100 + + # Issue the same request asking the server to sleep for a sec, than assert request timing is at least 1s + requests.get(endpoints.root + "httptrace_test_url", params={"sleep_sec": 1}, headers={"User-Data": user_header}) + response = requests.get(endpoints.httptrace) + response_traces = response.json()["traces"] + trace = next(x for x in response_traces if "httptrace_test_url?sleep_sec" in x["request"]["uri"]) + assert int(trace["timeTaken"]) > 1000