Merge pull request #30 from richardkoehler/feat/improve-logging

Improve logging

Author: Lucia-Poma

src/clinical_dbs_annotator/__main__.py

@@ -11,10 +11,12 @@
 import PySide6.QtSvg  # noqa: F401 - required to enable SVG rendering in QSS
 from PySide6.QtWidgets import QApplication
 
-from .logging_config import setup_logging
+from .logging_config import setup_bootstrap_logging, setup_logging
 from .utils import get_theme_manager
 from .views import WizardWindow
 
+logger = logging.getLogger(__name__)
+
 
 def main() -> int:
     """
@@ -23,23 +25,28 @@ def main() -> int:
     Returns:
         Exit code (0 for success)
     """
-    app = QApplication(sys.argv)
+    setup_bootstrap_logging()
+    try:
+        app = QApplication(sys.argv)
 
-    app.setApplicationName("Clinical DBS Annotator")
-    app.setOrganizationName("BML")
+        app.setApplicationName("Clinical DBS Annotator")
+        app.setOrganizationName("BML")
 
-    setup_logging(app)
+        setup_logging(app)
 
-    theme_manager = get_theme_manager()
-    try:
-        theme_manager.apply_theme(theme_manager.get_current_theme(), app)
-    except Exception as e:
-        logging.warning("Could not load theme: %s", e)
+        theme_manager = get_theme_manager()
+        try:
+            theme_manager.apply_theme(theme_manager.get_current_theme(), app)
+        except Exception:
+            logger.exception("Could not load current theme")
 
-    window = WizardWindow(app)
-    window.show()
+        window = WizardWindow(app)
+        window.show()
 
-    return app.exec()
+        return app.exec()
+    except Exception:
+        logger.critical("Fatal startup failure", exc_info=True)
+        return 1
 
 
 if __name__ == "__main__":

src/clinical_dbs_annotator/logging_config.py

@@ -1,3 +1,4 @@
+import faulthandler
 import logging
 import platform
 import sys
@@ -17,10 +18,53 @@
 
 _configured = False
 _log_file_path: Path | None = None
+_crash_log_file = None
+
+
+def _install_exception_hooks() -> None:
+    def exc_hook(exc_type, exc, tb):
+        logging.getLogger("uncaught").critical(
+            "Uncaught exception",
+            exc_info=(exc_type, exc, tb),
+        )
+
+    sys.excepthook = exc_hook
+
+    def thread_exc_hook(args: threading.ExceptHookArgs) -> None:
+        logging.getLogger("uncaught").critical(
+            "Uncaught thread exception",
+            exc_info=(args.exc_type, args.exc_value, args.exc_traceback),
+        )
+
+    threading.excepthook = thread_exc_hook
+
+    def unraisable_hook(args: sys.UnraisableHookArgs) -> None:
+        logging.getLogger("uncaught").error(
+            "Unraisable exception in %r",
+            args.object,
+            exc_info=(args.exc_type, args.exc_value, args.exc_traceback),
+        )
+
+    sys.unraisablehook = unraisable_hook
+
+
+def setup_bootstrap_logging() -> None:
+    root = logging.getLogger()
+    if root.handlers:
+        _install_exception_hooks()
+        return
+
+    fmt = logging.Formatter("%(asctime)s ¦ %(levelname)s ¦ %(name)s ¦ %(message)s")
+    sh = logging.StreamHandler(sys.stderr)
+    sh.setLevel(logging.INFO)
+    sh.setFormatter(fmt)
+    root.setLevel(logging.DEBUG)
+    root.addHandler(sh)
+    _install_exception_hooks()
 
 
 def setup_logging(_app: QApplication) -> Path:
-    global _configured, _log_file_path
+    global _configured, _log_file_path, _crash_log_file
     if _configured:
         assert _log_file_path is not None
         return _log_file_path
@@ -53,21 +97,7 @@ def setup_logging(_app: QApplication) -> Path:
         sh.setFormatter(fmt)
         root.addHandler(sh)
 
-    def exc_hook(exc_type, exc, tb):
-        logging.getLogger("uncaught").critical(
-            "Uncaught exception",
-            exc_info=(exc_type, exc, tb),
-        )
-
-    sys.excepthook = exc_hook
-
-    def thread_exc_hook(args: threading.ExceptHookArgs) -> None:
-        logging.getLogger("uncaught").critical(
-            "Uncaught thread exception",
-            exc_info=(args.exc_type, args.exc_value, args.exc_traceback),
-        )
-
-    threading.excepthook = thread_exc_hook
+    _install_exception_hooks()
 
     def qt_handler(mode: QtMsgType, context: QMessageLogContext, message: str) -> None:
         if mode == QtMsgType.QtDebugMsg:
