Merge pull request #235 from ecmwf-projects/COPDS-2353-better-logs

Enhance logs

Author: mcucchi9

cads_processing_api_service/clients.py

@@ -108,7 +108,8 @@ 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")
+        structlog.contextvars.bind_contextvars(client_endpoint="get_processes")
+        logger.info("get_processes")
         statement = sqlalchemy.select(self.process_table)
         sort_key, sort_dir = utils.parse_sortby(sortby.name)
         if cursor:
@@ -161,8 +162,9 @@ def get_process(
             Process description.
         """
         structlog.contextvars.bind_contextvars(
-            operation="get_process", process_id=process_id
+            client_endpoint="get_process", process_id=process_id
         )
+        logger.info("get_process")
         catalogue_sessionmaker = db_utils.get_catalogue_sessionmaker(
             db_utils.ConnectionMode.read
         )
@@ -219,10 +221,11 @@ def post_process_execution(
         """
         structlog.contextvars.bind_contextvars(
             **auth_info.model_dump(),
-            operation="post_process_execution",
+            client_endpoint="post_process_execution",
             process_id=process_id,
             execution_content=execution_content.model_dump(),
         )
+        logger.info("post_process_execution")
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.process_execution.post,
             auth_info,
@@ -379,8 +382,9 @@ def get_jobs(
             List of jobs status information.
         """
         structlog.contextvars.bind_contextvars(
-            **auth_info.model_dump(), operation="get_jobs"
+            **auth_info.model_dump(), client_endpoint="get_jobs"
         )
+        logger.info("get_jobs")
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.jobs.get,
             auth_info,
@@ -501,8 +505,9 @@ def get_job(
             Job status information.
         """
         structlog.contextvars.bind_contextvars(
-            **auth_info.model_dump(), job_id=job_id, operation="get_job"
+            **auth_info.model_dump(), job_id=job_id, client_endpoint="get_job"
         )
+        logger.info("get_job")
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.job.get,
             auth_info,
@@ -630,8 +635,9 @@ def get_job_results(
             Job results.
         """
         structlog.contextvars.bind_contextvars(
-            **auth_info.model_dump(), job_id=job_id, operation="get_job_results"
+            **auth_info.model_dump(), job_id=job_id, client_endpoint="get_job_results"
         )
+        logger.info("get_job_results")
         _ = limits.check_rate_limits(
             SETTINGS.rate_limits.job_results.get,
             auth_info,

cads_processing_api_service/costing.py

@@ -28,8 +28,8 @@
 
 
 class RequestOrigin(str, enum.Enum):
-    api: str = "api"
-    ui: str = "ui"
+    api = "api"
+    ui = "ui"
 
 
 def estimate_cost(

cads_processing_api_service/exceptions.py

@@ -63,6 +63,14 @@ class RateLimitExceeded(ogc_api_processes_fastapi.exceptions.OGCAPIException):
     retry_after: int = 0
 
 
+def find_last_context_line(lines: list[str]) -> int:
+    index = 0
+    for i, line in enumerate(lines):
+        if "result = context.run(func, *args)" in line:
+            index = len(lines) - i - 1
+    return index
+
+
 def format_exception_content(
     exc: ogc_api_processes_fastapi.exceptions.OGCAPIException,
     request: fastapi.Request | None = None,
@@ -201,9 +209,11 @@ def general_exception_handler(
     -------
     fastapi.responses.JSONResponse
     """
+    exc_traceback = list(traceback.TracebackException.from_exception(exc).format())
+    last_context_line = find_last_context_line(list(exc_traceback))
     logger.error(
         "internal server error",
-        exception="".join(traceback.TracebackException.from_exception(exc).format()),
+        exception="".join(exc_traceback[-last_context_line:]),
     )
     out = fastapi.responses.JSONResponse(
         status_code=fastapi.status.HTTP_500_INTERNAL_SERVER_ERROR,

cads_processing_api_service/limits.py

@@ -41,8 +41,8 @@ def check_rate_limits_for_user(
             for rate_limit in rate_limits_exceeded
         ]
         expiry = storage.get_expiry(user_uid)
-        time_to_wait = max(
-            [reset_time - expiry for reset_time in rate_limiters_reset_time]
+        time_to_wait = round(
+            max([reset_time - expiry for reset_time in rate_limiters_reset_time])
         )
         raise exceptions.RateLimitExceeded(
             detail=f"Rate limit exceeded. Please wait {time_to_wait} seconds.",

cads_processing_api_service/main.py

@@ -93,7 +93,7 @@ async def initialize_logger(
 ) -> Any:
     structlog.contextvars.clear_contextvars()
     trace_id = str(uuid.uuid4())
-    structlog.contextvars.bind_contextvars(trace_id=trace_id)
+    structlog.contextvars.bind_contextvars(trace_id=trace_id, request=request.url.path)
     response = await call_next(request)
     return response
 

cads_processing_api_service/models.py

@@ -32,10 +32,10 @@ class AuthInfo(pydantic.BaseModel):
 
 
 class StatusCode(str, enum.Enum):
-    accepted: str = "accepted"
-    running: str = "running"
-    successful: str = "successful"
-    failed: str = "failed"
+    accepted = "accepted"
+    running = "running"
+    successful = "successful"
+    failed = "failed"
 
 
 class StatusInfoMetadata(pydantic.BaseModel):

cads_processing_api_service/utils.py

@@ -44,13 +44,13 @@
 
 
 class ProcessSortCriterion(str, enum.Enum):
-    resource_uid_asc: str = "id"
-    resource_uid_desc: str = "-id"
+    resource_uid_asc = "id"
+    resource_uid_desc = "-id"
 
 
 class JobSortCriterion(str, enum.Enum):
-    created_at_asc: str = "created"
-    created_at_desc: str = "-created"
+    created_at_asc = "created"
+    created_at_desc = "-created"
 
 
 @cachetools.cached(