improve logging

Author: davidgamez

functions-python/helpers/logger.py

@@ -51,7 +51,9 @@ def init_logger():
     Initializes the logger with level INFO if not set in the environment.
     On cloud environment it will also initialize the GCP logger.
     """
-    logging.basicConfig(level=get_env_logging_level())
+    logging_level = get_env_logging_level()
+    logging.basicConfig(level=logging_level)
+    logging.info("Logger initialized with level: %s", logging_level)
     global _logging_initialized
     if not is_local_env() and not _logging_initialized:
         # Avoids initializing the logs multiple times due to performance concerns
@@ -81,6 +83,7 @@ def get_logger(name: str, stable_id: str = None):
             if stable_id
             else logging.getLogger(name)
         )
+        logger.setLevel(level=get_env_logging_level())
         if stable_id and not any(
             isinstance(log_filter, StableIdFilter) for log_filter in logger.filters
         ):

functions-python/helpers/runtime_metrics.py

@@ -1,10 +1,11 @@
+import functools
 import time
 import tracemalloc
 import psutil
 import logging
 
 
-def track_metrics(metrics=("time", "memory", "cpu"), logger=None):
+def track_metrics(metrics=("time", "memory", "cpu")):
     """Decorator to track specified metrics (time, memory, cpu) during function execution.
     The decorator logs the metrics using the provided logger or a default logger if none is provided.
     Args:
@@ -18,18 +19,13 @@ def example_function():
             return sum(data)
     """
 
-    def decorator(func):
+    def decorator(funct):
+        @functools.wraps(funct)
         def wrapper(*args, **kwargs):
+            logger = kwargs.get("logger")
             if not logger:
                 # Use a default logger if none is provided
-                logger_instance = logging.getLogger(func.__name__)
-                # handler = logging.StreamHandler()
-                # formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
-                # handler.setFormatter(formatter)
-                # logger_instance.addHandler(handler)
-                # logger_instance.setLevel(logging.DEBUG)
-            else:
-                logger_instance = logger
+                logger = logging.getLogger(funct.__name__)
 
             process = psutil.Process()
             tracemalloc.start() if "memory" in metrics else None
@@ -39,30 +35,30 @@ def wrapper(*args, **kwargs):
             )
 
             try:
-                result = func(*args, **kwargs)
+                result = funct(*args, **kwargs)
             except Exception as e:
-                logger_instance.error(
-                    f"Function '{func.__name__}' raised an exception: {e}"
-                )
+                logger.error(f"Function '{funct.__name__}' raised an exception: {e}")
                 raise
             finally:
+                metrics_message = ""
                 if "time" in metrics:
                     duration = time.time() - start_time
-                    logger_instance.debug(
-                        f"Function '{func.__name__}' executed in {duration:.2f} seconds."
-                    )
+                    metrics_message = f"time: {duration:.2f} seconds"
                 if "memory" in metrics:
                     current, peak = tracemalloc.get_traced_memory()
                     tracemalloc.stop()
-                    logger_instance.debug(
-                        f"Function '{func.__name__}' peak memory usage: {peak / (1024 ** 2):.2f} MB."
-                    )
+                    if metrics_message:
+                        metrics_message += ", "
+                    metrics_message += f"memory: {current / (1024 ** 2):.2f} MB (peak: {peak / (1024 ** 2):.2f} MB)"
                 if "cpu" in metrics:
                     cpu_after = process.cpu_percent(interval=None)
-                    logger_instance.debug(
-                        f"Function '{func.__name__}' CPU usage: {cpu_after - cpu_before:.2f}%."
+                    if metrics_message:
+                        metrics_message += ", "
+                    metrics_message += f"cpu: {cpu_after - cpu_before:.2f}%"
+                if len(metrics_message) > 0:
+                    logger.info(
+                        "Function metrics('%s'): %s", funct.__name__, metrics_message
                     )
-
             return result
 
         return wrapper

functions-python/reverse_geolocation/src/reverse_geolocation_processor.py

@@ -385,11 +385,9 @@ def extract_location_aggregates_per_point(
 
 
 @with_db_session
-@track_metrics(
-    metrics=("time", "memory", "cpu"), logger=get_logger(__name__, "stable_id")
-)
+@track_metrics(metrics=("time", "memory", "cpu"))
 def update_dataset_bounding_box(
-    dataset_id: str, stops_df: pd.DataFrame, db_session: Session
+    dataset_id: str, stops_df: pd.DataFrame, logger: logging.Logger, db_session: Session
 ) -> shapely.Polygon:
     """
     Update the bounding box of the dataset using the stops DataFrame.
@@ -476,7 +474,7 @@ def reverse_geolocation_process(
     logger = get_logger(__name__, stable_id)
     try:
         # Update the bounding box of the dataset
-        bounding_box = update_dataset_bounding_box(dataset_id, stops_df)
+        bounding_box = update_dataset_bounding_box(dataset_id, stops_df, logger)
 
         location_groups = reverse_geolocation(
             strategy,
@@ -516,9 +514,7 @@ def reverse_geolocation_process(
         return str(e), ERROR_STATUS_CODE
 
 
-@track_metrics(
-    metrics=("time", "memory", "cpu"), logger=get_logger(__name__, "stable_id")
-)
+@track_metrics(metrics=("time", "memory", "cpu"))
 def reverse_geolocation(
     strategy,
     stable_id,

functions-python/reverse_geolocation/src/scripts/reverse_geolocation_process_verifier.py

@@ -9,6 +9,7 @@
 from google.cloud import storage
 
 from reverse_geolocation_processor import reverse_geolocation_process
+from shared.helpers.logger import init_logger
 
 HOST = "localhost"
 PORT = 9023
@@ -24,6 +25,8 @@
 # Load environment variables from .env.local
 load_dotenv(dotenv_path=".env.local")
 
+init_logger()
+
 
 def download_to_local(url: str, filename: str):
     """

functions-python/reverse_geolocation/tests/test_reverse_geolocation_processor.py

@@ -620,7 +620,7 @@ def test_update_dataset_bounding_box_success(self, db_session):
 
         # Call the function
         bounding_box = update_dataset_bounding_box(
-            dataset_id, stops_df, db_session=db_session
+            dataset_id, stops_df, db_session=db_session, logger=logger
         )
 
         # Expected bounding box: POLYGON((30 10, 40 10, 40 20, 30 20, 30 10))