From 9b967999af837a177be84a48336f0cf5e9fcbf43 Mon Sep 17 00:00:00 2001 From: azawlocki Date: Wed, 21 Apr 2021 09:48:58 +0200 Subject: [PATCH 1/3] Fix assertion success/failure reporting in the EventMonitor --- goth/assertions/monitor.py | 33 ++++++++++++----- test/goth/assertions/test_monitor.py | 55 +++++++++++++++++++++++++++- 2 files changed, 77 insertions(+), 11 deletions(-) diff --git a/goth/assertions/monitor.py b/goth/assertions/monitor.py index 11c2c995..d1ee20b9 100644 --- a/goth/assertions/monitor.py +++ b/goth/assertions/monitor.py @@ -8,7 +8,7 @@ import importlib import logging import sys -from typing import Callable, Generic, List, Optional, Sequence, Union +from typing import Callable, Generic, List, Optional, Sequence, Set, Union import colors @@ -76,6 +76,9 @@ class EventMonitor(Generic[E]): _logger: Union[logging.Logger, MonitorLoggerAdapter] """A logger instance for this monitor.""" + _reported: Set[Assertion[E]] + """The set of assertions for which acceptance or failure has been reported.""" + _worker_task: Optional[asyncio.Task] """A worker task that registers events and checks assertions.""" @@ -97,6 +100,7 @@ def __init__( self._logger = MonitorLoggerAdapter( self._logger, {MonitorLoggerAdapter.EXTRA_MONITOR_NAME: self.name} ) + self._reported = set() self._stop_callback = on_stop self._worker_task = None @@ -245,6 +249,12 @@ async def _run_worker(self) -> None: await self._check_assertions(events_ended) async def _check_assertions(self, events_ended: bool) -> None: + """Notify assertions that a new event has occurred. + + Should be called exactly once after a new event is added + to `self._events` or after the monitor is stopped, with + `events_ended` set to `True`. + """ event_descr = ( f"#{len(self._events)} ({self._events[-1]})" @@ -252,23 +262,26 @@ async def _check_assertions(self, events_ended: bool) -> None: else "EndOfEvents" ) + # Notify all active (not done) assertions about the new event. + for a in list(self.assertions.keys()): + if not a.done: + await a.update_events(events_ended=events_ended) + + # Report acceptance/failure for all assertions that completed + # since last check. for a, level in list(self.assertions.items()): - if a.done: + if not a.done or a in self._reported: continue - await a.update_events(events_ended=events_ended) - - if a.done: - self._logger.debug( - "Assertion '%s' finished after event %s", a.name, event_descr - ) - + self._reported.add(a) + self._logger.debug( + "Assertion '%s' finished after event %s", a.name, event_descr + ) if a.accepted: result = a.result() msg = colors.green("Assertion '%s' succeeded; result: %s", style="bold") self._logger.log(level, msg, a.name, result) - elif a.failed: await self._report_failure(a) diff --git a/test/goth/assertions/test_monitor.py b/test/goth/assertions/test_monitor.py index d15776a5..669e01e6 100644 --- a/test/goth/assertions/test_monitor.py +++ b/test/goth/assertions/test_monitor.py @@ -1,5 +1,4 @@ """Test the `assertions.monitor`.""" - import asyncio import pytest @@ -220,3 +219,57 @@ async def long_running_assertion_2(stream: Events): monitor.add_assertion(assert_all_positive) await monitor.stop() + + +@pytest.mark.asyncio +async def test_assertion_results_reported(caplog): + """Test that assertion success and failure are logged. + + This used to be a problem for assertions that do not succeed or fail + immediately after consuming an event. For example if an assertion + contains `asyncio.wait_for()` then it may raise an exception some time + after it consumed any event. After the failure, the monitor will not + feed new events to the assertion. But it should report the failure + (exactly once). + """ + + monitor = EventMonitor() + + async def never_accept(events): + async for _ in events: + pass + + async def await_impossible(events): + await asyncio.wait_for(never_accept(events), timeout=0.1) + + async def await_inevitable(events): + try: + await asyncio.wait_for(never_accept(events), timeout=0.1) + except asyncio.TimeoutError: + return "I'm fine!" + + monitor.add_assertion(await_impossible) + monitor.add_assertion(await_inevitable) + monitor.start() + + await monitor.add_event(1) + # At this point the assertions are still alive + assert not monitor.done + + await asyncio.sleep(0.3) + # The assertions should be done now + assert monitor.failed + assert monitor.satisfied + + # Stopping the monitor should trigger logging assertion success and + # failure messages + await monitor.stop() + + assert any( + record.levelname == "ERROR" and "failed" in record.message + for record in caplog.records + ) + assert any( + record.levelname == "INFO" and "I'm fine!" in record.message + for record in caplog.records + ) From 3b676ae8fd7635e5bb9d611877ef111c8e6c3a06 Mon Sep 17 00:00:00 2001 From: azawlocki Date: Wed, 21 Apr 2021 10:00:38 +0200 Subject: [PATCH 2/3] Add possibility of passing extra monitors to Runner.check_assertion_errors() --- goth/runner/__init__.py | 9 ++-- test/goth/runner/test_assertion_monitors.py | 53 +++++++++++++++++++++ 2 files changed, 59 insertions(+), 3 deletions(-) create mode 100644 test/goth/runner/test_assertion_monitors.py diff --git a/goth/runner/__init__.py b/goth/runner/__init__.py index 8d71cea0..b10c4f43 100644 --- a/goth/runner/__init__.py +++ b/goth/runner/__init__.py @@ -18,8 +18,10 @@ TypeVar, ) +import colors import docker +from goth.assertions.monitor import EventMonitor from goth.runner.container.compose import ( ComposeConfig, ComposeNetworkManager, @@ -123,7 +125,7 @@ def get_probes( probes = [p for p in probes if isinstance(p, probe_type)] return cast(List[ProbeType], probes) - def check_assertion_errors(self) -> None: + def check_assertion_errors(self, *extra_monitors: EventMonitor) -> None: """If any monitor reports an assertion error, raise the first error.""" probe_agents = chain(*(probe.agents for probe in self.probes)) @@ -133,6 +135,7 @@ def check_assertion_errors(self) -> None: (probe.container.logs for probe in self.probes), (agent.log_monitor for agent in probe_agents), [self.proxy.monitor] if self.proxy else [], + extra_monitors, ) ) failed = chain.from_iterable( @@ -257,7 +260,7 @@ async def __call__( async def _enter(self) -> None: self._exit_stack.enter_context(configure_logging_for_test(self.log_dir)) - logger.info("Running test: %s", self.test_name) + logger.info(colors.yellow("Running test: %s"), self.test_name) await self._exit_stack.enter_async_context( run_compose_network(self._compose_manager, self.log_dir) @@ -274,7 +277,7 @@ async def _enter(self) -> None: await self._start_nodes() async def _exit(self): - logger.info("Test finished: %s", self.test_name) + logger.info(colors.yellow("Test finished: %s"), self.test_name) await self._exit_stack.aclose() payment.clean_up() diff --git a/test/goth/runner/test_assertion_monitors.py b/test/goth/runner/test_assertion_monitors.py new file mode 100644 index 00000000..060b8ffb --- /dev/null +++ b/test/goth/runner/test_assertion_monitors.py @@ -0,0 +1,53 @@ +"""Unit tests related to the use of assertion monitors in Runner.""" + +import asyncio +from pathlib import Path +import tempfile +from unittest.mock import Mock + +import pytest + +from goth.assertions.monitor import EventMonitor +from goth.runner import Runner, TemporalAssertionError + + +@pytest.mark.asyncio +async def test_check_assertions(caplog): + """Test the `Runner.check_assertion_errors()` method.""" + + runner = Runner( + base_log_dir=Path(tempfile.mkdtemp()), + compose_config=Mock(), + ) + + async def assertion(events): + async for _ in events: + break + async for _ in events: + raise AssertionError("Just failing") + + idle_monitor = EventMonitor() + idle_monitor.start() + busy_monitor = EventMonitor() + busy_monitor.add_assertion(assertion) + busy_monitor.start() + + await asyncio.sleep(0.1) + runner.check_assertion_errors(idle_monitor, busy_monitor) + + await busy_monitor.add_event(1) + await asyncio.sleep(0.1) + runner.check_assertion_errors(idle_monitor, busy_monitor) + + await busy_monitor.add_event(2) + await asyncio.sleep(0.1) + # Assertion failure should be logged at this point + assert any(record.levelname == "ERROR" for record in caplog.records) + # And `check_assertion_errors()` should raise an exception + with pytest.raises(TemporalAssertionError): + runner.check_assertion_errors(idle_monitor, busy_monitor) + + await busy_monitor.stop() + await idle_monitor.stop() + with pytest.raises(TemporalAssertionError): + runner.check_assertion_errors(idle_monitor, busy_monitor) From 692ed032b67b851a0c38b5f3f57c904adf97c74a Mon Sep 17 00:00:00 2001 From: azawlocki Date: Wed, 21 Apr 2021 12:11:48 +0200 Subject: [PATCH 3/3] Bump project version in pyproject.toml --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 82f537e9..7263d727 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ exclude= '/(\.eggs|\.git|\.hg|\.mypy_cache|\.nox|\.tox|\.venv|venv|\.svn|_build| [tool.poetry] name = "goth" -version = "0.2.3" +version = "0.2.4" description = "Golem Test Harness - integration testing framework" authors = ["Golem Factory "] license = "GPL-3.0"