diff --git a/reacton/core.py b/reacton/core.py index 4956275..93441c8 100644 --- a/reacton/core.py +++ b/reacton/core.py @@ -1760,6 +1760,10 @@ def format(reason: RerenderReason): finally: local.rc = prev_rc # type: ignore self._is_rendering = False + # clear before the lock is released: a stale _lock_thread makes the + # recursion guard above fire for a thread that merely rendered last, + # while a *different* thread holds the lock (false "Recursive render") + self._lock_thread = None assert self.context is self.context_root exceptions = [*self.context.exceptions_children, *self.context_root.exceptions_self] @@ -2101,6 +2105,7 @@ def _reconsolidate(self, el: Element, default_key: str, parent_key: str): try: effect.cleanup() except BaseException as e: + logger.exception("Effect cleanup %r raised exception %r", effect.callable, e) context.exceptions_self.append(e) self._rerender_needed_reasons.append(RerenderReason(reason="Exception ocurred during effect")) self._rerender_needed = True @@ -2112,6 +2117,7 @@ def _reconsolidate(self, el: Element, default_key: str, parent_key: str): continue effect() except BaseException as e: + logger.exception("Effect %r raised exception %r", effect.callable, e) context.exceptions_self.append(e) self._rerender_needed_reasons.append(RerenderReason(reason="Exception ocurred during effect")) self._rerender_needed = True @@ -2123,6 +2129,7 @@ def _reconsolidate(self, el: Element, default_key: str, parent_key: str): continue effect() except BaseException as e: + logger.exception("Effect %r raised exception %r", effect.callable, e) context.exceptions_self.append(e) self._rerender_needed_reasons.append(RerenderReason(reason="Exception ocurred during effect")) self._rerender_needed = True @@ -2336,6 +2343,7 @@ def _remove_element(self, el: Element, default_key: str, parent_key): if not effect._cleaned_up: effect.cleanup() except BaseException as e: + logger.exception("Effect cleanup %r raised exception %r", effect.callable, e) child_context.exceptions_self.append(e) self._rerender_needed_reasons.append(RerenderReason(reason="Exception ocurred during effect")) self._rerender_needed = True @@ -2876,6 +2884,7 @@ def _process_effects(self, child_context: "ComponentContext", context: "Componen try: effect.cleanup() except BaseException as e: + logger.exception("Effect cleanup %r raised exception %r", effect.callable, e) context.exceptions_self.append(e) self._set_rerender_needed("Exception ocurred during effect") _mark_needs_render_ancestors(context) @@ -2887,6 +2896,7 @@ def _process_effects(self, child_context: "ComponentContext", context: "Componen try: effect() except BaseException as e: + logger.exception("Effect %r raised exception %r", effect.callable, e) context.exceptions_self.append(e) self._set_rerender_needed("Exception ocurred during effect") _mark_needs_render_ancestors(context) @@ -2930,6 +2940,7 @@ def _remove_element(self, el: Element, default_key: str, parent_key): if not effect._cleaned_up: effect.cleanup() except BaseException as e: + logger.exception("Effect cleanup %r raised exception %r", effect.callable, e) child_context.exceptions_self.append(e) self._set_rerender_needed("Exception ocurred during effect") _mark_needs_render_ancestors(child_context) diff --git a/reacton/core_test.py b/reacton/core_test.py index ee9e117..9e24e35 100644 --- a/reacton/core_test.py +++ b/reacton/core_test.py @@ -1,5 +1,6 @@ import gc import sys +import threading import time import traceback import unittest.mock @@ -3447,3 +3448,89 @@ def effect(): set_other(1) assert root.children[0].description == "other 1" rc.close() + + +def test_effect_exception_is_logged(caplog): + @react.component + def Test(): + def effect(): + raise RuntimeError("boom") + + react.use_effect(effect, []) + return w.Button() + + with caplog.at_level("ERROR", logger="reacton"): + # handle_error=True: the exception is turned into an error page, which is + # exactly why it used to be invisible in the logs + box, rc = react.render(Test(), handle_error=True) + assert "Traceback" in rc.find(ipywidgets.HTML).widget.value + records = [r for r in caplog.records if r.name == "reacton" and r.levelname == "ERROR"] + assert len(records) == 1, records + assert "Effect" in records[0].getMessage() + assert records[0].exc_info is not None + rc.close() + + +def test_effect_cleanup_exception_is_logged(caplog): + set_value = None + failed: List[bool] = [] + + @react.component + def Test(): + nonlocal set_value + value, set_value = react.use_state(0) + + def effect(): + def cleanup(): + # only the first cleanup fails, so the error page can tear down cleanly + if not failed: + failed.append(True) + raise RuntimeError("cleanup boom") + + return cleanup + + react.use_effect(effect, [value]) + return w.Button() + + box, rc = react.render(Test(), handle_error=True) + assert set_value is not None + with caplog.at_level("ERROR", logger="reacton"): + set_value(1) + records = [r for r in caplog.records if r.name == "reacton" and r.levelname == "ERROR"] + assert len(records) == 1, records + assert "Effect cleanup" in records[0].getMessage() + assert records[0].exc_info is not None + rc.close() + + +def test_render_lock_no_false_recursive_render(): + # close() takes the render lock without touching _lock_thread. With a stale + # _lock_thread the recursion guard fires for the thread that merely rendered + # last, while a *different* thread holds the lock. + holding = threading.Event() + + @react.component + def Test(): + def effect(): + def cleanup(): + holding.set() + # hold the render lock long enough for the main thread to hit the guard + time.sleep(0.5) + + return cleanup + + react.use_effect(effect, []) + return w.Button() + + box, rc = react.render(Test(), handle_error=False) + # the main thread rendered last, so rc._lock_thread pointed at it + + thread = threading.Thread(target=rc.close) + thread.start() + try: + assert holding.wait(5) + # the other thread holds the render lock: this must wait for it, not raise + rc.render(Test(), box) + finally: + thread.join(5) + assert not thread.is_alive()