Skip to content
Snippets Groups Projects
Commit 3fbd7d5d authored by Christoph Schmidt's avatar Christoph Schmidt
Browse files

Fixed logging issues.Now the logger can be set using the global config....

Fixed logging issues.Now the logger can be set using the global config. Module-level logger can now be disabled, and enabled.
parent e2ae7a2b
Branches
No related tags found
No related merge requests found
......@@ -15,6 +15,7 @@ class ChildProcess3(cmp.CProcess):
@cmp.CProcess.register_signal()
def test_call(self, a):
self.logger.info(f"{os.getpid()} -> test_call!")
self.logger.debug(f"{os.getpid()} -> test_call2!")
time.sleep(1)
# self.test_call2 = 1
return a
......
......@@ -12,6 +12,7 @@ from threading import Thread
from PySide6.QtCore import QObject, Signal, SIGNAL
from PySide6.QtWidgets import QDialog, QApplication, QTextBrowser, QLineEdit, QVBoxLayout, QMainWindow, QMessageBox
from rich.logging import RichHandler
sys.path.append('./src')
from ChildProcessControl3 import ChildProcessControl3
......@@ -24,8 +25,15 @@ class Form(QDialog):
def __init__(self, parent=None):
super().__init__(parent)
child_con = ChildProcessControl3(self, internal_log_level=logging.WARNING, log_file="log.log")
#child_con.set_internal_log_level(logging.INFO)
FORMAT = "%(name)s %(message)s"
logging.basicConfig(
level=logging.DEBUG, format=FORMAT, datefmt="[%X]", handlers=[RichHandler()]
)
child_con = ChildProcessControl3(self)
child_con.internal_log_enabled = True
child_con.internal_log_level = logging.INFO
child_con.mp_finished.connect(self.updateUI)
......
......@@ -9,47 +9,22 @@ class CBase:
# Public methods
# ==================================================================================================================
def __init__(self):
self._internal_logger = None
self._module_logger = None
self._internal_log_handler = None
self.name = self.__class__.__name__
def create_new_logger(self, logger_name: str,
logger_handler: logging.Handler = None,
logger_format: str = "%(asctime)s - %(name)s %(message)s",
to_file=None,
enabled=True, level=logging.DEBUG) -> logging.Logger:
"""
Creates a new logger with the given name and handler. If no handler is given, a RichHandler will be used.
:param enabled:
:param logger_name:
:param logger_handler:
:param logger_format:
:param to_file:
:return:
"""
formatter = logging.Formatter(logger_format)
if logger_handler is None:
logger_handler = RichHandler(rich_tracebacks=True)
logger_handler.setLevel(level)
logger_handler.setFormatter(formatter)
def create_new_logger(self, logger_name: str, logger_handler: logging.Handler = logging.NullHandler(),
enabled=True, level=logging.DEBUG, propagate=True) -> logging.Logger:
#logger_handler.setLevel(level)
_internal_logger = logging.getLogger(logger_name)
_internal_logger.handlers = [logger_handler]
_internal_logger.setLevel(logging.DEBUG)
if to_file is not None:
_file_handler = logging.FileHandler(to_file)
_file_handler.setLevel(logging.DEBUG)
_file_handler_formatter = logging.Formatter(f"%(levelname)s {logger_format})")
_file_handler.setFormatter(_file_handler_formatter)
_internal_logger.addHandler(_file_handler)
_internal_logger.propagate = propagate
_internal_logger.setLevel(level)
if enabled:
_internal_logger.disabled = False
_internal_logger.info(f"Logger {logger_name} created with ({len(_internal_logger.handlers)}) handlers and has been enabled (Level {level}).")
_internal_logger.info(f"Logger {logger_name} created with ({len(_internal_logger.handlers)}) "
f"handlers and has been enabled (Level {_internal_logger.level}).")
else:
_internal_logger.info(f"Logger {logger_name} created and has been disabled.")
_internal_logger.disabled = True
......@@ -59,8 +34,8 @@ class CBase:
@property
def internal_log_enabled(self):
if self._internal_logger is not None:
return not self._internal_logger.disabled
if self._module_logger is not None:
return not self._module_logger.disabled
else:
raise Exception("Internal logger not initialized")
......@@ -71,20 +46,20 @@ class CBase:
emitted to the state queue.
:param enable: True to enable, False to disable
"""
if self._internal_logger is not None:
if self._module_logger is not None:
if enable:
self._internal_logger.disabled = False
self._internal_logger.info(f"Internal logger of {self.__class__.__name__} has been enabled.")
self._module_logger.disabled = False
self._module_logger.info(f"Internal logger of {self.__class__.__name__} has been enabled.")
else:
self._internal_logger.warning(f"Internal logger of {self.__class__.__name__} has been disabled.")
self._internal_logger.disabled = True
self._module_logger.warning(f"Internal logger of {self.__class__.__name__} has been disabled.")
self._module_logger.disabled = True
else:
raise Exception("Can't enable internal logger. Internal logger not initialized")#
@property
def internal_log_level(self):
return self._internal_logger.handlers[0].level
return self._module_logger.level
@internal_log_level.setter
def internal_log_level(self, level: int) -> None:
......@@ -93,20 +68,20 @@ class CBase:
:param level:
:return:
"""
if self._internal_logger is not None:
if self._module_logger is not None:
if level == logging.DEBUG:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to DEBUG.")
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to DEBUG.")
elif level == logging.INFO:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to INFO.")
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to INFO.")
elif level == logging.WARNING:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to WARNING.")
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to WARNING.")
elif level == logging.ERROR:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to ERROR.")
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to ERROR.")
elif level == logging.CRITICAL:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to CRITICAL.")
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to CRITICAL.")
else:
self._internal_logger.info(f"Internal log level of {self.__class__.__name__} has been set to level {level}.")
self._internal_logger.handlers[0].setLevel(level)
self._module_logger.info(f"Internal log level of {self.__class__.__name__} has been set to level {level}.")
self._module_logger.setLevel(level)
else:
raise Exception("Can't set internal log level. Internal logger not initialized")
......@@ -15,7 +15,7 @@ class CCommandRecord:
def execute(self, class_object: CProcess):
if hasattr(class_object, '_internal_logger'):
class_object._internal_logger.info(f"Executing {self} in {class_object.name}.")
class_object._module_logger.info(f"Executing {self} in {class_object.name}.")
if self.signal_name is not None:
getattr(class_object, self.func_name)(signal_name=self.signal_name, *self.args, **self.kwargs)
else:
......
......@@ -55,22 +55,19 @@ class CProcess(CBase, Process):
def run(self):
self.name = f"{os.getpid()}({self.name})"
self._internal_logger = self.create_new_logger(
f"(cmp) {self.name}",
self._module_logger = self.create_new_logger(f"(cmp) {self.name}",
logger_handler=logging.handlers.QueueHandler(self.state_queue),
logger_format="%(message)s",
to_file=self.log_file,
enabled=self._internal_log_enabled_, level=self._internal_log_level_)
enabled=self._internal_log_enabled_,
level=self._internal_log_level_,
propagate=True
)
self.logger = self.create_new_logger(
f"{os.getpid()}({self.__class__.__name__})",
self.logger = self.create_new_logger(f"{os.getpid()}({self.__class__.__name__})",
logger_handler=logging.handlers.QueueHandler(self.state_queue),
logger_format="%(message)s",
enabled=True,
to_file=self.log_file)
enabled=True)
self._internal_logger.debug(f"Child process {self.__class__.__name__} started.")
self._module_logger.debug(f"Child process {self.__class__.__name__} started.")
#sys.stderr.write = self.logger.error
#sys.stdout.write = self.logger.info
......@@ -86,27 +83,27 @@ class CProcess(CBase, Process):
continue
if isinstance(cmd, cmp.CCommandRecord):
self._internal_logger.debug(
self._module_logger.debug(
f"Received cmd: {cmd}, args: {cmd.args}, kwargs: {cmd.kwargs}, Signal to emit: {cmd.signal_name}")
try:
cmd.execute(self)
except Exception as e:
traceback_str = ''.join(traceback.format_tb(e.__traceback__))
self._internal_logger.error(f"Exception '{e}' occurred in {cmd}!. Traceback:\n{traceback_str}")
self._internal_logger.debug(f"Command {cmd} finished.")
self._module_logger.error(f"Exception '{e}' occurred in {cmd}!. Traceback:\n{traceback_str}")
self._module_logger.debug(f"Command {cmd} finished.")
else:
self._internal_logger.error(f"Received unknown command {cmd}!")
self._internal_logger.error(f"Control Process exited. Terminating Process {os.getpid()}")
self._module_logger.error(f"Received unknown command {cmd}!")
self._module_logger.error(f"Control Process exited. Terminating Process {os.getpid()}")
if self._kill_flag.value == 0:
self._internal_logger.error(f"Process {os.getpid()} received kill signal!")
self._module_logger.error(f"Process {os.getpid()} received kill signal!")
except KeyboardInterrupt:
self._internal_logger.warning(f"Received KeyboardInterrupt! Exiting Process {os.getpid()}")
self._module_logger.warning(f"Received KeyboardInterrupt! Exiting Process {os.getpid()}")
time.sleep(1)
self.close()
except Exception as e:
self._internal_logger.warning(f"Received Exception {e}! Exiting Process {os.getpid()}")
self._module_logger.warning(f"Received Exception {e}! Exiting Process {os.getpid()}")
self._internal_logger.warning(f"Child process monitor {self.__class__.__name__} ended.")
self._module_logger.warning(f"Child process monitor {self.__class__.__name__} ended.")
def __del__(self):
#self.logger.warning(f"Child process {self.name} deleted.")
......@@ -115,14 +112,14 @@ class CProcess(CBase, Process):
def _put_result_to_queue(self, func_name, signal_name, res):
if signal_name is not None:
self._internal_logger.debug(f"{func_name} finished. Emitting signal {signal_name} in control class.")
self._module_logger.debug(f"{func_name} finished. Emitting signal {signal_name} in control class.")
else:
self._internal_logger.debug(f"{func_name} finished. No signal to emit.")
self._module_logger.debug(f"{func_name} finished. No signal to emit.")
result = cmp.CResultRecord(func_name, signal_name, res)
self.state_queue.put(result)
def _put_exception_to_queue(self, func_name, exc):
self._internal_logger.debug(f"Error executing {func_name}.")
self._module_logger.debug(f"Error executing {func_name}.")
tb_str = traceback.format_exception(type(exc), value=exc, tb=exc.__traceback__)
tb_join = "".join(tb_str[-2:len(tb_str)])
result = cmp.CException(self.name, func_name, exc, )
......@@ -148,7 +145,7 @@ class CProcess(CBase, Process):
sign = kwargs.pop('signal_name')
elif _postfix is not None:
sign = f"{func.__name__}{_postfix}"
self._internal_logger.debug(f"Constructing signal name for function '{func.__name__}': {sign}")
self._module_logger.debug(f"Constructing signal name for function '{func.__name__}': {sign}")
else:
sign = None
try:
......@@ -156,7 +153,7 @@ class CProcess(CBase, Process):
self._put_result_to_queue(func_name, sign, res)
return res
except Exception as e:
self._internal_logger.error(f"Error in function {func_name}: {e} ({type(e)})")
self._module_logger.error(f"Error in function {func_name}: {e} ({type(e)})")
self._put_exception_to_queue(func.__name__, e)
return None
......@@ -187,7 +184,7 @@ class CProcess(CBase, Process):
def get_signature(self, *args, **kwargs):
func_name = f"{func.__name__}->{self.pid}"
res = func(self, *args, **kwargs)
self._internal_logger.debug(f"{func_name} finished. Emitting signal {signal_same} in control class.")
self._module_logger.debug(f"{func_name} finished. Emitting signal {signal_same} in control class.")
result = cmp.CResultRecord(func_name, signal_same, res)
self.state_queue.put(result)
return res
......
......@@ -19,16 +19,16 @@ class CProcessControl(CBase, QObject):
def __init__(self, parent: QObject = None,
signal_class: QObject = None,
internal_log: bool = True, internal_log_level: int = logging.WARNING, log_file: str = None):
module_log: bool = True, module_log_level: int = logging.WARNING, log_file: str = None):
QObject.__init__(self, parent)
CBase.__init__(self)
self.log_file = log_file
self._internal_logger = self.create_new_logger(f"(cmp) {self.name}",
to_file=self.log_file, enabled=internal_log, level=internal_log_level)
self._module_logger = self.create_new_logger(f"(cmp) {self.name}",
enabled=module_log, level=module_log_level
)
self.logger = self.create_new_logger(f"{self.__class__.__name__}({os.getpid()})",
to_file=self.log_file, enabled=internal_log)
self.logger = self.create_new_logger(f"{self.__class__.__name__}({os.getpid()})", enabled=module_log)
if isinstance(parent, QWidget) or isinstance(parent, QWindow):
parent.destroyed.connect(lambda: self.safe_exit(reason="Parent destroyed."))
......@@ -72,7 +72,7 @@ class CProcessControl(CBase, QObject):
return self._child_process_pid
def register_child_process(self, child, *args, **kwargs):
self._internal_logger.debug(f"Registering child process.")
self._module_logger.debug(f"Registering child process.")
self._child = child(self.state_queue, self.cmd_queue,
kill_flag=self._child_kill_flag,
......@@ -83,7 +83,7 @@ class CProcessControl(CBase, QObject):
# self._child.register_kill_flag(self._child_kill_flag)
self._child_process_pid = child.pid
self._child.start()
self._internal_logger.info(f"Child process {self._child.name} created.")
self._module_logger.info(f"Child process {self._child.name} created.")
self.thread_manager.start(self._monitor_result_state)
@property
......@@ -91,7 +91,7 @@ class CProcessControl(CBase, QObject):
return self._child
def _monitor_result_state(self):
self._internal_logger.info("Starting monitor thread.")
self._module_logger.info("Starting monitor thread.")
try:
while self._child.is_alive():
try:
......@@ -108,21 +108,21 @@ class CProcessControl(CBase, QObject):
try:
res.emit_signal(self._signal_class)
except Exception as e:
self._internal_logger.error(f"Error while emitting {res} in {self.__class__.__name__}: {e}")
self._module_logger.error(f"Error while emitting {res} in {self.__class__.__name__}: {e}")
elif isinstance(res, cmp.CException):
self._internal_logger.error(f"Received exception: {res}")
self._module_logger.error(f"Received exception: {res}")
try:
self.on_exception_raised.emit(res)
except Exception as e:
self._internal_logger.error(f"Error while emitting exception: {e}")
self._module_logger.error(f"Error while emitting exception: {e}")
else:
self._internal_logger.error(f"Received unknown result {res}!")
self._module_logger.error(f"Received unknown result {res}!")
except:
self._internal_logger.error(f"Error in monitor thread")
self._module_logger.error(f"Error in monitor thread")
time.sleep(1)
self._internal_logger.info(f"Ended monitor thread. Child process alive: {self._child.is_alive()}")
self._module_logger.info(f"Ended monitor thread. Child process alive: {self._child.is_alive()}")
self.state_queue.close()
self.cmd_queue.close()
......@@ -140,7 +140,7 @@ class CProcessControl(CBase, QObject):
self.logger.error(f"Error executing {e.function_name} in {e.parent_name}: {e.exception}\n"
f"{e.traceback()}")
except Exception as e:
self._internal_logger.error(f"Error while displaying exception: {e}")
self._module_logger.error(f"Error while displaying exception: {e}")
def execute_function(self, func: callable, signal: Signal = None):
self.register_function(signal)(func)(self)
......@@ -176,24 +176,24 @@ class CProcessControl(CBase, QObject):
if signal is not None:
sig_name, sig_args = match_signal_name(signal)
cmd.register_signal(sig_name)
self._internal_logger.debug(f"New function registered: {cmd} -> "
self._module_logger.debug(f"New function registered: {cmd} -> "
f"{cmd.signal_name if cmd.signal_name is not None else 'None'}("
f"{', '.join(str(a) for a in sig_args) if sig_args is not None else 'None'})")
else:
self._internal_logger.debug(f"New function registered: {cmd}")
self._module_logger.debug(f"New function registered: {cmd}")
try:
self._internal_logger.debug(f"Executing {name} with args {args} and kwargs {kwargs}")
self._module_logger.debug(f"Executing {name} with args {args} and kwargs {kwargs}")
func(self, *args, **kwargs)
except Exception as e:
self._internal_logger.error(f"Error while executing {cmd}: {e}")
self._module_logger.error(f"Error while executing {cmd}: {e}")
raise e
try:
self.cmd_queue.put(cmd)
self._internal_logger.debug(f"{cmd} put into cmd_queue.")
self._module_logger.debug(f"{cmd} put into cmd_queue.")
except Exception as e:
self._internal_logger.error(f"Error while putting {cmd} into cmd_queue: {e}")
self._module_logger.error(f"Error while putting {cmd} into cmd_queue: {e}")
raise e
return get_signature
......@@ -225,8 +225,8 @@ class CProcessControl(CBase, QObject):
"""
def safe_exit(self, reason: str = ""):
self._internal_logger.warning(f"Shutting down ProcessControl {os.getpid()}. Reason: {reason}")
self._module_logger.warning(f"Shutting down ProcessControl {os.getpid()}. Reason: {reason}")
self._child_kill_flag.value = 0
def __del__(self):
self._internal_logger.warning(f"Closing ProcessControl {self.__class__.__name__} with pid {os.getpid()}")
self._module_logger.warning(f"Closing ProcessControl {self.__class__.__name__} with pid {os.getpid()}")
......@@ -28,7 +28,7 @@ class _Cache(object):
# set attribute on instance
name = '%s_called' % self.func.__name__
# print(f"Setting {name} in {}!")
self.instance_._internal_logger.debug(
self.instance_._module_logger.debug(
f"Setting {name} in {self.instance_.__class__.__name__} and emitting {self.signal_name}!")
# setattr(self.instance_, name, datetime.utcnow())
......@@ -64,7 +64,7 @@ class CProperty:
def __set__(self, obj: cmp.CProcess, value):
if self.fset is None:
raise AttributeError("can't set attribute")
obj._internal_logger.debug(f"Setting {self.signal_name}!")
obj._module_logger.debug(f"Setting {self.signal_name}!")
result = cmp.CResultRecord(str(self.fset.__name__), self.signal_name, value)
obj.state_queue.put(result)
......
......@@ -11,8 +11,8 @@ class CResultRecord:
self.result = result
def emit_signal(self, class_object: CProcessControl):
if hasattr(class_object, '_internal_logger'):
logger: logging.Logger = class_object._internal_logger
if hasattr(class_object, '_module_logger'):
logger: logging.Logger = class_object._module_logger
else:
logger = logging.getLogger(f"{__name__} - fallback")
......@@ -20,7 +20,7 @@ class CResultRecord:
logger.debug(f"Function {self.function_name} returned {self.result}. "
f"No signal to emit.")
return
if hasattr(class_object, '_internal_logger'):
if hasattr(class_object, '_module_logger'):
logger.debug(f"Function {self.function_name} returned {self.result}. "
f"Emitting {self} in {class_object.__class__.__name__}.")
emitter = getattr(class_object, self.signal_name).emit
......
......@@ -26,7 +26,7 @@ class _Cache(object):
# set attribute on instance
name = '%s_called' % self.func.__name__
# print(f"Setting {name} in {}!")
self.instance_._internal_logger.debug(
self.instance_._module_logger.debug(
f"Setting {name} in {self.instance_.__class__.__name__} and emitting {self.signal_name}!")
# setattr(self.instance_, name, datetime.utcnow())
......
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment