From 0eb44039f00129bb1414c76f4926a01f610f2ce7 Mon Sep 17 00:00:00 2001 From: Markus Rosenstihl Date: Mon, 13 Jul 2026 22:47:54 +0200 Subject: [PATCH] added proper logging facility --- src/damaris/gui/BackendDriver.py | 67 +++---- src/damaris/gui/ExperimentHandling.py | 5 +- src/damaris/gui/ResultHandling.py | 5 +- src/damaris/gui/__init__.py | 5 + src/damaris/gui/logging_utils.py | 256 ++++++++++++++++++++++++++ src/damaris/gui/script_interface.py | 30 +-- 6 files changed, 315 insertions(+), 53 deletions(-) create mode 100644 src/damaris/gui/logging_utils.py diff --git a/src/damaris/gui/BackendDriver.py b/src/damaris/gui/BackendDriver.py index a0532bd..a5f899d 100644 --- a/src/damaris/gui/BackendDriver.py +++ b/src/damaris/gui/BackendDriver.py @@ -5,12 +5,16 @@ import sys import time import re import glob +import logging from . import ExperimentWriter from . import ResultReader +from .logging_utils import FileTailerHandler import threading import types import signal +logger = logging.getLogger("damaris.backend_driver") + if sys.platform=="win32": import winreg @@ -40,7 +44,7 @@ class BackendDriver(threading.Thread): try: os.makedirs(os.path.abspath(self.spool_dir)) except OSError as e: - print(e) + logger.error("Could not create backend's spool directory %s: %s", self.spool_dir, e) raise AssertionError("could not create backend's spool directory %s "%self.spool_dir) # remove stale state filenames @@ -62,10 +66,10 @@ class BackendDriver(threading.Thread): if os.path.isdir("/proc/%d"%core_pid): raise AssertionError("found backend with pid %d (state file %s) in same spool dir"%(core_pid,statefilename)) else: - print("removing stale backend state file", statefilename) + logger.warning("Removing stale backend state file: %s", statefilename) os.remove(statefilename) else: - print("todo: take care of existing backend state files") + logger.warning("TODO: take care of existing backend state files (Windows)") self.result_reader = ResultReader.BlockingResultReader(self.spool_dir, no=0, @@ -81,21 +85,9 @@ class BackendDriver(threading.Thread): self.raised_exception=None def run(self): - # take care of older logfiles - self.core_output_filename=os.path.join(self.spool_dir,"logdata") - if os.path.isfile(self.core_output_filename): - i=0 - max_logs=100 - while os.path.isfile(self.core_output_filename+".%02d"%i): - i+=1 - while (i>=max_logs): - i-=1 - os.remove(self.core_output_filename+".%02d"%i) - for j in range(i): - os.rename(self.core_output_filename+".%02d"%(i-j-1),self.core_output_filename+".%02d"%(i-j)) - os.rename(self.core_output_filename, self.core_output_filename+".%02d"%0) - # create logfile - self.core_output=open(self.core_output_filename,"w") + # Log file for backend output + self.core_output_filename = os.path.join(self.spool_dir, "logdata") + self.core_output = open(self.core_output_filename, "w") # again look out for existing state files state_files=glob.glob(os.path.join(self.spool_dir,"*.state")) @@ -118,6 +110,10 @@ class BackendDriver(threading.Thread): stdout=self.core_output, stderr=self.core_output) + # Start tailing backend log file for unified logging + self._log_tailer = FileTailerHandler(self.core_output_filename) + self._log_tailer.start() + # wait till state file shows up timeout=10 # to do: how should I know core's state name????!!!!! @@ -126,19 +122,16 @@ class BackendDriver(threading.Thread): while len(state_files)==0: if timeout<0 or self.core_input is None or self.core_input.poll() is not None or self.quit_flag.isSet(): # look into core log file and include contents - print(timeout, self.core_input, self.quit_flag.isSet()) - if self.core_input is not None: - print(self.core_input.poll()) + logger.error("Backend failed to start: timeout=%s poll=%s", timeout, self.core_input.poll()) log_message='' self.core_input=None if os.path.isfile(self.core_output_filename): - # to do include log data log_message='\n'+''.join(open(self.core_output_filename,"r", errors='replace').readlines()[:10]) if not log_message: log_message=" no error message from core" self.core_output.close() self.raised_exception="no state file appeared or backend died away:"+log_message - print(self.raised_exception) + logger.error(self.raised_exception) self.quit_flag.set() return time.sleep(0.05) @@ -147,7 +140,7 @@ class BackendDriver(threading.Thread): # save the one if len(state_files)>1: - print("did find more than one state file, taking first one!") + logger.warning("Found more than one state file, taking first one!") self.statefilename=state_files[0] # read state file @@ -182,28 +175,28 @@ class BackendDriver(threading.Thread): backend_result=self.core_input.poll() if backend_result is not None: break if wait_loop_counter==10: - print("sending termination signal to backend process") + logger.warning("Sending termination signal to backend process") self.send_signal("SIGTERM") elif wait_loop_counter==20: - print("sending kill signal to backend process") + logger.warning("Sending kill signal to backend process") self.send_signal("SIGKILL") elif wait_loop_counter>30: - print("no longer waiting for backend shutdown") + logger.warning("No longer waiting for backend shutdown") break if backend_result is None: - print("backend dit not end properly, please stop it manually") + logger.error("Backend did not end properly, please stop it manually") elif backend_result>0: - print("backend returned ", backend_result) + logger.error("Backend returned exit code %d", backend_result) elif backend_result<0: sig_name=[x for x in dir(signal) if x.startswith("SIG") and \ x[3]!="_" and \ (type(signal.__dict__[x])is int) and \ signal.__dict__[x]==-backend_result] if sig_name: - print("backend was terminated by signal ",sig_name[0]) + logger.error("Backend was terminated by signal %s", sig_name[0]) else: - print("backend was terminated by signal no",-backend_result) + logger.error("Backend was terminated by signal no %d", -backend_result) self.core_input = None self.core_pid = None @@ -226,12 +219,6 @@ class BackendDriver(threading.Thread): if os.path.isfile(resultfilename): os.remove(resultfilename) - def get_messages(self): - # return pending messages - if self.core_output.tell()==os.path.getsize(self.core_output_filename): - return None - return self.core_output.read() - def restart_queue(self): self.send_signal("SIGUSR1") @@ -250,7 +237,7 @@ class BackendDriver(threading.Thread): def send_signal(self, sig): if self.core_pid is None: - print("BackendDriver.send_signal is called with core_pid=None") + logger.error("BackendDriver.send_signal called with core_pid=None") return try: if sys.platform[:5]=="linux": @@ -262,7 +249,7 @@ class BackendDriver(threading.Thread): kill_command=os.path.join(cygwin_path,"bin","kill.exe") os.popen("%s -%s %d"%(kill_command,sig,self.core_pid)) except OSError as e: - print("could not send signal %s to core: %s"%(sig, str(e))) + logger.error("Could not send signal %s to core: %s", sig, str(e)) def is_busy(self): @@ -294,3 +281,5 @@ class BackendDriver(threading.Thread): if self.core_output: self.core_output.close() self.core_output=None + if hasattr(self, '_log_tailer'): + self._log_tailer.stop() diff --git a/src/damaris/gui/ExperimentHandling.py b/src/damaris/gui/ExperimentHandling.py index 2172b70..8433eac 100644 --- a/src/damaris/gui/ExperimentHandling.py +++ b/src/damaris/gui/ExperimentHandling.py @@ -3,10 +3,13 @@ import io import traceback import sys import time +import logging import ast from damaris.experiments.Experiment import Quit from damaris.experiments import Experiment +logger = logging.getLogger("damaris.experiment_handling") + class StopExperiment(Exception): pass @@ -66,7 +69,7 @@ class ExperimentHandling(threading.Thread): found_blocking_sleep = True if found_blocking_sleep: - print("Warning: time.sleep() detected in experiment script. This is blocking and not interruptible. Please use sleep() instead.") + logger.warning("time.sleep() detected in experiment script. This is blocking and not interruptible. Please use sleep() instead.") break except Exception: pass diff --git a/src/damaris/gui/ResultHandling.py b/src/damaris/gui/ResultHandling.py index 44d9ea7..28c1476 100644 --- a/src/damaris/gui/ResultHandling.py +++ b/src/damaris/gui/ResultHandling.py @@ -4,10 +4,13 @@ import sys import os import os.path import traceback +import logging import ast from damaris.data import Resultable from damaris.gui.ExperimentHandling import StopExperiment +logger = logging.getLogger("damaris.result_handling") + class ResultHandling(threading.Thread): """ runs the result script in sandbox @@ -52,7 +55,7 @@ class ResultHandling(threading.Thread): found_blocking_sleep = True if found_blocking_sleep: - print("Warning: time.sleep() detected in result script. This is blocking and not interruptible. Please use sleep() instead.") + logger.warning("time.sleep() detected in result script. This is blocking and not interruptible. Please use sleep() instead.") break except Exception: pass diff --git a/src/damaris/gui/__init__.py b/src/damaris/gui/__init__.py index e69de29..724429b 100644 --- a/src/damaris/gui/__init__.py +++ b/src/damaris/gui/__init__.py @@ -0,0 +1,5 @@ +from .logging_utils import ( + FileTailerHandler, + LogDispatcher, + setup_logging, +) diff --git a/src/damaris/gui/logging_utils.py b/src/damaris/gui/logging_utils.py new file mode 100644 index 0000000..2a25fb6 --- /dev/null +++ b/src/damaris/gui/logging_utils.py @@ -0,0 +1,256 @@ +# -*- coding: utf-8 -*- +""" +Unified logging for DAMARIS. + +Provides: +- FileTailerHandler: reads new lines from the backend log file and emits them + as logging records into the damaris.backend logger. +- LogDispatcher: a logging.Handler that dispatches records to both a GTK + messages_textview (via idle_add) and the console. +- setup_logging(): convenience function to configure the root logger. +""" + +import logging +import os +import queue +import re +import sys +import threading +import time + +# --------------------------------------------------------------------------- +# Severity prefix pattern for C++ backend messages +# --------------------------------------------------------------------------- +_BACKEND_PREFIX_RE = re.compile(r"^\[(DEBUG|INFO|WARNING|ERROR|CRITICAL)\]\s*(.*)") + +# Mapping from string prefix to logging level +_PREFIX_TO_LEVEL = { + "DEBUG": logging.DEBUG, + "INFO": logging.INFO, + "WARNING": logging.WARNING, + "ERROR": logging.ERROR, + "CRITICAL": logging.CRITICAL, +} + + +# --------------------------------------------------------------------------- +# FileTailerHandler +# --------------------------------------------------------------------------- +class FileTailerHandler(logging.Handler): + """ + Reads new lines from a log file and emits them as log records. + + Runs a background thread that polls the file every `poll_interval` seconds. + New lines are parsed for a severity prefix (e.g. ``[INFO] message``) and + emitted as LogRecords under the ``damaris.backend`` logger. Lines without + a recognized prefix are emitted at INFO level. + + Parameters + ---------- + filename : str + Path to the log file to tail. + poll_interval : float, optional + Seconds between polls (default 0.1). + logger_name : str, optional + Logger name for emitted records (default "damaris.backend"). + """ + + def __init__(self, filename, poll_interval=0.1, logger_name="damaris.backend"): + super().__init__() + self._filename = filename + self._poll_interval = poll_interval + self._logger_name = logger_name + self._queue = queue.Queue() + self._thread = None + self._stop_event = threading.Event() + self._position = 0 + self._file = None + + def _tailer_loop(self): + """Background thread: open file, read new lines, push to queue.""" + while not self._stop_event.is_set(): + try: + if not os.path.isfile(self._filename): + time.sleep(self._poll_interval) + continue + + fh = open(self._filename, "r", errors="replace") + fh.seek(self._position) + new_lines = fh.readlines() + self._position = fh.tell() + fh.close() + + for line in new_lines: + line = line.rstrip("\n\r") + if line: + self._queue.put(line) + + except Exception: + # File may have been rotated or deleted; reset position + self._position = 0 + + self._stop_event.wait(self._poll_interval) + + def emit(self, record): + """Called when a log record is ready. Not used directly — lines are + pushed from the queue by _process_queue().""" + pass + + def _process_queue(self): + """Drain the queue and emit parsed log records. Called from the + thread that owns the handler (typically the GUI thread).""" + while not self._queue.empty(): + try: + line = self._queue.get_nowait() + except queue.Empty: + break + + m = _BACKEND_PREFIX_RE.match(line) + if m: + level_str, message = m.group(1), m.group(2) + level = _PREFIX_TO_LEVEL.get(level_str, logging.INFO) + else: + level = logging.INFO + message = line + + # Create a LogRecord from the raw message + record = logging.LogRecord( + name=self._logger_name, + level=level, + pathname="(tailer)", + lineno=0, + msg=message, + args=None, + exc_info=None, + ) + self.handle(record) + + def start(self): + """Start the background tailing thread.""" + if self._thread is not None and self._thread.is_alive(): + return + self._stop_event.clear() + self._thread = threading.Thread(target=self._tailer_loop, name="log-tailer", daemon=True) + self._thread.start() + + def stop(self): + """Stop the background thread.""" + self._stop_event.set() + if self._thread is not None: + self._thread.join(timeout=2) + self._thread = None + + def close(self): + self.stop() + super().close() + + +# --------------------------------------------------------------------------- +# LogDispatcher +# --------------------------------------------------------------------------- +class LogDispatcher(logging.Handler): + """ + Dispatches log records to a GTK messages_textview and/or the console. + + Parameters + ---------- + gui_callback : callable or None + If not None, called with the formatted message string. Must be + thread-safe (e.g. wrapped in ``gobject.idle_add``). This is the + textview's ``__call__`` method from DamarisGUI. + console : bool, optional + If True, also emit to sys.stderr (default True). + """ + + def __init__(self, gui_callback=None, console=True): + super().__init__() + self._gui_callback = gui_callback + self._console_handler = logging.StreamHandler(sys.stderr) if console else None + if self._console_handler: + self._console_handler.setFormatter( + logging.Formatter("%(asctime)s [%(levelname)-8s] %(name)s: %(message)s", + datefmt="%H:%M:%S") + ) + + def emit(self, record): + try: + msg = self.format(record) + + if self._gui_callback is not None: + try: + import gi + gi.require_version("Gdk", "3.0") + from gi.repository import GObject as gobject + gobject.idle_add(self._gui_callback, msg + "\n", priority=gobject.PRIORITY_LOW) + except Exception: + # GUI not available or import failed — ignore + pass + + if self._console_handler is not None: + self._console_handler.emit(record) + except Exception: + self.handleError(record) + + def close(self): + if self._console_handler: + self._console_handler.close() + super().close() + + +# --------------------------------------------------------------------------- +# setup_logging +# --------------------------------------------------------------------------- +def setup_logging(level=logging.INFO, gui_callback=None, backend_logfile=None): + """ + Configure the DAMARIS logging system. + + Parameters + ---------- + level : int + Minimum logging level (default INFO). + gui_callback : callable or None + Optional callback for GUI textview output. + backend_logfile : str or None + Path to the backend log file. If provided, a FileTailerHandler is + attached to the ``damaris.backend`` logger. + + Returns + ------- + logger : logging.Logger + The root damaris logger. + """ + root = logging.getLogger("damaris") + root.setLevel(level) + + # Remove existing handlers to avoid duplicates on re-init + root.handlers.clear() + + # Console handler on the root logger + console = logging.StreamHandler(sys.stderr) + console.setFormatter( + logging.Formatter("%(asctime)s [%(levelname)-8s] %(name)s: %(message)s", + datefmt="%H:%M:%S") + ) + root.addHandler(console) + + # GUI dispatcher + if gui_callback is not None: + dispatcher = LogDispatcher(gui_callback=gui_callback, console=False) + dispatcher.setFormatter( + logging.Formatter("[%(levelname)s] %(name)s: %(message)s") + ) + root.addHandler(dispatcher) + + # Backend file tailer + if backend_logfile is not None and os.path.isfile(backend_logfile): + tailer = FileTailerHandler(backend_logfile) + tailer.setFormatter( + logging.Formatter("[%(levelname)s] %(name)s: %(message)s") + ) + backend_logger = logging.getLogger("damaris.backend") + backend_logger.setLevel(logging.DEBUG) + backend_logger.addHandler(tailer) + backend_logger.propagate = True # bubble up to damaris root + tailer.start() + + return root diff --git a/src/damaris/gui/script_interface.py b/src/damaris/gui/script_interface.py index 82a1618..029cf1a 100644 --- a/src/damaris/gui/script_interface.py +++ b/src/damaris/gui/script_interface.py @@ -4,6 +4,7 @@ import time import sys import os import os.path +import logging import tables import damaris.data.DataPool as DataPool import damaris.gui.ResultReader as ResultReader @@ -12,6 +13,8 @@ import damaris.gui.BackendDriver as BackendDriver import damaris.gui.ResultHandling as ResultHandling import damaris.gui.ExperimentHandling as ExperimentHandling +logger = logging.getLogger("damaris.script_interface") + def some_listener(event): if event.subject=="__recentexperiment" or event.subject=="__recentresult": r=event.origin.get("__recentresult",-1)+1 @@ -20,7 +23,8 @@ def some_listener(event): ratio=100.0*r/e else: ratio=100.0 - print("\r%d/%d (%.0f%%)"%(r,e,ratio), end=' ') + sys.stderr.write("\r%d/%d (%.0f%%)"%(r,e,ratio)) + sys.stderr.flush() class ScriptInterface: @@ -73,27 +77,29 @@ class ScriptInterface: if not self.exp_handling.is_alive(): self.exp_handling.join() if self.exp_handling.raised_exception: - print(": experiment script failed at line %d (function %s): %s"%(self.exp_handling.location[0], - self.exp_handling.location[1], - self.exp_handling.raised_exception)) + logger.error(": experiment script failed at line %d (function %s): %s", + self.exp_handling.location[0], + self.exp_handling.location[1], + self.exp_handling.raised_exception) else: - print(": experiment script finished") + logger.info(": experiment script finished") self.exp_handling = None if self.res_handling is not None: if not self.res_handling.is_alive(): self.res_handling.join() if self.res_handling.raised_exception: - print(": result script failed at line %d (function %s): %s"%(self.res_handling.location[0], - self.res_handling.location[1], - self.res_handling.raised_exception)) + logger.error(": result script failed at line %d (function %s): %s", + self.res_handling.location[0], + self.res_handling.location[1], + self.res_handling.raised_exception) else: - print(": result script finished") + logger.info(": result script finished") self.res_handling = None if self.back_driver is not None: if not self.back_driver.is_alive(): - print(": backend finished") + logger.info(": backend finished") self.back_driver=None except KeyboardInterrupt: @@ -120,14 +126,14 @@ class ScriptInterface: dump_file=None # todo except Exception as e: - print("dump failed", e) + logger.error("Dump failed: %s", e) if __name__=="__main__": if len(sys.argv)==1: - print("%s: data_handling_script [spool directory]"%sys.argv[0]) + logger.error("%s: data_handling_script [spool directory]", sys.argv[0]) sys.exit(1) if len(sys.argv)==3: spool_dir=os.getcwd()