Merge pull request #3 from slohse/more-logging

More logging
Molmed · Sep 3, 2018 · d1935e6 · d1935e6
2 parents 0b5732d + 956a3fb
commit d1935e6
Showing 1 changed file with 21 additions and 3 deletions.
diff --git a/archive_verify/workers.py b/archive_verify/workers.py
@@ -3,6 +3,7 @@
 import rq
 import subprocess
 import os
+import datetime
 
 log = logging.getLogger(__name__)
 
@@ -39,13 +40,13 @@ def _parse_dsmc_return_code(exit_code, output, whitelist):
 
         for warning in warnings:
             if warning not in whitelist:
-                log.debug("A non-whitelisted DSMC warning was encountered. Reporting it as an error!")
+                log.error("A non-whitelisted DSMC warning was encountered. Reporting it as an error! ('{}')".format(warning))
                 return False
 
         log.debug("Only whitelisted DSMC warnings were encountered. Everything is OK.")
         return True
     else:
-        log.info("An uncatched DSMC error code was encountered!")
+        log.error("An uncaught DSMC error code was encountered!")
         return False
 
 def download_from_pdc(archive, description, dest, dsmc_log_dir, whitelist):
@@ -59,7 +60,8 @@ def download_from_pdc(archive, description, dest, dsmc_log_dir, whitelist):
     :param whitelist: A list of dsmc warnings which we shall allow to be generated by dsmc but still count the download as successful
     :returns True if no errors or only whitelisted warnings were encountered, False otherwise 
     """
-    cmd = "export DMS_LOG={} && dsmc retr {}/ {}/ -subdir=yes -description='{}'".format(dsmc_log_dir, archive, dest, description)
+    log.debug("download_from_pdc started for {}".format(archive))
+    cmd = "export DSM_LOG={} && dsmc retr {}/ {}/ -subdir=yes -description='{}'".format(dsmc_log_dir, archive, dest, description)
     p = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
 
     dsmc_output, _ = p.communicate()
@@ -68,6 +70,7 @@ def download_from_pdc(archive, description, dest, dsmc_log_dir, whitelist):
     if dsmc_exit_code != 0:
         return _parse_dsmc_return_code(dsmc_exit_code, dsmc_output, whitelist)
 
+    log.debug("download_from_pdc completed successfully for {}".format(archive))
     return True
 
 def compare_md5sum(archive_dir):
@@ -104,19 +107,34 @@ def verify_archive(archive, archive_path, description, config):
     dest_root = config["verify_root_dir"]
     dsmc_log_dir = config["dsmc_log_dir"]
     whitelist = config["whitelisted_warnings"]
+
+    now_str = datetime.datetime.now().strftime('%Y-%m-%d_%H-%M')
+    log.setLevel(logging.DEBUG)
+    fh = logging.FileHandler(os.path.join(dsmc_log_dir, "{}-{}.log".format(description, now_str)))
+    fh.setLevel(logging.DEBUG)
+    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+    fh.setFormatter(formatter)
+    log.addHandler(fh)
+
+    log.debug("verify_archive started for {}".format(archive))
+
     job_id = rq.get_current_job().id
     dest = "{}_{}".format(os.path.join(dest_root, archive), job_id)
 
     download_ok = download_from_pdc(archive_path, description, dest, dsmc_log_dir, whitelist)
 
     if not download_ok:
+        log.debug("Download of {} failed.".format(archive))
         return {"state": "error", "msg": "failed to properly download archive from pdc", "path": dest}
     else:
+        log.debug("verifying {}".format(archive))
         archive = os.path.join(dest, archive)
         verified_ok = compare_md5sum(archive)
         output_file = "{}/compare_md5sum.out".format(dest)
 
         if verified_ok:
+            log.debug("Verify of {} succeeded.".format(archive))
             return {"state": "done", "path": output_file, "msg": "sucessfully verified archive md5sums"}
         else:
+            log.debug("Verify of {} failed.".format(archive))
             return {"state": "error", "path": output_file, "msg": "failed to verify archive md5sums"}