Improve logging

VERSIONLOG.md

@@ -1,5 +1,9 @@
 # TACA Version Log
 
+## 20251106.1
+
+Improve logging
+
 ## 20251015.1
 
 Bugfix: Get all available samples in get_noindex_stats

taca/__init__.py

@@ -1,3 +1,3 @@
 """Main TACA module"""
 
-__version__ = "1.6.11"
+__version__ = "1.6.12"

taca/analysis/analysis.py

@@ -516,6 +516,7 @@ def _process(run):
                 run.archive_run(CONFIG["storage"]["archive_dirs"][run.sequencer_type])
 
     if run:
+        logger.info(f"Starting processing of run {run}")
         # Determine the run type
         runObj = get_runObj(run, software)
         if not runObj:
@@ -524,7 +525,9 @@ def _process(run):
             )
         else:
             _process(runObj)
+        logger.info(f"Finished processing run {run}")
     else:
+        logger.info("Starting processing of all runs in data directories")
         data_dirs = CONFIG.get("analysis").get("data_dirs")
         mail_recipients = CONFIG.get("mail", {}).get("recipients")
         for data_dir in data_dirs:
@@ -573,3 +576,4 @@ def _process(run):
                             )
                             misc.send_mail(subject, message, mail_recipients)
                         pass
+        logger.info("Finished processing all runs in data directories")

taca/analysis/analysis_element.py

@@ -178,16 +178,19 @@ def _process(run_to_process):
             return
 
     if given_run:
+        logger.info(f"Starting processing of run {given_run}")
         _process(given_run)
+        logger.info(f"Finished processing run {given_run}")
     else:
+        logger.info("Starting processing of all runs in data directories")
         data_dirs = CONFIG.get("element_analysis").get("data_dirs")
         for data_dir in data_dirs:
             # Run folder looks like DATE_*_*, the last section is the FC side (A/B) and ID (PID for teton runs)
             runs = glob.glob(os.path.join(data_dir, "[1-9]*_*_*"))
             for run in runs:
                 if "FlowcellPressureCheck" in run:
                     # Skip the pressure check runs (Teton runs)
-                    logger.info(f"Skipping {run}")  # TODO: should these be synced?
+                    logger.info(f"Skipping {run}")
                     continue
                 try:
                     _process(run)
@@ -205,3 +208,4 @@ def _process(run_to_process):
                         f"There was an error processing the run {run}. Error: {e}"
                     )
                     pass
+        logger.info("Finished processing all runs in data directories")

taca/analysis/analysis_nanopore.py

@@ -119,10 +119,13 @@ def ont_transfer(run_abspath: str | None):
     """
 
     if run_abspath:
+        logger.info(f"Starting processing of run {run_abspath}")
         process_run(ONT_run(run_abspath))
+        logger.info(f"Finished processing run {run_abspath}")
 
     # If no run is specified, locate all runs
     else:
+        logger.info("Starting processing of all runs in data directories")
         data_dirs = CONFIG["nanopore_analysis"]["data_dirs"]
         ignore_dirs = CONFIG["nanopore_analysis"]["ignore_dirs"]
 
@@ -137,6 +140,7 @@ def ont_transfer(run_abspath: str | None):
                     logger.info(e)
                 except Exception as e:
                     send_error_mail(os.path.basename(run_dir), e)
+        logger.info("Finished processing all runs in data directories")
 
 
 class WaitForRun(Exception):

taca/backup/backup.py

@@ -373,6 +373,7 @@ def _move_run_to_archived(self, run):
     @classmethod
     def encrypt_runs(cls, run, force):
         """Encrypt the runs that have been collected."""
+        logger.info("Started taca backup encrypt")
         bk = cls(run)
         bk.collect_runs(ext=".tar")
         logger.info(f"In total, found {len(bk.runs)} run(s) to be encrypted")
@@ -506,10 +507,12 @@ def encrypt_runs(cls, run, force):
                 logger.info(
                     f"Encryption of run {run.name} is successfully done, removing run folder tarball"
                 )
+        logger.info("Finished taca backup encrypt")
 
     @classmethod
     def pdc_put(cls, run):
         """Archive the collected runs to PDC."""
+        logger.info("Started taca backup put_data")
         bk = cls(run)
         bk.collect_runs(ext=".tar.gpg", filter_by_ext=True)
         logger.info(f"In total, found {len(bk.runs)} run(s) to send PDC")
@@ -577,3 +580,4 @@ def pdc_put(cls, run):
                             bk._move_run_to_archived(run)
                         continue
                 logger.warning(f"Sending file {run.tar_encrypted} to PDC failed")
+        logger.info("Finished taca backup put_data")

taca/log/__init__.py

@@ -1,15 +1,31 @@
 """TACA logging module for external scripts"""
 
 import logging
+from datetime import datetime
+
+# session id is the timestamp when this module is imported (script start)
+SESSION_ID = datetime.now().strftime("%y%m%d%H%M")
+
+
+class SessionFilter(logging.Filter):
+    """Attach session_id (script start timestamp) to every LogRecord."""
+
+    def filter(self, record):
+        record.session_id = SESSION_ID
+        return True
+
 
 # get root logger
 ROOT_LOG = logging.getLogger()
 ROOT_LOG.setLevel(logging.INFO)
 
-# Console logger
+# Console logger with session_id in format
+formatter = logging.Formatter(
+    "%(asctime)s - %(session_id)s - %(name)s - %(levelname)s - %(message)s"
+)
 stream_handler = logging.StreamHandler()
-formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
 stream_handler.setFormatter(formatter)
+stream_handler.addFilter(SessionFilter())
 ROOT_LOG.addHandler(stream_handler)
 
 LOG_LEVELS = {
@@ -36,5 +52,6 @@ def init_logger_file(log_file, log_level="INFO"):
     file_handle = logging.FileHandler(log_file)
     file_handle.setLevel(log_level)
     file_handle.setFormatter(formatter)
+    file_handle.addFilter(SessionFilter())
     ROOT_LOG.addHandler(file_handle)
     ROOT_LOG.addHandler(stream_handler)