Merge pull request #1368 from cmu-delphi/krivard/improve-acrhiver-logging

Improve runner logging

Author: krivard

_delphi_utils_python/delphi_utils/archive.py

@@ -307,8 +307,9 @@ def filter_exports(self, common_diffs: FileDiffMap):
             else:
                 replace(diff_file, exported_file)
 
-    def run(self):
+    def run(self, logger=None):
         """Run the differ and archive the changed and new files."""
+        start_time = time.time()
         self.update_cache()
 
         # Diff exports, and make incremental versions
@@ -317,6 +318,11 @@ def run(self):
         # Archive changed and new files only
         to_archive = [f for f, diff in common_diffs.items()
                       if diff is not None]
+        if logger:
+            logger.debug("Diffed exports",
+                         phase="archiving",
+                         new_files_count=len(new_files),
+                         common_diffs_count=len(to_archive))
         to_archive += new_files
         _, fails = self.archive_exports(to_archive)
 
@@ -329,6 +335,14 @@ def run(self):
         for exported_file in fails:
             print(f"Failed to archive '{exported_file}'")
 
+        elapsed_time_in_seconds = round(time.time() - start_time, 2)
+        if logger:
+            logger.info("Completed archive run",
+                        phase="archiving",
+                        elapsed_time_in_seconds=elapsed_time_in_seconds,
+                        new_changed_count=len(to_archive),
+                        fail_count=len(fails))
+
 
 class S3ArchiveDiffer(ArchiveDiffer):
     """
@@ -685,10 +699,5 @@ def update_cache(self):
     logger = get_structured_logger(
         __name__, filename=_params["common"].get("log_filename"),
         log_exceptions=_params["common"].get("log_exceptions", True))
-    start_time = time.time()
-
-    archiver_from_params(_params).run()
 
-    elapsed_time_in_seconds = round(time.time() - start_time, 2)
-    logger.info("Completed archive run.",
-                elapsed_time_in_seconds=elapsed_time_in_seconds)
+    archiver_from_params(_params).run(logger)

_delphi_utils_python/delphi_utils/runner.py

@@ -36,17 +36,19 @@ def run_indicator_pipeline(indicator_fn:  Callable[[Params], None],
         None if no archiving should be performed.
     """
     params = read_params()
+    logger = get_structured_logger(
+        name=indicator_fn.__module__,
+        filename=params["common"].get("log_filename", None),
+        log_exceptions=params["common"].get("log_exceptions", True))
     indicator_fn(params)
     validator = validator_fn(params)
     archiver = archiver_fn(params)
     if validator:
         validation_report = validator.validate()
-        validation_report.log(get_structured_logger(
-            name = indicator_fn.__module__,
-            filename=params["common"].get("log_filename", None)))
+        validation_report.log(logger)
     if (not validator or validation_report.success()):
         if archiver:
-            archiver.run()
+            archiver.run(logger)
         if "delivery" in params:
             transfer_files()