From a03554bf0ef81a51377a3046d3e533108bb42855 Mon Sep 17 00:00:00 2001 From: rmorshea Date: Tue, 4 Jan 2022 23:18:15 -0800 Subject: [PATCH] implement the use_debug_value hook --- .pre-commit-config.yaml | 2 +- src/idom/__init__.py | 2 + src/idom/core/hooks.py | 56 ++++++++++++++++++ src/idom/core/layout.py | 9 +++ src/idom/testing.py | 100 ++++++++++++++++++++++++--------- tests/test_core/test_hooks.py | 80 +++++++++++++++++++++++++- tests/test_core/test_layout.py | 16 +++--- 7 files changed, 230 insertions(+), 35 deletions(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 319bab4a2..3f16f971b 100644 --- a/.pre-commit-config.yaml +++ b/.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 diff --git a/src/idom/__init__.py b/src/idom/__init__.py index 20f6472ff..991b70e5d 100644 --- a/src/idom/__init__.py +++ b/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", diff --git a/src/idom/core/hooks.py b/src/idom/core/hooks.py index 0aeb2a0d5..621dea76d 100644 --- a/src/idom/core/hooks.py +++ b/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], diff --git a/src/idom/core/layout.py b/src/idom/core/layout.py index 0e228b83f..f73cd6600 100644 --- a/src/idom/core/layout.py +++ b/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") diff --git a/src/idom/testing.py b/src/idom/testing.py index 24592208e..87e853cc1 100644 --- a/src/idom/testing.py +++ b/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): diff --git a/tests/test_core/test_hooks.py b/tests/test_core/test_hooks.py index 8ecb705ee..0451d35fd 100644 --- a/tests/test_core/test_hooks.py +++ b/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() diff --git a/tests/test_core/test_layout.py b/tests/test_core/test_layout.py index 08df5e7b3..894a39c9d 100644 --- a/tests/test_core/test_layout.py +++ b/tests/test_core/test_layout.py @@ -13,7 +13,7 @@ from idom.testing import ( HookCatcher, StaticEventHandler, - assert_idom_logged, + assert_idom_did_log, capture_idom_logs, ) from tests.general_utils import assert_same_items @@ -144,7 +144,7 @@ def OkChild(): def BadChild(): raise ValueError("error from bad child") - with assert_idom_logged( + with assert_idom_did_log( match_error="error from bad child", clear_matched_records=True, ): @@ -188,7 +188,7 @@ def OkChild(): def BadChild(): raise ValueError("error from bad child") - with assert_idom_logged( + with assert_idom_did_log( match_error="error from bad child", clear_matched_records=True, ): @@ -649,7 +649,7 @@ def ComponentReturnsDuplicateKeys(): idom.html.div(key="duplicate"), idom.html.div(key="duplicate") ) - with assert_idom_logged( + with assert_idom_did_log( error_type=ValueError, match_error=r"Duplicate keys \['duplicate'\] at '/'", clear_matched_records=True, @@ -692,7 +692,7 @@ def raise_error(): return idom.html.button({"onClick": raise_error}) - with assert_idom_logged( + with assert_idom_did_log( match_error="bad event handler", clear_matched_records=True, ): @@ -719,7 +719,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", ): with idom.Layout(Parent()) as layout: @@ -758,7 +758,7 @@ def Child(): "component": Child(key="the-same-key"), } - with assert_idom_logged( + with assert_idom_did_log( error_type=ValueError, match_error="prior element with this key wasn't a component", clear_matched_records=True, @@ -789,7 +789,7 @@ def Child(): "component": Child(key="the-same-key"), } - with assert_idom_logged( + with assert_idom_did_log( error_type=ValueError, match_error="prior element with this key was a component", clear_matched_records=True,