implement the use_debug_value hook

Author: rmorshea

.pre-commit-config.yaml

@@ -4,7 +4,7 @@ repos:
     hooks:
       - id: black
   - repo: https://github.com/PyCQA/flake8
-    rev: 3.7.9
+    rev: 4.0.1
     hooks:
       - id: flake8
   - repo: https://github.com/pycqa/isort

src/idom/__init__.py

@@ -5,6 +5,7 @@
 from .core.events import EventHandler, event
 from .core.hooks import (
     use_callback,
+    use_debug_value,
     use_effect,
     use_memo,
     use_reducer,
@@ -42,6 +43,7 @@
     "run",
     "Stop",
     "use_callback",
+    "use_debug_value",
     "use_effect",
     "use_memo",
     "use_reducer",

src/idom/core/hooks.py

@@ -24,8 +24,11 @@
 
 from typing_extensions import Protocol
 
+from idom.config import IDOM_DEBUG_MODE
 from idom.utils import Ref
 
+from .proto import ComponentType
+
 
 if not TYPE_CHECKING:
     # make flake8 think that this variable exists
@@ -392,6 +395,54 @@ def use_ref(initial_value: _StateType) -> Ref[_StateType]:
     return _use_const(lambda: Ref(initial_value))
 
 
+if IDOM_DEBUG_MODE.current:
+
+    def use_debug_value(
+        message: Any | Callable[[], Any],
+        dependencies: Sequence[Any] | ellipsis | None = ...,
+    ) -> None:
+        """Log debug information when the given message changes.
+
+        Differently from 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.
+
+        .. note::
+
+            This hook only logs if :data:`~idom.config.IDOM_DEBUG_MODE` is active.
+        """
+        old_ref = _use_const(Ref)
+        memo_func = message if callable(message) else lambda: message
+        new = use_memo(memo_func, dependencies)
+
+        try:
+            old = old_ref.current
+        except AttributeError:
+            old = object()
+
+        if old != new:
+            old_ref.current = new
+            logger.debug(f"{current_hook().component} {new}")
+
+else:  # pragma: no cover
+
+    def use_debug_value(
+        message: Any | Callable[[], Any],
+        dependencies: Sequence[Any] | ellipsis | None = ...,
+    ) -> None:
+        """This hook does nothing because :data:`~idom.config.IDOM_DEBUG_MODE` is off"""
+
+
 def _use_const(function: Callable[[], _StateType]) -> _StateType:
     return current_hook().use_state(function)
 
@@ -507,6 +558,11 @@ class LifeCycleHook:
         "__weakref__",
     )
 
