feat: enhance logging with debug timing for various operations and ad…

api/asset.py

@@ -14,12 +14,19 @@
 # limitations under the License.
 # ===============================================================================
 
+import logging
+import time
+
 from fastapi import APIRouter, Depends, UploadFile, File
 from fastapi_pagination.ext.sqlalchemy import paginate
 from sqlalchemy import select
 from sqlalchemy.exc import ProgrammingError
 from starlette.concurrency import run_in_threadpool
-from starlette.status import HTTP_201_CREATED, HTTP_409_CONFLICT, HTTP_204_NO_CONTENT
+from starlette.status import (
+    HTTP_201_CREATED,
+    HTTP_204_NO_CONTENT,
+    HTTP_409_CONFLICT,
+)
 
 from api.pagination import CustomPage
 from core.dependencies import (
@@ -33,16 +40,38 @@
 from schemas.asset import AssetResponse, CreateAsset, UpdateAsset
 from services.audit_helper import audit_add
 from services.crud_helper import model_patcher, model_deleter
+from services.env import get_bool_env
 from services.exceptions_helper import PydanticStyleException
 from services.query_helper import simple_get_by_id
 
 router = APIRouter(prefix="/asset", tags=["asset"])
+logger = logging.getLogger(__name__)
+
+
+def is_debug_timing_enabled() -> bool:
+    return bool(get_bool_env("API_DEBUG_TIMING", False))
 
 
 def get_storage_bucket():
-    from services.gcs_helper import get_storage_bucket as get_gcs_storage_bucket
+    from services.gcs_helper import (
+        get_storage_bucket as get_gcs_storage_bucket,
+    )
 
-    return get_gcs_storage_bucket()
+    started_at = time.perf_counter()
+    try:
+        return get_gcs_storage_bucket()
+    finally:
+        if is_debug_timing_enabled():
+            logger.info(
+                "asset storage bucket resolved",
+                extra={
+                    "event": "asset_storage_bucket_resolved",
+                    "bucket_resolution_ms": round(
+                        (time.perf_counter() - started_at) * 1000,
+                        2,
+                    ),
+                },
+            )
 
 
 def database_error_handler(payload: CreateAsset, error: ProgrammingError) -> None:
@@ -53,8 +82,8 @@ def database_error_handler(payload: CreateAsset, error: ProgrammingError) -> Non
     error_message = error.orig.args[0]["M"]
 
     if (
-        error_message
-        == 'null value in column "thing_id" of relation "asset_thing_association" violates not-null constraint'
+        error_message == 'null value in column "thing_id" of relation '
+        '"asset_thing_association" violates not-null constraint'
     ):
         """
         Developer's notes
@@ -70,10 +99,13 @@ def database_error_handler(payload: CreateAsset, error: ProgrammingError) -> Non
             "input": {"thing_id": payload.thing_id},
         }
 
-    raise PydanticStyleException(status_code=HTTP_409_CONFLICT, detail=[detail])
+    raise PydanticStyleException(
+        status_code=HTTP_409_CONFLICT,
+        detail=[detail],
+    )
 
 
-# POST =========================================================================
+# POST =======================================================================
 @router.post(
     "/upload",
     status_code=HTTP_201_CREATED,
@@ -86,7 +118,21 @@ async def upload_asset(
     from services.gcs_helper import gcs_upload
 
     # GCS client calls are synchronous and can block for large uploads.
+    request_started_at = time.perf_counter()
     uri, blob_name = await run_in_threadpool(gcs_upload, file, bucket)
+    if is_debug_timing_enabled():
+        logger.info(
+            "asset upload request completed",
+            extra={
+                "event": "asset_upload_request_completed",
+                "upload_filename": file.filename,
+                "content_type": file.content_type,
+                "upload_request_ms": round(
+                    (time.perf_counter() - request_started_at) * 1000,
+                    2,
+                ),
+            },
+        )
     return {
         "uri": uri,
         "storage_path": blob_name,
@@ -110,7 +156,11 @@ async def add_asset(
         # this storage path and thing_id
         from services.gcs_helper import check_asset_exists
 
-        existing_asset = check_asset_exists(session, storage_path, thing_id=thing_id)
+        existing_asset = check_asset_exists(
+            session,
+            storage_path,
+            thing_id=thing_id,
+        )
         if existing_asset:
             # If an asset already exists, return it
             return existing_asset
@@ -136,7 +186,7 @@ async def add_asset(
         database_error_handler(asset_data, e)
 
 
-# GET ==========================================================================
+# GET ========================================================================
 
 """
 Developer's notes
@@ -189,11 +239,11 @@ async def get_asset(
 
     asset = simple_get_by_id(session, Asset, asset_id)
 
-    add_signed_url(asset, bucket)
+    asset = await run_in_threadpool(add_signed_url, asset, bucket)
     return asset
 
 
-# PATCH ========================================================================
+# PATCH ======================================================================
 @router.patch("/{asset_id}")
 async def update_asset(
     asset_id: int,
@@ -207,15 +257,16 @@ async def update_asset(
     return model_patcher(session, Asset, asset_id, asset_data, user=user)
 
 
-# DELETE =======================================================================
+# DELETE =====================================================================
 
 
 @router.delete("/{asset_id}", status_code=HTTP_204_NO_CONTENT)
 async def delete_asset(
     asset_id: int, session: session_dependency, user: admin_dependency
 ):
 
-    # TODO: Interesting issue here.  we don't have a way of tracking who deleted a record
+    # TODO: Interesting issue here. We don't have a way of tracking
+    # who deleted a record.
     return model_deleter(session, Asset, asset_id)
 
 

api/sample.py

@@ -27,11 +27,13 @@
 )
 from db.sample import Sample
 from schemas import ResourceNotFoundResponse
-from schemas.sample import SampleResponse, CreateSample, UpdateSample
-from services.query_helper import simple_get_by_id
+from schemas.sample import CreateSample, SampleResponse, UpdateSample
 from services.crud_helper import model_patcher, model_deleter, model_adder
 from services.exceptions_helper import PydanticStyleException
-from services.sample_helper import get_db_samples
+from services.sample_helper import (
+    get_db_samples,
+    get_sample_by_id_with_relationships,
+)
 
 router = APIRouter(
     prefix="/sample",
@@ -42,44 +44,56 @@
 # TODO: add the following database validation handlers
 # invalid sample_id
 # invalid lexicon terms
-# sample_date of the Sample model cannot be before the event_date of the FieldEvent model
+# sample_date of the Sample model cannot be before the
+# event_date of the FieldEvent model
 
 
 def database_error_handler(
-    payload: CreateSample | UpdateSample, error: IntegrityError | ProgrammingError
+    payload: CreateSample | UpdateSample,
+    error: IntegrityError | ProgrammingError,
 ) -> None:
     """
     Handle errors raised by the database when adding or updating a sample.
     """
     error_message = error.orig.args[0]["M"]
     if (
-        error_message
-        == 'duplicate key value violates unique constraint "sample_sample_name_key"'
+        error_message == "duplicate key value violates unique "
+        'constraint "sample_sample_name_key"'
     ):
         detail = {
             "loc": ["body", "sample_name"],
-            "msg": f"Sample with sample_name {payload.sample_name} already exists.",
+            "msg": (
+                f"Sample with sample_name {payload.sample_name} " "already exists."
+            ),
             "type": "value_error",
             "input": {"sample_name": payload.sample_name},
         }
     elif (
         error_message
-        == 'insert or update on table "sample" violates foreign key constraint "sample_field_activity_id_fkey"'
+        == 'insert or update on table "sample" violates foreign key constraint '
+        '"sample_field_activity_id_fkey"'
     ):
         detail = {
             "loc": ["body", "field_activity_id"],
-            "msg": f"FieldActivity with ID {payload.field_activity_id} does not exist.",
+            "msg": (
+                f"FieldActivity with ID {payload.field_activity_id} " "does not exist."
+            ),
             "type": "value_error",
             "input": {"field_activity_id": payload.field_activity_id},
         }
 
-    raise PydanticStyleException(status_code=HTTP_409_CONFLICT, detail=[detail])
+    raise PydanticStyleException(
+        status_code=HTTP_409_CONFLICT,
+        detail=[detail],
+    )
 
 
 # ============= Post =============================================
 @router.post("", status_code=HTTP_201_CREATED)
 async def add_sample(
-    sample_data: CreateSample, session: session_dependency, user: admin_dependency
+    sample_data: CreateSample,
+    session: session_dependency,
+    user: admin_dependency,
 ) -> SampleResponse:
     """
     Endpoint to add a sample.
@@ -106,7 +120,13 @@ async def update_sample(
     try:
         # since this is only one instance N+1 is not a concern for
         # FieldActivity, FieldEvent, and Thing
-        return model_patcher(session, Sample, sample_id, sample_data, user=user)
+        return model_patcher(
+            session,
+            Sample,
+            sample_id,
+            sample_data,
+            user=user,
+        )
     except (IntegrityError, ProgrammingError) as e:
         database_error_handler(sample_data, e)
 
@@ -124,27 +144,38 @@ async def get_samples(
     """
     Endpoint to retrieve samples.
     """
-    return get_db_samples(session, thing_id, sort=sort, order=order, filter_=filter_)
+    return get_db_samples(
+        session,
+        thing_id,
+        sort=sort,
+        order=order,
+        filter_=filter_,
+    )
 
 
 @router.get("/{sample_id}", summary="Get Sample by ID")
 async def get_sample_by_id(
-    sample_id: int, session: session_dependency, user: viewer_dependency
+    sample_id: int,
+    session: session_dependency,
+    user: viewer_dependency,
 ) -> SampleResponse | ResourceNotFoundResponse:
     """
     Endpoint to retrieve a sample by its ID.
     """
-    # since this is only one instance N+1 is not a concern
-    # FieldActivity, FieldEvent, and Thing
-    return simple_get_by_id(session, Sample, sample_id)
+    return get_sample_by_id_with_relationships(session, sample_id)
 
 
 # ======= DELETE ===============================================================
 
 
-@router.delete("/{sample_id}", summary="Delete Sample by ID")
+@router.delete(
+    "/{sample_id}",
+    summary="Delete Sample by ID",
+)
 async def delete_sample_by_id(
-    sample_id: int, session: session_dependency, user: admin_dependency
+    sample_id: int,
+    session: session_dependency,
+    user: admin_dependency,
 ) -> Response:
     return model_deleter(session, Sample, sample_id)
 

api/thing.py

@@ -52,6 +52,7 @@
     UpdateWellScreen,
 )
 from schemas.well_details import WellDetailsResponse
+from schemas.well_export import WellExportResponse
 from services.crud_helper import model_patcher, model_adder, model_deleter
 from services.exceptions_helper import PydanticStyleException
 from services.lexicon_helper import get_terms_by_category
@@ -69,7 +70,10 @@
     modify_well_descriptor_tables,
     WELL_DESCRIPTOR_MODEL_MAP,
 )
-from services.well_details_helper import get_well_details_payload
+from services.well_details_helper import (
+    get_well_details_payload,
+    get_well_export_payload,
+)
 
 router = APIRouter(prefix="/thing", tags=["thing"])
 
@@ -201,6 +205,27 @@ async def get_well_details(
     )
 
 
+@router.get(
+    "/water-well/{thing_id}/export",
+    summary="Get water well export payload",
+    status_code=HTTP_200_OK,
+)
+async def get_well_export(
+    user: viewer_dependency,
+    thing_id: int,
+    session: session_dependency,
+    request: Request,
+) -> WellExportResponse:
+    """
+    Retrieve the minimal payload needed for field sheet export generation.
+    """
+    return get_well_export_payload(
+        session=session,
+        request=request,
+        thing_id=thing_id,
+    )
+
+
 @router.get(
     "/water-well/{thing_id}/well-screen",
     summary="Get well screens by water well ID",