feat: optimize logging for request and asset upload processes, and enhance debug timing functionality

Author: jirhiker

api/asset.py

@@ -125,7 +125,7 @@ async def upload_asset(
             "asset upload request completed",
             extra={
                 "event": "asset_upload_request_completed",
-                "filename": file.filename,
+                "upload_filename": file.filename,
                 "content_type": file.content_type,
                 "upload_request_ms": round(
                     (time.perf_counter() - request_started_at) * 1000,

core/app.py

@@ -74,9 +74,7 @@ async def log_request_lifecycle(request: Request, call_next):
         request_id = uuid4().hex
         request.state.request_id = request_id
         logger.info(
-            "request started %s %s",
-            request.method,
-            request.url.path,
+            "request started",
             extra={
                 "event": "request_started",
                 "request_id": request_id,
@@ -91,10 +89,7 @@ async def log_request_lifecycle(request: Request, call_next):
             return response
         finally:
             logger.info(
-                "request completed %s %s status=%s",
-                request.method,
-                request.url.path,
-                status_code,
+                "request completed",
                 extra={
                     "event": "request_completed",
                     "request_id": request_id,

db/engine.py

@@ -37,7 +37,17 @@
 logger = logging.getLogger(__name__)
 
 
+def is_pool_logging_enabled() -> bool:
+    return bool(
+        get_bool_env("DB_POOL_LOGGING", False)
+        or get_bool_env("API_DEBUG_TIMING", False)
+    )
+
+
 def _install_pool_logging(engine):
+    if not is_pool_logging_enabled():
+        return
+
     @event.listens_for(engine, "checkout")
     def log_checkout(dbapi_connection, connection_record, connection_proxy):
         connection_record.info["checked_out_at"] = time.perf_counter()

services/gcs_helper.py

@@ -79,14 +79,16 @@ def get_storage_bucket(client=None, bucket: str = None):
 def _log_stage(stage: str, started_at: float, **extra):
     if not is_debug_timing_enabled():
         return
+    record_extra = {
+        "event": "gcs_stage_timing",
+        "stage": stage,
+        "duration_ms": round((time.perf_counter() - started_at) * 1000, 2),
+    }
+    if "filename" in extra:
+        record_extra["upload_filename"] = extra.pop("filename")
     logger.info(
         "gcs stage timing",
-        extra={
-            "event": "gcs_stage_timing",
-            "stage": stage,
-            "duration_ms": round((time.perf_counter() - started_at) * 1000, 2),
-            **extra,
-        },
+        extra={**record_extra, **extra},
     )
 
 

services/sample_helper.py

@@ -1,6 +1,3 @@
-import logging
-import time
-
 from fastapi import HTTPException
 from fastapi_pagination.ext.sqlalchemy import paginate
 from sqlalchemy import select
@@ -21,9 +18,6 @@
 )
 from services.query_helper import order_sort_filter
 
-logger = logging.getLogger(__name__)
-
-
 THING_RESPONSE_BASE = (
     joinedload(Sample.field_activity)
     .joinedload(FieldActivity.field_event)
@@ -60,14 +54,17 @@
 CONTACT_RESPONSE_THING_ASSOCIATIONS = CONTACT_RESPONSE_PARTICIPANT.selectinload(
     Contact.thing_associations
 )
+CONTACT_RESPONSE_THING = CONTACT_RESPONSE_THING_ASSOCIATIONS.selectinload(
+    ThingContactAssociation.thing
+)
 
 
 CONTACT_RESPONSE_LOADER_OPTIONS = (
     CONTACT_RESPONSE_PARTICIPANT.selectinload(Contact.emails),
     CONTACT_RESPONSE_PARTICIPANT.selectinload(Contact.phones),
     CONTACT_RESPONSE_PARTICIPANT.selectinload(Contact.addresses),
     CONTACT_RESPONSE_PARTICIPANT.selectinload(Contact.incomplete_nma_phones),
-    CONTACT_RESPONSE_THING_ASSOCIATIONS.selectinload(ThingContactAssociation.thing),
+    CONTACT_RESPONSE_THING,
     CONTACT_RESPONSE_PARTICIPANT.selectinload(Contact.notes),
 )
 
@@ -103,8 +100,10 @@ def get_db_samples(
     return paginate(query)
 
 
-def get_sample_by_id_with_relationships(session: Session, sample_id: int) -> Sample:
-    started_at = time.perf_counter()
+def get_sample_by_id_with_relationships(
+    session: Session,
+    sample_id: int,
+) -> Sample:
     sql = select(Sample).where(Sample.id == sample_id)
     sql = sql.options(*SAMPLE_LOADER_OPTIONS)
     sample = session.execute(sql).unique().scalar_one_or_none()
@@ -113,16 +112,4 @@ def get_sample_by_id_with_relationships(session: Session, sample_id: int) -> Sam
             status_code=HTTP_404_NOT_FOUND,
             detail=f"Sample with ID {sample_id} not found.",
         )
-
-    duration_ms = round((time.perf_counter() - started_at) * 1000, 2)
-    logger.info(
-        "sample lookup completed sample_id=%s duration_ms=%s",
-        sample_id,
-        duration_ms,
-        extra={
-            "event": "sample_lookup_completed",
-            "sample_id": sample_id,
-            "duration_ms": duration_ms,
-        },
-    )
     return sample