@@ -86,6 +116,19 @@ def qt_handler(mode: QtMsgType, context: QMessageLogContext, message: str) -> No
         logging.getLogger("qt").log(level, "%s%s", message, suffix)
 
     qInstallMessageHandler(qt_handler)
+    _app.aboutToQuit.connect(
+        lambda: logging.getLogger("clinical_dbs_annotator").info("Application shutdown")
+    )
+
+    crash_log_path = log_dir / "clinical-dbs-annotator-crash.log"
+    try:
+        _crash_log_file = open(crash_log_path, "a", encoding="utf-8")
+        faulthandler.enable(file=_crash_log_file, all_threads=True)
+    except Exception:
+        logging.getLogger("clinical_dbs_annotator").exception(
+            "Failed to enable faulthandler with crash log %s",
+            crash_log_path,
+        )
 
     logging.getLogger("clinical_dbs_annotator").info(
         "Started v%s Python %s | %s | log=%s",

src/clinical_dbs_annotator/models/session_data.py

@@ -6,6 +6,7 @@
 """
 
 import csv
+import logging
 from datetime import datetime
 from pathlib import Path
 from typing import TextIO
@@ -15,6 +16,8 @@
 from .clinical_scale import ClinicalScale, SessionScale
 from .stimulation import StimulationParameters
 
+logger = logging.getLogger(__name__)
+
 
 class SessionData:
     """
@@ -82,6 +85,7 @@ def open_file_append(
         # Calculate next session_id and block_id
         max_block = -1
         max_session = 0
+        parse_errors = 0
         try:
             with open(file_path, newline="", encoding="utf-8") as f:
                 reader = csv.DictReader(f, delimiter="\t")
@@ -97,10 +101,22 @@ def open_file_append(
                         if session_val is not None and session_val != "":
                             max_session = max(max_session, int(float(session_val)))
                     except Exception:
+                        parse_errors += 1
                         continue
         except Exception:
+            logger.warning(
+                "Failed to inspect existing session file before append: %s",
+                file_path,
+                exc_info=True,
+            )
             max_block = -1
             max_session = 0
+        if parse_errors:
+            logger.warning(
+                "Skipped %d malformed rows while opening session file in append mode: %s",
+                parse_errors,
+                file_path,
+            )
 
         if start_block_id is None:
             start_block_id = max_block + 1
@@ -114,6 +130,11 @@ def open_file_append(
                 reader = csv.DictReader(f, delimiter="\t")
                 existing_fieldnames = reader.fieldnames
         except Exception:
+            logger.warning(
+                "Failed to read existing TSV headers, using defaults: %s",
+                file_path,
+                exc_info=True,
+            )
             existing_fieldnames = None
 
         self.tsv_fieldnames = existing_fieldnames or list(TSV_COLUMNS)
@@ -128,7 +149,11 @@ def open_file_append(
             if Path(file_path).stat().st_size == 0:
                 self.tsv_writer.writeheader()
         except Exception:
-            pass
+            logger.warning(
+                "Failed to initialize TSV header for file: %s",
+                file_path,
+                exc_info=True,
+            )
         self.session_start_time = datetime.now()
 
     def close_file(self) -> None:
@@ -365,6 +390,11 @@ def open_simple_file_append(self, filepath: str) -> None:
                     reader = csv.DictReader(f, delimiter="\t")
                     fieldnames = reader.fieldnames
             except Exception:
+                logger.warning(
+                    "Failed reading annotation TSV headers, using defaults: %s",
+                    filepath,
+                    exc_info=True,
+                )
                 fieldnames = None
 
         fieldnames = fieldnames or ["date", "time", "timezone", "annotation"]
@@ -381,7 +411,11 @@ def open_simple_file_append(self, filepath: str) -> None:
                 self.tsv_writer.writeheader()
                 self.tsv_file.flush()
         except Exception:
-            pass
+            logger.warning(
+                "Failed to initialize annotation TSV header: %s",
+                filepath,
+                exc_info=True,
+            )
 
     def write_simple_annotation(self, annotation: str) -> None:
         """