+    if IDOM_DEBUG_MODE.current:
+        __slots__ += ("component",)
+        component: ComponentType
+        """Only exists if in :data:`~idom.config.IDOM_DEBUG_MODE` is active."""
+
     def __init__(
         self,
         schedule_render: Callable[[], None],

src/idom/core/layout.py

@@ -644,6 +644,15 @@ class _LifeCycleState(NamedTuple):
     """The current component instance"""
 
 
+if IDOM_DEBUG_MODE.current:
+    # When in debug mode we bind a hook's associated component
+    # to it so we can have more information when logging.
+
+    class _LifeCycleState(_LifeCycleState):
+        def __init__(self, *args: Any, **kwargs: Any) -> None:
+            self.hook.component = self.component
+
+
 _Type = TypeVar("_Type")
 
 

src/idom/testing.py

@@ -14,6 +14,7 @@
     Generic,
     Iterator,
     List,
+    NoReturn,
     Optional,
     Tuple,
     Type,
@@ -173,8 +174,12 @@ def __exit__(
         return None
 
 
+class LogAssertionError(AssertionError):
+    """An assertion error raised in relation to log messages."""
+
+
 @contextmanager
-def assert_idom_logged(
+def assert_idom_did_log(
     match_message: str = "",
     error_type: type[Exception] | None = None,
     match_error: str = "",
@@ -192,11 +197,13 @@ def assert_idom_logged(
     error_pattern = re.compile(match_error)
 
     try:
-        with capture_idom_logs() as handler:
+        with capture_idom_logs(use_existing=clear_matched_records) as log_records:
             yield None
-    finally:
+    except Exception:
+        raise
+    else:
         found = False
-        for record in list(handler.records):
+        for record in list(log_records):
             if (
                 # record message matches
                 message_pattern.findall(record.getMessage())
@@ -222,36 +229,79 @@ def assert_idom_logged(
             ):
                 found = True
                 if clear_matched_records:
-                    handler.records.remove(record)
+                    log_records.remove(record)
 
         if not found:  # pragma: no cover
-            conditions = []
-            if match_message:
-                conditions.append(f"log message pattern {match_message!r}")
-            if error_type:
-                conditions.append(f"exception type {error_type}")
-            if match_error:
-                conditions.append(f"error message pattern {match_error!r}")
-            raise AssertionError(
-                "Could not find a log record matching the given "
-                + " and ".join(conditions)
+            _raise_log_message_error(
+                "Could not find a log record matching the given",
+                match_message,
+                error_type,
+                match_error,
             )
 
 
 @contextmanager
-def capture_idom_logs() -> Iterator[_LogRecordCaptor]:
-    """Capture logs from IDOM"""
-    if _LOG_RECORD_CAPTOR_SINGLTON in ROOT_LOGGER.handlers:
-        # this is being handled by an outer capture context
-        yield _LOG_RECORD_CAPTOR_SINGLTON
-        return None
+def assert_idom_did_not_log(
+    match_message: str = "",
+    error_type: type[Exception] | None = None,
+    match_error: str = "",
+    clear_matched_records: bool = False,
+) -> Iterator[None]:
+    """Assert the inverse of :func:`assert_idom_did_log`"""
+    try:
+        with assert_idom_did_log(
+            match_message, error_type, match_error, clear_matched_records
+        ):
+            yield None
+    except LogAssertionError:
+        pass
+    else:
+        _raise_log_message_error(
+            "Did find a log record matching the given",
+            match_message,
+            error_type,
+            match_error,
+        )
+
+
+def _raise_log_message_error(
+    prefix: str,
+    match_message: str = "",
+    error_type: type[Exception] | None = None,
+    match_error: str = "",
+) -> NoReturn:
+    conditions = []
+    if match_message:
+        conditions.append(f"log message pattern {match_message!r}")
+    if error_type:
+        conditions.append(f"exception type {error_type}")
+    if match_error:
+        conditions.append(f"error message pattern {match_error!r}")
+    raise LogAssertionError(prefix + " " + " and ".join(conditions))
+
 
-    ROOT_LOGGER.addHandler(_LOG_RECORD_CAPTOR_SINGLTON)
+@contextmanager
+def capture_idom_logs(use_existing: bool = False) -> Iterator[list[logging.LogRecord]]:
+    """Capture logs from IDOM
+
+    Parameters:
+        use_existing:
+            If already inside an existing capture context yield the same list of logs.
+            This is useful if you need to mutate the list of logs to affect behavior in
+            the outer context.
+    """
+    if use_existing:
+        for handler in reversed(ROOT_LOGGER.handlers):
+            if isinstance(handler, _LogRecordCaptor):
+                yield handler.records
+                return None
+
+    handler = _LogRecordCaptor()
+    ROOT_LOGGER.addHandler(handler)
     try:
-        yield _LOG_RECORD_CAPTOR_SINGLTON
+        yield handler.records
     finally:
-        ROOT_LOGGER.removeHandler(_LOG_RECORD_CAPTOR_SINGLTON)
-        _LOG_RECORD_CAPTOR_SINGLTON.records = []
+        ROOT_LOGGER.removeHandler(handler)
 
 
 class _LogRecordCaptor(logging.NullHandler):

tests/test_core/test_hooks.py

@@ -4,9 +4,10 @@
 import pytest
 
 import idom
+from idom.config import IDOM_DEBUG_MODE
 from idom.core.dispatcher import render_json_patch
 from idom.core.hooks import LifeCycleHook
-from idom.testing import HookCatcher
+from idom.testing import HookCatcher, assert_idom_did_log, assert_idom_did_not_log
 from tests.general_utils import assert_same_items
 
 
@@ -915,3 +916,80 @@ def some_memo_func_that_uses_count():
             await layout.render()
             await did_memo.wait()
             did_memo.clear()
+
+
+@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()
+
+    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()
+
+    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()
+
+    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()