Http-traces's timeTaken should be millis between request and response

When http-traces is capturing a request and response, the `timeTaken`
field should be millis between the time the request was received and the
time the response was sent.

Both `fastapi_pyctuator` and `flask_pyctuator` used the `microseconds`
of the `timedelta` between the request time and the response time.
Unfortunately, this only returns the microseconds part of the time
delta. Instead, should calculate the difference between the two
timestamps.

Fix #13

Author: michael.yak

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

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)

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:

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:

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,15 +82,15 @@ 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"]
     assert system_properties
     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