Merge pull request #233 from ecmwf-projects/COPDS-2353-rationalize-logging

Rationalize logging

Author: mcucchi9

cads_processing_api_service/clients.py

@@ -108,6 +108,7 @@ def get_processes(
         back : bool | None, optional
             Specifies in which sense the list of processes should be traversed, used for pagination.
         """
+        structlog.contextvars.bind_contextvars(operation="get_processes")
         statement = sqlalchemy.select(self.process_table)
         sort_key, sort_dir = utils.parse_sortby(sortby.name)
         if cursor:
@@ -159,6 +160,9 @@ def get_process(
         ogc_api_processes_fastapi.models.ProcessDescription
             Process description.
         """
+        structlog.contextvars.bind_contextvars(
+            operation="get_process", process_id=process_id
+        )
         catalogue_sessionmaker = db_utils.get_catalogue_sessionmaker(
             db_utils.ConnectionMode.read
         )
@@ -213,11 +217,16 @@ def post_process_execution(
         models.StatusInfo
             Submitted job's status information.
         """
+        structlog.contextvars.bind_contextvars(
+            **auth_info.model_dump(),
+            operation="post_process_execution",
+            process_id=process_id,
+            execution_content=execution_content.model_dump(),
+        )
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.process_execution.post,
             auth_info,
         )
-        structlog.contextvars.bind_contextvars(user_uid=auth_info.user_uid)
         request_body = execution_content.model_dump()
         portals = (
             [p.strip() for p in auth_info.portal_header.split(",")]
@@ -369,6 +378,9 @@ def get_jobs(
         models.JobList
             List of jobs status information.
         """
+        structlog.contextvars.bind_contextvars(
+            **auth_info.model_dump(), operation="get_jobs"
+        )
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.jobs.get,
             auth_info,
@@ -488,6 +500,9 @@ def get_job(
         models.StatusInfo
             Job status information.
         """
+        structlog.contextvars.bind_contextvars(
+            **auth_info.model_dump(), job_id=job_id, operation="get_job"
+        )
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.job.get,
             auth_info,
@@ -503,6 +518,9 @@ def get_job(
             else db_utils.ConnectionMode.read
         )
         try:
+            structlog.contextvars.bind_contextvars(
+                compute_connection_mode=compute_connection_mode
+            )
             compute_sessionmaker = db_utils.get_compute_sessionmaker(
                 mode=compute_connection_mode
             )
@@ -528,8 +546,12 @@ def get_job(
             if compute_connection_mode == db_utils.ConnectionMode.write:
                 raise
             else:
+                compute_connection_mode = db_utils.ConnectionMode.write
+                structlog.contextvars.bind_contextvars(
+                    compute_connection_mode=compute_connection_mode
+                )
                 compute_sessionmaker = db_utils.get_compute_sessionmaker(
-                    mode=db_utils.ConnectionMode.write
+                    mode=compute_connection_mode
                 )
                 with compute_sessionmaker() as compute_session:
                     job = utils.get_job_from_broker_db(
@@ -607,19 +629,22 @@ def get_job_results(
         ogc_api_processes_fastapi.models.Results
             Job results.
         """
+        structlog.contextvars.bind_contextvars(
+            **auth_info.model_dump(), job_id=job_id, operation="get_job_results"
+        )
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.job_results.get,
             auth_info,
         )
-        structlog.contextvars.bind_contextvars(
-            job_id=job_id, user_uid=auth_info.user_uid
-        )
         compute_connection_mode = (
             db_utils.ConnectionMode.write
             if auth_info.request_origin == "ui"
             else db_utils.ConnectionMode.read
         )
         try:
+            structlog.contextvars.bind_contextvars(
+                compute_connection_mode=compute_connection_mode
+            )
             compute_sessionmaker = db_utils.get_compute_sessionmaker(
                 mode=compute_connection_mode
             )
@@ -636,6 +661,10 @@ def get_job_results(
             if compute_connection_mode == db_utils.ConnectionMode.write:
                 raise
             else:
+                compute_connection_mode = db_utils.ConnectionMode.write
+                structlog.contextvars.bind_contextvars(
+                    compute_connection_mode=compute_connection_mode
+                )
                 compute_sessionmaker = db_utils.get_compute_sessionmaker(
                     mode=db_utils.ConnectionMode.write
                 )
@@ -671,13 +700,14 @@ def delete_job(
         ogc_api_processes_fastapi.models.StatusInfo
             Job status information
         """
+        structlog.contextvars.bind_contextvars(
+            **auth_info.model_dump(), job_id=job_id, operation="delete_job"
+        )
+        logger.info("delete_job")
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.job.delete,
             auth_info,
         )
-        structlog.contextvars.bind_contextvars(
-            job_id=job_id, user_id=auth_info.user_uid
-        )
         compute_sessionmaker = db_utils.get_compute_sessionmaker(
             mode=db_utils.ConnectionMode.write
         )

cads_processing_api_service/utils.py

@@ -463,15 +463,19 @@ def get_job_from_broker_db(
     """
     try:
         job = cads_broker.database.get_request(request_uid=job_id, session=session)
+        structlog.contextvars.bind_contextvars(job_status=job.status)
         if job.status in ("dismissed", "deleted"):
+            logger.error("job status is dismissed or deleted")
             raise ogc_api_processes_fastapi.exceptions.NoSuchJob(
                 detail=f"job {job_id} {job.status}"
             )
     except cads_broker.database.NoResultFound:
+        logger.error("job not found")
         raise ogc_api_processes_fastapi.exceptions.NoSuchJob(
             detail=f"job {job_id} not found"
         )
     except cads_broker.database.InvalidRequestID:
+        logger.error("invalid job id")
         raise ogc_api_processes_fastapi.exceptions.NoSuchJob(
             detail=f"invalid job id {job_id}"
         )

tests/test_30_limits.py

@@ -39,7 +39,7 @@ def test_check_rate_limits_for_user() -> None:
             cads_processing_api_service.limits.check_rate_limits_for_user(
                 user_uid, rate_limits
             )
-    assert exc.value.retry_after == 60
+    assert exc.value.retry_after == pytest.approx(60)
 
     rate_limit_ids = ["2/second"]
     rate_limits = [limits.parse(rate_limit_id) for rate_limit_id in rate_limit_ids]