diff --git a/README.md b/README.md index 93a754f0..18fafdc2 100644 --- a/README.md +++ b/README.md @@ -1,5 +1,34 @@ -# Log-based testing +# Log-based testing 🪵 [![Build](https://github.com/etianen/logot/actions/workflows/build.yml/badge.svg)](https://github.com/etianen/logot/actions/workflows/build.yml) +[![Docs](https://readthedocs.org/projects/logot/badge/)](https://logot.readthedocs.io) -📖 [Read the docs](https://logot.readthedocs.io) 📖 +`logot` makes it easy to test your application is logging correctly: + +``` python +from logot import Logot, logged + +def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for(logged.info("App started")) +``` + + +## Documentation 📖 + +Full documentation is published on [Read the Docs](https://logot.readthedocs.io). + + +## Bugs / feedback 🐛 + +Issue tracking is hosted on [GitHub](https://github.com/etianen/logot/issues). + + +## Changelog 🏗️ + +Release notes are published on [GitHub](https://github.com/etianen/logot/releases). + + +## License ⚖️ + +``logot`` is published as open-source software under the [MIT license](https://github.com/etianen/logot/blob/main/LICENSE). diff --git a/docs/api.rst b/docs/api.rst new file mode 100644 index 00000000..f88eff5e --- /dev/null +++ b/docs/api.rst @@ -0,0 +1,54 @@ +API reference +============= + +.. currentmodule:: logot + +Import the :mod:`logot` API in your tests: + +.. code:: python + + from logot import Logot, logged + + +:mod:`logot` +------------ + +.. module:: logot + +.. autoclass:: logot.Logot + + .. automethod:: capturing + + .. automethod:: wait_for + + .. automethod:: await_for + + .. automethod:: assert_logged + + .. automethod:: assert_not_logged + + .. autoattribute:: DEFAULT_LEVEL + + .. autoattribute:: DEFAULT_LOGGER + + .. autoattribute:: DEFAULT_TIMEOUT + +.. autoclass:: logot.Logged + + +:mod:`logot.logged` +------------------- + +.. module:: logot.logged + +.. autofunction:: logot.logged.log + +.. autofunction:: logot.logged.debug + +.. autofunction:: logot.logged.info + +.. autofunction:: logot.logged.warning + +.. autofunction:: logot.logged.error + +.. autofunction:: logot.logged.critical diff --git a/docs/conf.py b/docs/conf.py index 4d3a0ea6..94d49198 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -27,4 +27,5 @@ intersphinx_mapping = { "python": ("https://docs.python.org/3", None), + "pytest": ("https://docs.pytest.org/en/latest/", None), } diff --git a/docs/index.rst b/docs/index.rst index e85db2ae..bf1df2f0 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -1,11 +1,155 @@ -Log-based testing -================= +Log-based testing 🪵 +==================== -.. automodule:: logot +.. currentmodule:: logot + +:mod:`logot` makes it easy to test your application is logging correctly: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for(logged.info("App started")) + +.. note:: + + These examples all show using :mod:`logot` with :mod:`pytest`. See :doc:`unittest` to learn about about using + :mod:`logot` with other testing frameworks. + + +Why test logging? 🤔 +-------------------- + +Good logging ensures your application is debuggable at runtime, but why bother actually *testing* your logs? After +all... surely the worst that can happen is your logs are a bit *wonky*? 🥴 + +Sometimes, testing logs is the only *reasonable* way to known your code has actually run correctly! This is particularly +the case in *threaded* or *asynchronous* applications where work is carried out at unpredictable times by background +workers. + +For example, imagine the following code running in a thread: + +.. code:: python + + def poll_daemon(app: App) -> None: + while not app.stopping: + sleep(app.poll_interval) + logger.debug("Poll started") + try: + app.data = app.get("http://is-everything-ok.com/") + except HTTPError: + logger.exception("Poll error") + else: + logger.debug("Poll finished") + +.. note:: + + It's certainly *possible* to rewrite this code in a way that can be tested without :mod:`logot`, but that often makes + the code less clear or more verbose. For complex threaded or asynchronous applications, this can quickly become + burdensome. + 👎 + +Testing this code with :mod:`logot` is easy! + +.. code:: python + + from logot import Logot, logged + + def test_poll_daemon(logot: Logot) -> None: + app.start_poll() + for _ in range(3): + logot.wait_for(logged.info("Poll started")) + logot.wait_for(logged.info("Poll finished")) + + +Testing threaded code +--------------------- + +Use :meth:`Logot.wait_for` to pause your test until the expected logs arrive or the timeout expires: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for(logged.info("App started")) + +.. note:: + + Use the ``timeout`` argument to :meth:`Logot.wait_for` to configure how long to wait before the test fails. This can + be configured globally with the ``timeout`` argument to :class:`Logot`, defaulting to :attr:`Logot.DEFAULT_TIMEOUT`. + +.. seealso:: + + See :doc:`logged` for examples of how to wait for logs that may arrive in an unpredictable order. + + +Testing asynchronous code +------------------------- + +Use :meth:`Logot.await_for` to pause your test until the expected logs arrive or the timeout expires: + +.. code:: python + + from logot import Logot, logged + + async def test_my_app(logot: Logot) -> None: + app.start() + await logot.await_for(logged.info("App started")) + +.. note:: + + Use the ``timeout`` argument to :meth:`Logot.await_for` to configure how long to wait before the test fails. This can + be configured globally with the ``timeout`` argument to :class:`Logot`, defaulting to :attr:`Logot.DEFAULT_TIMEOUT`. + +.. seealso:: + + See :doc:`logged` for examples of how to wait for logs that may arrive in an unpredictable order. + + +Testing synchronous code +------------------------ + +Use :meth:`Logot.assert_logged` to fail *immediately* if the expected logs have not arrived: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.run() + logot.assert_logged(logged.info("App started")) + +.. note:: + + You can also use :meth:`Logot.wait_for` to test for expected logs, but since this only fails after a ``timeout``, + using :meth:`Logot.assert_logged` will give more immediate feedback if your test fails. + +.. seealso:: + + Use :meth:`Logot.assert_not_logged` to fail *immediately* if the expected logs *do* arrive. + + +Further reading +--------------- + +Learn more about :mod:`logot` with the following guides: .. toctree:: - :caption: Contents :hidden: :maxdepth: 1 self + + +.. toctree:: + :maxdepth: 1 + + match + logged + pytest + unittest + api diff --git a/docs/logged.rst b/docs/logged.rst new file mode 100644 index 00000000..fbaa05bb --- /dev/null +++ b/docs/logged.rst @@ -0,0 +1,84 @@ +Log pattern matching +==================== + +.. currentmodule:: logot + +:mod:`logot` makes it easy to match logs that may arrive in an unpredictable order. This is especially useful in +*threaded* or *asynchronous* applications! + +Compose your :mod:`logot.logged` calls with special *log pattern operators*: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for( + # Wait for the app to start... + logged.info("App started") + # ...then wait for the app to stop *or* crash! + >> ( + logged.info("App stopped") + | logged.error("App crashed!") + ) + ) + +.. note:: + + Log pattern operators are *infinitely* composable! Use ``()`` brackets when needed to define complex log patterns. + + +Available operators +------------------- + +Sequential logs +~~~~~~~~~~~~~~~ + +Use the ``>>`` operator to wait for logs that must arrive in a *sequential* order: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for( + logged.info("App started") + >> logged.info("App stopped") + ) + + +Parallel logs +~~~~~~~~~~~~~ + +Use the ``&`` operator to wait for logs that must arrive in *any* order: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + other_app.start() + logot.wait_for( + logged.info("App started") + & logged.info("Other app started") + ) + + +Any logs +~~~~~~~~ + +Use the ``|`` operator to wait for *any* matching log pattern: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for( + logged.info("App stopped") + | logged.error("App crashed!") + ) diff --git a/docs/match.rst b/docs/match.rst new file mode 100644 index 00000000..75a66b63 --- /dev/null +++ b/docs/match.rst @@ -0,0 +1,45 @@ +Log message matching +==================== + +.. currentmodule:: logot + +:mod:`logot` makes it easy to match log messages using ``%``-style placeholders: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for(logged.info("App %s")) + +In this case, the ``%s`` placeholder will match *any* string! + + +Available placeholders +---------------------- + +The following placeholders are available, each corresponding to a formatting option available in the stdlib +:mod:`logging` module: + +=========== =========================================================================================================== +Placeholder Matches +=========== =========================================================================================================== +``%d`` Signed integer decimal. +``%i`` Signed integer decimal. +``%o`` Signed octal value. +``%u`` Signed integer decimal. +``%x`` Signed hexadecimal (lowercase). +``%X`` Signed hexadecimal (uppercase). +``%e`` Floating point exponential format (lowercase). +``%E`` Floating point exponential format (uppercase). +``%f`` Floating point decimal format (lowercase). +``%F`` Floating point decimal format (uppercase). +``%g`` Floating point format. Uses lowercase exponential format if exponent is less than -4 or not less than precision, decimal format otherwise. +``%G`` Floating point format. Uses uppercase exponential format if exponent is less than -4 or not less than precision, decimal format otherwise. +``%c`` Single character. +``%r`` Any string (non-greedy). +``%s`` Any string (non-greedy). +``%a`` Any string (non-greedy). +``%%`` Escape sequence, results in a ``%`` character in the result. +=========== =========================================================================================================== diff --git a/docs/pytest.rst b/docs/pytest.rst new file mode 100644 index 00000000..6684f4b3 --- /dev/null +++ b/docs/pytest.rst @@ -0,0 +1,42 @@ +Using with :mod:`pytest` +======================== + +.. currentmodule:: logot + +:mod:`logot` includes a :mod:`pytest` plugin. Just use the ``logot`` fixture in your tests: + +.. code:: python + + from logot import Logot, logged + + def test_my_app(logot: Logot) -> None: + app.start() + logot.wait_for(logged.info("App started")) + +.. note:: + + The ``logot`` fixture is configured with default settings and captures all logs in the root logger. + +.. seealso:: + + See :class:`Logot` API reference for default settings. + + +Customizing the ``logot`` fixture +--------------------------------- + +To customize the ``logot`` fixure, simply override it in your own ``conftest.py``: + +.. code:: python + + import pytest + from logot import Logot, logged + + @pytest.fixture() + def logot(): + with Logot(timeout=30.0).capturing(level=logging.WARNING) as logot: + yield logot + +.. seealso:: + + See :class:`Logot` and :meth:`Logot.capturing` API reference. diff --git a/docs/unittest.rst b/docs/unittest.rst new file mode 100644 index 00000000..229e3f10 --- /dev/null +++ b/docs/unittest.rst @@ -0,0 +1,22 @@ +Using with :mod:`unittest` +========================== + +.. currentmodule:: logot + +:mod:`logot` is compatible with any testing framework, including :mod:`unittest`: + +.. code:: python + + import unittest + from logot import Logot, logged + + class MyAppTest(unittest.TestCase): + + def test_my_app(self) -> None: + with Logot().capture() as logot: + app.start() + logot.wait_for(logged.info("App started")) + +.. seealso:: + + See :class:`Logot` and :meth:`Logot.capturing` API reference. diff --git a/logot/_logged.py b/logot/_logged.py index 24ef0c7c..afa2a802 100644 --- a/logot/_logged.py +++ b/logot/_logged.py @@ -8,6 +8,23 @@ class Logged(ABC): + """ + A :doc:`log pattern ` passed to :meth:`Logot.wait_for`, :meth:`Logot.await_for` and similar APIs. + + .. important:: + + :class:`Logged` instances are immutable and can be reused between tests. + + .. note:: + + This is an abstract class and cannot be instantiated. Use the helpers in :mod:`logot.logged` to create log + patterns. + + .. seealso:: + + See :doc:`logged` usage guide. + """ + __slots__ = () def __rshift__(self, log: Logged) -> Logged: @@ -40,26 +57,57 @@ def _str(self, *, indent: str) -> str: def log(level: int | str, msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at the given ``level`` with the given ``msg``. + + :param level: A log level (e.g. ``logging.DEBUG``) or string name (e.g. ``"DEBUG"``). + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(validate_levelno(level), msg) def debug(msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at ``DEBUG`` level with the given ``msg``. + + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(logging.DEBUG, msg) def info(msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at ``INFO`` level with the given ``msg``. + + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(logging.INFO, msg) def warning(msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at ``WARNING`` level with the given ``msg``. + + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(logging.WARNING, msg) def error(msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at ``ERROR`` level with the given ``msg``. + + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(logging.ERROR, msg) def critical(msg: str) -> Logged: + """ + Creates a :doc:`log pattern ` representing a log record at ``CRITICAL`` level with the given ``msg``. + + :param msg: A log :doc:`message pattern `. + """ return _LogRecordLogged(logging.CRITICAL, msg) diff --git a/logot/_logot.py b/logot/_logot.py index 06124966..7db9b292 100644 --- a/logot/_logot.py +++ b/logot/_logot.py @@ -16,11 +16,39 @@ class Logot: + """ + The main :mod:`logot` API for capturing and waiting for logs. + + .. seealso:: + + See :doc:`index` usage guide. + + :param timeout: The default timeout (in seconds) for calls to :meth:`wait_for` and :meth:`await_for`. Defaults to + :attr:`DEFAULT_TIMEOUT`. + """ + __slots__ = ("_timeout", "_lock", "_seen_records", "_queue", "_waiter") DEFAULT_LEVEL: ClassVar[int | str] = logging.NOTSET + """ + The default ``level`` used by :meth:`capturing`. + + This is ``logging.NOTSET``, specifying that all logs are captured. + """ + DEFAULT_LOGGER: ClassVar[logging.Logger | str | None] = None + """ + The default ``logger`` used by :meth:`capturing`. + + This is the root logger. + """ + DEFAULT_TIMEOUT: ClassVar[float] = 3.0 + """ + The default ``timeout`` used by :meth:`wait_for` and :meth:`await_for`. + + This is 3 seconds. + """ def __init__( self, @@ -39,21 +67,51 @@ def capturing( level: int | str = DEFAULT_LEVEL, logger: logging.Logger | str | None = DEFAULT_LOGGER, ) -> AbstractContextManager[Logot]: + """ + Captures logs emitted at the given ``level`` by the given ``logger`` for the duration of the context. + + If the given ``logger`` level is less verbose than the requested ``level``, it will be temporarily adjusted to + the requested ``level`` for the duration of the context. + + :param level: A log level (e.g. ``logging.DEBUG``) or string name (e.g. ``"DEBUG"``). Defaults to + ``logging.NOTSET``, specifying that all logs are captured. + :param logger: A logger or logger name to capture logs from. Defaults to the root logger. + """ levelno = validate_levelno(level) logger = validate_logger(logger) return _Capturing(self, _Handler(self, levelno=levelno), logger=logger) def assert_logged(self, log: Logged) -> None: + """ + Fails *immediately* if the expected ``log`` pattern has not arrived. + + :param log: The expected :doc:`log pattern `. + :raises AssertionError: If the expected ``log`` pattern has not arrived. + """ reduced_log = self._reduce(log) if reduced_log is not None: raise AssertionError(f"Not logged:\n\n{reduced_log}") def assert_not_logged(self, log: Logged) -> None: + """ + Fails *immediately* if the expected ``log`` pattern **has** arrived. + + :param log: The expected :doc:`log pattern `. + :raises AssertionError: If the expected ``log`` pattern **has** arrived. + """ reduced_log = self._reduce(log) if reduced_log is None: raise AssertionError(f"Logged:\n\n{log}") def wait_for(self, log: Logged, *, timeout: float | None = None) -> None: + """ + Waits for the expected ``log`` pattern to arrive or the ``timeout`` to expire. + + :param log: The expected :doc:`log pattern `. + :param timeout: How long to wait (in seconds) before failing the test. Defaults to the ``timeout`` passed to + :class:`Logot`. + :raises AssertionError: If the expected ``log`` pattern does not arrive within ``timeout`` seconds. + """ waiter = self._open_waiter(log, SyncWaiter, timeout=timeout) try: waiter.wait() @@ -61,6 +119,14 @@ def wait_for(self, log: Logged, *, timeout: float | None = None) -> None: self._close_waiter(waiter) async def await_for(self, log: Logged, *, timeout: float | None = None) -> None: + """ + Waits *asynchronously* for the expected ``log`` pattern to arrive or the ``timeout`` to expire. + + :param log: The expected :doc:`log pattern `. + :param timeout: How long to wait (in seconds) before failing the test. Defaults to the ``timeout`` passed to + :class:`Logot`. + :raises AssertionError: If the expected ``log`` pattern does not arrive within ``timeout`` seconds. + """ waiter = self._open_waiter(log, AsyncWaiter, timeout=timeout) try: await waiter.wait() diff --git a/pyproject.toml b/pyproject.toml index 863ac4d6..95a0b557 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [tool.poetry] name = "logot" -version = "0.0.1a5" +version = "0.1.0" description = "Log-based testing" authors = ["Dave Hall "] license = "MIT"