IPKM/python3-damaris
Public Access
3
0
Fork 0
Code Issues 7 Pull Requests Actions Releases Activity

added proper logging facility

Browse Source
This commit is contained in:
markusro
2026-07-13 22:47:54 +02:00
parent fa064c1727
commit 0eb44039f0
6 changed files with 315 additions and 53 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/damaris/gui/BackendDriver.py
+28 -39
View File
@@ -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()
src/damaris/gui/ExperimentHandling.py
+4 -1
View File
@@ -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
src/damaris/gui/ResultHandling.py
+4 -1
View File
@@ -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
src/damaris/gui/__init__.py
+5
View File
@@ -0,0 +1,5 @@
from .logging_utils import (
FileTailerHandler,
LogDispatcher,
setup_logging,
)
src/damaris/gui/logging_utils.py
+256
View File
@@ -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
src/damaris/gui/script_interface.py
+18 -12
View File
@@ -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()