Log request duration (GSI-1220) (#54)

* Reduce CID logs to DEBUG level

* Bump version from 3.1.7 -> 3.1.8

* Measure and log request duration while CID is set

* Stringify url in details and add space before ms

* Add a test checking for the req duration log

* Use integer for duration

Co-authored-by: Christoph Zwerschke <[email protected]>

* Specify "_ms" in log details

Co-authored-by: Christoph Zwerschke <[email protected]>

* Improve req duration log test

---------

Co-authored-by: Christoph Zwerschke <[email protected]>

Author: TheByronHimes

.pyproject_generation/pyproject_custom.toml

@@ -1,6 +1,6 @@
 [project]
 name = "ghga_service_commons"
-version = "3.1.7"
+version = "3.1.8"
 description = "A library that contains common functionality used in services of GHGA"
 readme = "README.md"
 authors = [

pyproject.toml

@@ -23,7 +23,7 @@ classifiers = [
     "Intended Audience :: Developers",
 ]
 name = "ghga_service_commons"
-version = "3.1.7"
+version = "3.1.8"
 description = "A library that contains common functionality used in services of GHGA"
 dependencies = [
     "pydantic >=2, <3",

src/ghga_service_commons/api/api.py

@@ -20,7 +20,9 @@
 """
 
 import asyncio
+import http
 import logging
+import time
 from collections.abc import Sequence
 from functools import partial
 from typing import Optional, Union
@@ -159,7 +161,7 @@ def set_header_correlation_id(request: Request, correlation_id: str):
     request.scope.update(headers=headers.raw)
     # delete _headers to force update
     delattr(request, "_headers")
-    log.info("Assigned %s as header correlation ID value.", correlation_id)
+    log.debug("Assigned %s as header correlation ID value.", correlation_id)
 
 
 def get_validated_correlation_id(
@@ -177,7 +179,7 @@ def get_validated_correlation_id(
     """
     if not correlation_id and generate_correlation_id:
         correlation_id = new_correlation_id()
-        log.info("Generated new correlation id: %s", correlation_id)
+        log.debug("Generated new correlation id: %s", correlation_id)
     else:
         validate_correlation_id(correlation_id)
     return correlation_id
@@ -217,6 +219,29 @@ async def correlation_id_middleware(
         return response
 
 
+async def request_logging_middleware(request: Request, call_next):
+    """Measure and log the amount of time it takes to process the HTTP request."""
+    url = request.url
+    start_time = time.time()
+    response = await call_next(request)
+    duration = int(round((time.time() - start_time) * 1000))
+    try:
+        status_phrase = http.HTTPStatus(response.status_code).phrase
+    except ValueError:
+        status_phrase = ""
+    msg = f'{request.method} {url} "{response.status_code} {status_phrase}" - {duration} ms'
+    log.info(
+        msg,
+        extra={
+            "method": request.method,
+            "url": str(url),
+            "status_code": response.status_code,
+            "duration_ms": duration,
+        },
+    )
+    return response
+
+
 def configure_app(app: FastAPI, config: ApiConfigBase):
     """Configure a FastAPI app based on a config object."""
     app.root_path = config.api_root_path.rstrip("/")
@@ -235,6 +260,7 @@ def configure_app(app: FastAPI, config: ApiConfigBase):
         kwargs["allow_credentials"] = config.cors_allow_credentials
 
     app.add_middleware(CORSMiddleware, **kwargs)
+    app.add_middleware(BaseHTTPMiddleware, dispatch=request_logging_middleware)
     app.add_middleware(
         BaseHTTPMiddleware,
         dispatch=partial(

tests/integration/test_api.py

@@ -17,13 +17,15 @@
 
 import asyncio
 import multiprocessing
+import re
 import time
 
 import httpx
 import pytest
 from fastapi import FastAPI
 
 from ghga_service_commons.api import ApiConfigBase, run_server
+from ghga_service_commons.api.api import configure_app
 from ghga_service_commons.api.testing import AsyncTestClient
 from ghga_service_commons.httpyexpect.server import HttpException
 from ghga_service_commons.httpyexpect.server.handlers.fastapi_ import (
@@ -32,8 +34,9 @@
 from tests.integration.fixtures.hello_world_test_app import GREETING, app
 from tests.integration.fixtures.utils import find_free_port
 
+pytestmark = pytest.mark.asyncio()
+
 
-@pytest.mark.asyncio
 async def test_run_server():
     """Test the run_server wrapper function."""
     config = ApiConfigBase()
@@ -58,7 +61,6 @@ async def test_run_server():
     assert response.json() == GREETING
 
 
-@pytest.mark.asyncio
 async def test_configure_exception_handler():
     """Test the exception handler configuration of a FastAPI app."""
     # example params for an http exception
@@ -92,3 +94,26 @@ async def test_route():
     assert body["exception_id"] == exception_id
     assert body["description"] == description
     assert body["data"] == data
+
+
+async def test_request_duration_log(caplog):
+    """Check the middleware function that logs request duration in ms."""
+    caplog.set_level("INFO")
+
+    # small fastapi app with basic endpoint
+    test_app = FastAPI()
+    test_app.get("/")(lambda: 200)
+
+    config = ApiConfigBase()
+    configure_app(test_app, config)
+
+    client = AsyncTestClient(test_app)
+    await client.get("/")
+
+    # Get list of the log messages
+    for record in caplog.record_tuples:
+        if record[0] == "ghga_service_commons.api.api":
+            assert re.match(r'GET http://.* "200 OK" - \d+ ms$', record[2])
+            break
+    else:
+        assert False, "Request duration log was not captured"