Log effect exceptions and clear the render lock owner

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)

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()