Ulm-IQO / qudi-core

A framework for modular measurement applications.
GNU General Public License v3.0
25 stars 19 forks source link

[Bug] Exceptions when calling functions in different threads are not correctly logged nor printed to console. #95

Open TobiasSpohn opened 1 month ago

TobiasSpohn commented 1 month ago

Version

Development

What is affected by the bug?

Any module that uses QtCore.Qt.QueuedConnection to call a method from any other thread (module).

When does the bug occur?

When using Qt's QueuedConnection to call a method of a different thread. If the called method raises an exception that exception is never logged nor printed to console. This can be very confusing when testing new modules as no exceptions are thrown when some call fails.

How do we replicate the issue?

I provided a minimal working example in branch no_exception_logging

  1. Checkout branch no_exception_logging
  2. Start Qudi and load config file located at src/exception.cfg
  3. In IPython console call problem_logic.connect_signal(1) problem_logic.emit_signal() or problem_logic.connect_signal(3) problem_logic.emit_signal()
  4. No exception is printed in the console nor in the logger

Expected behavior

The logger should log the exception Exception in exception_method. Maybe even the traceback for easier identification where the exception occured.

If calling problem_logic.connect_signal(2) problem_logic.emit_signal() or problem_logic.connect_signal(4) problem_logic.emit_signal() the exception is correctly logged.

Relevant log output

Calling all 4 signal slots after each other.
2024-05-06 15:24:32 debug qudi.logic.problem_logic.ProblemLogic Emitting signal.
2024-05-06 15:24:32 debug qudi.logic.exception_logic.ExceptionLogic In exception_method.

2024-05-06 15:24:46 debug qudi.logic.problem_logic.ProblemLogic Emitting signal.
2024-05-06 15:24:46 debug qudi.logic.exception_logic.ExceptionLogic In exception_method.
2024-05-06 15:24:46 error qudi.logic.exception_logic.ExceptionLogic Exception in exception_method

2024-05-06 15:24:54 debug qudi.logic.problem_logic.ProblemLogic Emitting signal.
2024-05-06 15:24:54 debug qudi.logic.problem_logic.ProblemLogic Testing exception_method.
2024-05-06 15:24:54 debug qudi.logic.exception_logic.ExceptionLogic In exception_method.

2024-05-06 15:25:43 debug qudi.logic.problem_logic.ProblemLogic Emitting signal.
2024-05-06 15:25:43 debug qudi.logic.problem_logic.ProblemLogic Testing exception_method by wrapping in try,except statement.
2024-05-06 15:25:43 debug qudi.logic.exception_logic.ExceptionLogic In exception_method.
2024-05-06 15:25:43 error qudi.logic.problem_logic.ProblemLogic Exception in exception_method
2024-05-06 15:25:43 debug qudi.logic.problem_logic.ProblemLogic Code after exception throw is reached and exception is logged.

Additional Comments

The resolution to this problem is to wrap the whole method body of the called method into a try, except statement. This is done by using ExceptionLogic.try_except_method as slot method. Or assign a slot method that calls the function in the other thread within a try, except statement. This is done by utilizing ProblemLogic.test_try_except_exception_method as slot method.

Maybe it makes sense to write a wrapper in some Base class that does this automatically.

Furthermore, is it possible to not only log the exception message Exception in exception_method but also the full traceback to simplify the search for what caused the exception?

Contact Details

No response

Neverhorst commented 1 month ago

Well as long as we are not providing "manual" logging by wrapping everything in try-except, this is a problem in PySide2. The PySide2 excepthook does not register exceptions raised in threaded slots.

Regarding your examples... the proper way to "manually" log exceptions in qudi would be:

try:
    ...
except:
    self.log.exception('Something went wrong')
    raise

This will log the full exception traceback and re-raise any exception without alteration.

TobiasSpohn commented 1 month ago

Yes, this is the better way to log the exception. Thanks, I changed the files.

Do you think it is possible and does it make sense to modify the base class so that every method does this wrapping by default? Then at least all exceptions will be logged so the user can deal with it and the exceptions not just "vanish".

Neverhorst commented 1 month ago

Possible, yes. But it comes with quite a large overhead that impacts performance of almost anything in qudi. Each call to a logic method and property will require a check if the caller is the main thread and only wrap the call in try-except if this is not the case.

Before we commit to such drastic workarounds, I would like to check first if this issue has been resolved in PySide6.