add use debug value hook (#733)

* add use debug value hook

* changelog entry

* fix tests

* export at top level

* no cover

* fix doctest

Author: rmorshea

docs/source/about/changelog.rst

@@ -23,7 +23,13 @@ more info, see the :ref:`Contributor Guide <Creating a Changelog Entry>`.
 Unreleased
 ----------
 
-No changes.
+**Added**
+
+- :pull:`733` - ``use_debug_value`` hook
+
+**Changed**
+
+- :pull:`733` - renamed ``assert_idom_logged`` testing util to ``assert_idom_did_log``
 
 
 v0.38.0-a3

src/idom/__init__.py

@@ -7,6 +7,7 @@
     create_context,
     use_callback,
     use_context,
+    use_debug_value,
     use_effect,
     use_memo,
     use_reducer,
@@ -42,6 +43,7 @@
     "types",
     "use_callback",
     "use_context",
+    "use_debug_value",
     "use_effect",
     "use_memo",
     "use_reducer",

src/idom/core/hooks.py

@@ -24,10 +24,11 @@
 
 from typing_extensions import Protocol
 
+from idom.config import IDOM_DEBUG_MODE
 from idom.utils import Ref
 
 from ._thread_local import ThreadLocal
-from .types import Key, VdomDict
+from .types import ComponentType, Key, VdomDict
 from .vdom import vdom
 
 
@@ -204,6 +205,40 @@ def effect() -> None:
         return add_effect
 
 
+def use_debug_value(
+    message: Any | Callable[[], Any],
+    dependencies: Sequence[Any] | ellipsis | None = ...,
+) -> None:
+    """Log debug information when the given message changes.
+
+    .. note::
+        This hook only logs if :data:`~idom.config.IDOM_DEBUG_MODE` is active.
+
+    Unlike other hooks, a message is considered to have changed if the old and new
+    values are ``!=``. Because this comparison is performed on every render of the
+    component, it may be worth considering the performance cost in some situations.
+
+    Parameters:
+        message:
+            The value to log or a memoized function for generating the value.
+        dependencies:
+            Dependencies for the memoized function. The message will only be recomputed
+            if the identity of any value in the given sequence changes (i.e. their
+            :func:`id` is different). By default these are inferred based on local
+            variables that are referenced by the given function.
+    """
+    if not IDOM_DEBUG_MODE.current:
+        return  # pragma: no cover
+
+    old: Ref[Any] = _use_const(lambda: Ref(object()))
+    memo_func = message if callable(message) else lambda: message
+    new = use_memo(memo_func, dependencies)
+
+    if old.current != new:
+        old.current = new
+        logger.debug(f"{current_hook().component} {new}")
+
+
 def create_context(
     default_value: _StateType, name: str | None = None
 ) -> type[Context[_StateType]]:
@@ -576,7 +611,7 @@ class LifeCycleHook:
 
             # --- start render cycle ---
 
-            hook.affect_component_will_render()
+            hook.affect_component_will_render(...)
 
             hook.set_current()
 
@@ -614,16 +649,19 @@ class LifeCycleHook:
     """
 
     __slots__ = (
+        "__weakref__",
+        "_current_state_index",
+        "_event_effects",
+        "_is_rendering",
+        "_rendered_atleast_once",
         "_schedule_render_callback",
         "_schedule_render_later",
-        "_current_state_index",
         "_state",
-        "_rendered_atleast_once",
-        "_is_rendering",
-        "_event_effects",
-        "__weakref__",
+        "component",
     )
 
+    component: ComponentType
+
     def __init__(
         self,
         schedule_render: Callable[[], None],
@@ -662,13 +700,17 @@ def add_effect(self, effect_type: EffectType, function: Callable[[], None]) -> N
         """Trigger a function on the occurance of the given effect type"""
         self._event_effects[effect_type].append(function)
 
-    def affect_component_will_render(self) -> None:
+    def affect_component_will_render(self, component: ComponentType) -> None:
         """The component is about to render"""
+        self.component = component
+
         self._is_rendering = True
         self._event_effects[COMPONENT_WILL_UNMOUNT_EFFECT].clear()
 
     def affect_component_did_render(self) -> None:
         """The component completed a render"""
+        del self.component
+
         component_did_render_effects = self._event_effects[COMPONENT_DID_RENDER_EFFECT]
         for effect in component_did_render_effects:
             try:

src/idom/core/layout.py

@@ -199,7 +199,7 @@ def _render_component(
             new_state.model.current = old_state.model.current
         else:
             life_cycle_hook = life_cycle_state.hook
-            life_cycle_hook.affect_component_will_render()
+            life_cycle_hook.affect_component_will_render(component)
             try:
                 life_cycle_hook.set_current()
                 try:

src/idom/testing/__init__.py

@@ -2,16 +2,16 @@
 from .display import DisplayFixture
 from .logs import (
     LogAssertionError,
+    assert_idom_did_log,
     assert_idom_did_not_log,
-    assert_idom_logged,
     capture_idom_logs,
 )
 from .server import ServerFixture
 
 
 __all__ = [
     "assert_idom_did_not_log",
-    "assert_idom_logged",
+    "assert_idom_did_log",
     "capture_idom_logs",
     "clear_idom_web_modules_dir",
     "DisplayFixture",

src/idom/testing/logs.py

@@ -14,7 +14,7 @@ class LogAssertionError(AssertionError):
 
 
 @contextmanager
-def assert_idom_logged(
+def assert_idom_did_log(
     match_message: str = "",
     error_type: type[Exception] | None = None,
     match_error: str = "",
@@ -77,7 +77,7 @@ def assert_idom_did_not_log(
 ) -> Iterator[None]:
     """Assert the inverse of :func:`assert_idom_logged`"""
     try:
-        with assert_idom_logged(match_message, error_type, match_error):
+        with assert_idom_did_log(match_message, error_type, match_error):
             yield None
     except LogAssertionError:
         pass

tests/test_core/test_hooks.py

@@ -5,10 +5,12 @@
 
 import idom
 from idom import html
+from idom.config import IDOM_DEBUG_MODE
 from idom.core.hooks import COMPONENT_DID_RENDER_EFFECT, LifeCycleHook, current_hook
 from idom.core.layout import Layout
 from idom.core.serve import render_json_patch
-from idom.testing import DisplayFixture, HookCatcher, assert_idom_logged, poll
+from idom.testing import DisplayFixture, HookCatcher, assert_idom_did_log, poll
+from idom.testing.logs import assert_idom_did_not_log
 from idom.utils import Ref
 from tests.tooling.asserts import assert_same_items
 
@@ -553,7 +555,7 @@ def bad_effect():
 
         return idom.html.div()
 
-    with assert_idom_logged(match_message=r"Layout post-render effect .* failed"):
+    with assert_idom_did_log(match_message=r"Layout post-render effect .* failed"):
         async with idom.Layout(ComponentWithEffect()) as layout:
             await layout.render()  # no error
 
@@ -574,7 +576,7 @@ def bad_cleanup():
 
         return idom.html.div()
 
-    with assert_idom_logged(match_error=r"Layout post-render effect .* failed"):
+    with assert_idom_did_log(match_error=r"Layout post-render effect .* failed"):
         async with idom.Layout(ComponentWithEffect()) as layout:
             await layout.render()
             component_hook.latest.schedule_render()
@@ -600,7 +602,7 @@ def bad_cleanup():
 
         return idom.html.div()
 
-    with assert_idom_logged(
+    with assert_idom_did_log(
         match_message=r"Pre-unmount effect .*? failed",
         error_type=ValueError,
     ):
@@ -843,7 +845,7 @@ def test_bad_schedule_render_callback():
     def bad_callback():
         raise ValueError("something went wrong")
 
-    with assert_idom_logged(
+    with assert_idom_did_log(
         match_message=f"Failed to schedule render via {bad_callback}"
     ):
         LifeCycleHook(bad_callback).schedule_render()
@@ -1137,7 +1139,7 @@ def bad_effect():
         hook.add_effect(COMPONENT_DID_RENDER_EFFECT, bad_effect)
         return idom.html.div()
 
-    with assert_idom_logged(
+    with assert_idom_did_log(
         match_message="Component post-render effect .*? failed",
         error_type=ValueError,
         match_error="The error message",
@@ -1168,3 +1170,80 @@ def SetStateDuringRender():
         # there should be no more renders to perform
         with pytest.raises(asyncio.TimeoutError):
             await asyncio.wait_for(layout.render(), timeout=0.1)
+
+
+@pytest.mark.skipif(not IDOM_DEBUG_MODE.current, reason="only logs in debug mode")
+async def test_use_debug_mode():
+    set_message = idom.Ref()
+    component_hook = HookCatcher()
+
+    @idom.component
+    @component_hook.capture
+    def SomeComponent():
+        message, set_message.current = idom.use_state("hello")
+        idom.use_debug_value(f"message is {message!r}")
+        return idom.html.div()
+
+    async with idom.Layout(SomeComponent()) as layout:
+
+        with assert_idom_did_log(r"SomeComponent\(.*?\) message is 'hello'"):
+            await layout.render()
+
+        set_message.current("bye")
+
+        with assert_idom_did_log(r"SomeComponent\(.*?\) message is 'bye'"):
+            await layout.render()
+
+        component_hook.latest.schedule_render()
+
+        with assert_idom_did_not_log(r"SomeComponent\(.*?\) message is 'bye'"):
+            await layout.render()
+
+
+@pytest.mark.skipif(not IDOM_DEBUG_MODE.current, reason="only logs in debug mode")
+async def test_use_debug_mode_with_factory():
+    set_message = idom.Ref()
+    component_hook = HookCatcher()
+
+    @idom.component
+    @component_hook.capture
+    def SomeComponent():
+        message, set_message.current = idom.use_state("hello")
+        idom.use_debug_value(lambda: f"message is {message!r}")
+        return idom.html.div()
+
+    async with idom.Layout(SomeComponent()) as layout:
+
+        with assert_idom_did_log(r"SomeComponent\(.*?\) message is 'hello'"):
+            await layout.render()
+
+        set_message.current("bye")
+
+        with assert_idom_did_log(r"SomeComponent\(.*?\) message is 'bye'"):
+            await layout.render()
+
+        component_hook.latest.schedule_render()
+
+        with assert_idom_did_not_log(r"SomeComponent\(.*?\) message is 'bye'"):
+            await layout.render()
+
+
+@pytest.mark.skipif(IDOM_DEBUG_MODE.current, reason="logs in debug mode")
+async def test_use_debug_mode_does_not_log_if_not_in_debug_mode():
+    set_message = idom.Ref()
+
+    @idom.component
+    def SomeComponent():
+        message, set_message.current = idom.use_state("hello")
+        idom.use_debug_value(lambda: f"message is {message!r}")
+        return idom.html.div()
+
+    async with idom.Layout(SomeComponent()) as layout:
+
+        with assert_idom_did_not_log(r"SomeComponent\(.*?\) message is 'hello'"):
+            await layout.render()
+
+        set_message.current("bye")
+
+        with assert_idom_did_not_log(r"SomeComponent\(.*?\) message is 'bye'"):
+            await layout.render()

tests/test_core/test_layout.py

@@ -17,7 +17,7 @@
 from idom.testing import (
     HookCatcher,
     StaticEventHandler,
-    assert_idom_logged,
+    assert_idom_did_log,
     capture_idom_logs,
 )
 from idom.utils import Ref
@@ -181,7 +181,7 @@ def OkChild():
     def BadChild():
         raise ValueError("error from bad child")
 
-    with assert_idom_logged(match_error="error from bad child"):
+    with assert_idom_did_log(match_error="error from bad child"):
 
         async with idom.Layout(Main()) as layout:
             patch = await render_json_patch(layout)
@@ -237,7 +237,7 @@ def OkChild():
     def BadChild():
         raise ValueError("error from bad child")
 
-    with assert_idom_logged(match_error="error from bad child"):
+    with assert_idom_did_log(match_error="error from bad child"):
 
         async with idom.Layout(Main()) as layout:
             patch = await render_json_patch(layout)
@@ -734,7 +734,7 @@ def ComponentReturnsDuplicateKeys():
             return idom.html.div()
 
     async with idom.Layout(ComponentReturnsDuplicateKeys()) as layout:
-        with assert_idom_logged(
+        with assert_idom_did_log(
             error_type=ValueError,
             match_error=r"Duplicate keys \['duplicate'\] at '/children/0'",
         ):
@@ -747,7 +747,7 @@ def ComponentReturnsDuplicateKeys():
 
         should_error = True
         hook.latest.schedule_render()
-        with assert_idom_logged(
+        with assert_idom_did_log(
             error_type=ValueError,
             match_error=r"Duplicate keys \['duplicate'\] at '/children/0'",
         ):
@@ -788,7 +788,7 @@ def raise_error():
 
         return idom.html.button({"onClick": raise_error})
 
-    with assert_idom_logged(match_error="bad event handler"):
+    with assert_idom_did_log(match_error="bad event handler"):
 
         async with idom.Layout(ComponentWithBadEventHandler()) as layout:
             await layout.render()
@@ -812,7 +812,7 @@ def Child(state):
         idom.hooks.use_effect(lambda: lambda: print("unmount", state))
         return idom.html.div(state)
 
-    with assert_idom_logged(
+    with assert_idom_did_log(
         r"Did not render component with model state ID .*? - component already unmounted",
     ):
         async with idom.Layout(Parent()) as layout:
@@ -1218,7 +1218,7 @@ def bad_should_render(new):
 
         return ComponentShouldRender(html.div(), should_render=bad_should_render)
 
-    with assert_idom_logged(
+    with assert_idom_did_log(
         match_message=r".* component failed to check if .* should be rendered",
         error_type=ValueError,
         match_error="The error message",