chore: improve logs on validation report processing functions (#1214)

Author: davidgamez

functions-python/process_validation_report/src/main.py

@@ -32,11 +32,11 @@
     Notice,
     Gtfsdataset,
 )
-from shared.helpers.logger import Logger
+from shared.helpers.logger import init_logger
 from shared.helpers.transform import get_nested_value
 from shared.helpers.feed_status import update_feed_statuses_query
 
-logging.basicConfig(level=logging.INFO)
+init_logger()
 
 FILES_ENDPOINT = os.getenv("FILES_ENDPOINT")
 
@@ -91,11 +91,11 @@ def validate_json_report(json_report_url):
     try:
         json_report, code = read_json_report(json_report_url)
         if code != 200:
-            logging.error(f"Error reading JSON report: {code}")
+            logging.error("Error reading JSON report: %s", code)
             return f"Error reading JSON report at url {json_report_url}.", code
         return json_report, 200
     except Exception as error:  # JSONDecodeError or RequestException
-        logging.error(f"Error reading JSON report: {error}")
+        logging.error("Error reading JSON report: %s", str(error))
         return f"Error reading JSON report at url {json_report_url}: {error}", 500
 
 
@@ -112,11 +112,13 @@ def parse_json_report(json_report):
         if "validatorVersion" in json_report["summary"]:
             version = json_report["summary"]["validatorVersion"]
         logging.info(
-            f"Validation report validated at {validated_at} with version {version}."
+            "Validation report validated_at: %s with version: %s.",
+            validated_at,
+            version,
         )
         return validated_at, version
     except Exception as error:
-        logging.error(f"Error parsing JSON report: {error}")
+        logging.error("Error parsing JSON report: %s", error)
         raise Exception(f"Error parsing JSON report: {error}")
 
 
@@ -135,7 +137,7 @@ def generate_report_entities(
     """
     entities = []
     report_id = f"{dataset_stable_id}_{version}"
-    logging.info(f"Creating validation report entities for {report_id}.")
+    logging.info("Creating validation report entities for: %s.", report_id)
 
     html_report_url = (
         f"{FILES_ENDPOINT}/{feed_stable_id}/{dataset_stable_id}/report_{version}.html"
@@ -146,7 +148,7 @@ def generate_report_entities(
     # Check if report already exists
     # If exists, the function should graceful finish avoiding retry mechanism to trigger again
     if get_validation_report(report_id, session):
-        logging.warning(f"Validation report {report_id} already exists. Terminating.")
+        logging.warning("Validation report %s already exists. Terminating.", report_id)
         return []
 
     validation_report_entity = Validationreport(
@@ -284,8 +286,9 @@ def create_validation_report_entities(
             return str(error), 200
 
         update_feed_statuses_query(db_session, [feed_stable_id])
-
-        return f"Created {len(entities)} entities.", 200
+        result = f"Created {len(entities)} entities."
+        logging.info(result)
+        return result, 200
     except Exception as error:
         logging.error("Error creating validation report entities: : %s", error)
         return f"Error creating validation report entities: {error}", 500
@@ -314,10 +317,9 @@ def process_validation_report(request):
     :param request: Request object containing 'dataset_id' and 'feed_id'
     :return: HTTP response indicating the result of the operation
     """
-    Logger.init_logger()
     request_json = request.get_json(silent=True)
     logging.info(
-        f"Processing validation report function called with request: {request_json}"
+        "Processing validation report function called with request: %s", request_json
     )
     if (
         not request_json
@@ -335,7 +337,10 @@ def process_validation_report(request):
     feed_id = request_json["feed_id"]
     validator_version = request_json["validator_version"]
     logging.info(
-        f"Processing validation report version {validator_version} for dataset {dataset_id} in feed {feed_id}."
+        "Processing validation report version: %s for dataset: %s in feed: %s.",
+        validator_version,
+        dataset_id,
+        feed_id,
     )
     return create_validation_report_entities(feed_id, dataset_id, validator_version)
 
@@ -370,8 +375,10 @@ def compute_validation_report_counters(request, db_session: Session):
             .offset(offset)
             .all()
         )
-        print(
-            f"Processing {len(validation_reports)} validation reports from offset {offset}."
+        logging.info(
+            "Processing %s validation reports from offset: %s.",
+            len(validation_reports),
+            offset,
         )
         # Break the loop if no more reports are found
         if len(validation_reports) == 0:
@@ -380,10 +387,17 @@ def compute_validation_report_counters(request, db_session: Session):
         for report in validation_reports:
             populate_counters(report.notices, report)
             logging.info(
-                f"Updated ValidationReport {report.id} with counters: "
-                f"INFO={report.total_info}, WARNING={report.total_warning}, ERROR={report.total_error}, "
-                f"Unique INFO Code={report.unique_info_count}, Unique WARNING Code={report.unique_warning_count}, "
-                f"Unique ERROR Code={report.unique_error_count}"
+                "Updated ValidationReport %s with counters: "
+                "INFO=%s, WARNING=%s, ERROR=%s, "
+                "Unique INFO Code=%s, Unique WARNING Code=%s, "
+                "Unique ERROR Code=%s",
+                report.id,
+                report.total_info,
+                report.total_warning,
+                report.total_error,
+                report.unique_info_count,
+                report.unique_warning_count,
+                report.unique_error_count,
             )
 
         # Commit the changes for the current batch
@@ -420,7 +434,7 @@ def process_validation_report_notices(notices):
                 total_error += notice.total_notices
                 error_codes.add(notice.notice_code)
             case _:
-                logging.warning(f"Unknown severity: {notice.severity}")
+                logging.warning("Unknown severity: %s", notice.severity)
 
     return {
         "total_info": total_info,

functions-python/process_validation_report/tests/test_validation_report.py

@@ -206,9 +206,8 @@ def test_create_validation_report_entities_missing_dataset(self, mock_get):
             message,
         )
 
-    @patch("main.Logger")
     @patch("main.create_validation_report_entities")
-    def test_process_validation_report(self, create_validation_report_entities_mock, _):
+    def test_process_validation_report(self, create_validation_report_entities_mock):
         request = MagicMock(
             get_json=MagicMock(
                 return_value={
@@ -221,10 +220,9 @@ def test_process_validation_report(self, create_validation_report_entities_mock,
         process_validation_report(request)
         create_validation_report_entities_mock.assert_called_once()
 
-    @patch("main.Logger")
     @patch("main.create_validation_report_entities")
     def test_process_validation_report_invalid_request(
-        self, create_validation_report_entities_mock, _
+        self, create_validation_report_entities_mock
     ):
         request = MagicMock(
             get_json=MagicMock(

functions-python/update_validation_report/src/main.py

@@ -35,10 +35,10 @@
 from shared.helpers.gtfs_validator_common import get_gtfs_validator_results_bucket
 from shared.database.database import with_db_session
 
-from shared.helpers.logger import Logger
+from shared.helpers.logger import init_logger
 from shared.helpers.validation_report.validation_report_update import execute_workflows
 
-logging.basicConfig(level=logging.INFO)
+init_logger()
 env = os.getenv("ENV", "dev").lower()
 bucket_name = f"mobilitydata-datasets-{env}"
 
@@ -49,8 +49,6 @@ def update_validation_report(request: flask.Request, db_session: Session):
     """
     Update the validation report for the datasets that need it
     """
-    Logger.init_logger()
-
     request_json = request.get_json()
     validator_endpoint = request_json.get(
         "validator_endpoint", os.getenv("WEB_VALIDATOR_URL")
@@ -77,10 +75,10 @@ def update_validation_report(request: flask.Request, db_session: Session):
     latest_datasets = get_latest_datasets_without_validation_reports(
         db_session, validator_version, force_update
     )
-    logging.info(f"Retrieved {len(latest_datasets)} latest datasets.")
+    logging.info("Retrieved %s latest datasets.", len(latest_datasets))
 
     valid_latest_datasets = get_datasets_for_validation(latest_datasets)
-    logging.info(f"Retrieved {len(latest_datasets)} blobs to update.")
+    logging.info("Retrieved %s blobs to update.", len(latest_datasets))
 
     execution_triggered_datasets = execute_workflows(
         valid_latest_datasets, validator_endpoint, bypass_db_update, reports_bucket_name
@@ -115,7 +113,7 @@ def get_validator_version(validator_url: str) -> str:
     """
     response = requests.get(f"{validator_url}/version")
     validator_version = response.json()["version"]
-    logging.info(f"Validator version: {validator_version}")
+    logging.info("Validator version: %s", validator_version)
     return validator_version
 
 
@@ -172,7 +170,9 @@ def get_datasets_for_validation(
             else:
                 report_update_needed.append((feed_id, dataset_id))
                 logging.info(
-                    f"Dataset blob found for {feed_id}/{dataset_id} -- Adding to update list"
+                    "Dataset blob found for %s/%s -- Adding to update list",
+                    feed_id,
+                    dataset_id,
                 )
         except Exception as e:
             logging.error(

functions-python/update_validation_report/tests/test_update_validation_report.py

@@ -103,7 +103,6 @@ def create_dataset_blob(name, exists):
     @patch("google.cloud.storage.Blob", autospec=True)
     @patch("requests.get", autospec=True)
     @patch("google.cloud.storage.Client", autospec=True)
-    @patch("main.Logger", autospec=True)
     @patch("google.cloud.workflows_v1.WorkflowsClient", autospec=True)
     @patch("google.cloud.workflows.executions_v1.ExecutionsClient", autospec=True)
     @patch("google.cloud.workflows.executions_v1.Execution", autospec=True)
@@ -112,7 +111,6 @@ def test_update_validation_report(
         execution_mock,
         executions_client_mock,
         workflows_client_mock,
-        mock_logger,
         mock_client,
         mock_get,
         mock_blob,

functions-python/validation_to_ndjson/src/main.py

@@ -4,7 +4,7 @@
 import functions_framework
 from cloudevents.http import CloudEvent
 
-from shared.helpers.logger import Logger
+from shared.helpers.logger import init_logger
 from google.cloud import storage
 from validation_report_converter import (
     ValidationReportConverter,
@@ -13,7 +13,7 @@
 )
 
 
-logging.basicConfig(level=logging.INFO)
+init_logger()
 
 
 def parse_resource_data(data: dict) -> tuple:
@@ -39,11 +39,14 @@ def convert_reports_to_ndjson(cloud_event: CloudEvent):
     Convert a validation report to NDJSON format.
     @param cloud_event: The CloudEvent object.
     """
-    Logger.init_logger()
     logging.info("Function triggered")
     stable_id, dataset_id, report_id, url = parse_resource_data(cloud_event.data)
     logging.info(
-        f"Stable ID: {stable_id}, Dataset ID: {dataset_id}, URL: {url}, Report ID: {report_id}"
+        "Stable ID: %s, Dataset ID: %s, URL: %s, Report ID: %s",
+        stable_id,
+        dataset_id,
+        url,
+        report_id,
     )
     converter_type = ValidationReportConverter.get_converter()
     converter_type(stable_id, dataset_id, report_id, url).process()
@@ -53,7 +56,6 @@ def convert_reports_to_ndjson(cloud_event: CloudEvent):
 @functions_framework.http
 def batch_convert_reports_to_ndjson(request: flask.Request):
     """Batch convert all reports in the bucket to NDJSON format."""
-    Logger.init_logger()
     logging.info("Function triggered")
 
     # 1. Get the validator version from the request
@@ -62,7 +64,7 @@ def batch_convert_reports_to_ndjson(request: flask.Request):
         validator_version = request_json.get("validator_version", "")
         report_suffix = f"{validator_version}.json"
     except Exception as e:
-        logging.error(f"Failed to get validator version: {e}")
+        logging.error("Failed to get validator version: %s", e)
         report_suffix = ".json"
 
     # 2. Get all reports in the bucket
@@ -73,7 +75,7 @@ def batch_convert_reports_to_ndjson(request: flask.Request):
         for blob in blobs
         if "report_" in blob.name and blob.name.endswith(report_suffix)
     ]
-    logging.info(f"Found {len(report_blobs)} reports to process.")
+    logging.info("Found %s reports to process.", len(report_blobs))
 
     # 3. For each report create cloud event and call convert_reports_to_ndjson
     for blob in report_blobs:

functions-python/validation_to_ndjson/src/validation_report_converter.py

@@ -32,7 +32,7 @@ def __init__(
         try:
             self.validation_report = requests.get(validation_report_url).json()
         except Exception as e:
-            logging.error(f"Failed to download the validation report: {e}")
+            logging.error("Failed to download the validation report: %", e)
             self.validation_report = None
         self.stable_id = stable_id
         self.dataset_id = dataset_id
@@ -69,7 +69,7 @@ def process(self) -> None:
             f"{self.report_id}.ndjson"
         )
         if self.validation_report is None:
-            logging.error(f"Validation report is empty for {self.report_id}.")
+            logging.error("Validation report is empty for %s.", self.report_id)
             return
 
         # Add feedId to the JSON data
@@ -93,7 +93,7 @@ def process(self) -> None:
         ndjson_content = json.dumps(json_data, separators=(",", ":"))
         ndjson_blob = bucket.blob(ndjson_blob_name)
         ndjson_blob.upload_from_string(ndjson_content + "\n")
-        logging.info(f"Processed and uploaded {ndjson_blob_name}")
+        logging.info("Processed and uploaded %s to", ndjson_blob_name)
 
 
 class GTFSValidationReportConverter(ValidationReportConverter):

functions-python/validation_to_ndjson/tests/test_main.py

@@ -9,11 +9,10 @@
 
 
 class TestReportConversionFunctions(unittest.TestCase):
-    @patch("main.Logger.init_logger")
     @patch("main.ValidationReportConverter.get_converter")
     @patch("main.parse_resource_data")
     def test_convert_reports_to_ndjson(
-        self, mock_parse_resource_data, mock_get_converter, mock_init_logger
+        self, mock_parse_resource_data, mock_get_converter
     ):
         # Setup mocks
         mock_converter_class = MagicMock()
@@ -42,7 +41,6 @@ def test_convert_reports_to_ndjson(
         result = convert_reports_to_ndjson(cloud_event)
 
         # Assertions
-        mock_init_logger.assert_called_once()
         mock_parse_resource_data.assert_called_once_with(cloud_event.data)
         mock_get_converter.assert_called_once()
         mock_converter_class.assert_called_once_with(
@@ -51,11 +49,10 @@ def test_convert_reports_to_ndjson(
         mock_converter_instance.process.assert_called_once()
         self.assertEqual(result, ("stable_id", "dataset_id", "url"))
 
-    @patch("main.Logger.init_logger")
     @patch("main.storage.Client")
     @patch("main.convert_reports_to_ndjson")
     def test_batch_convert_reports_to_ndjson(
-        self, mock_convert_reports_to_ndjson, mock_storage_client, mock_init_logger
+        self, mock_convert_reports_to_ndjson, mock_storage_client
     ):
         # Setup mocks
         mock_blob1 = MagicMock()
@@ -70,7 +67,6 @@ def test_batch_convert_reports_to_ndjson(
         result = batch_convert_reports_to_ndjson(None)
 
         # Assertions
-        mock_init_logger.assert_called_once()
         mock_storage_client().list_blobs.assert_called_once()
         self.assertEqual(mock_convert_reports_to_ndjson.call_count, 2)
         self.assertEqual(result, "Success converting reports to NDJSON")