Add __repr__() to StructuredLogCapture class.

[olii]

This is to print the content of the captured log events when the test fails. To my knowledge, there is no disadvantage related to this change.

When the test fails it prints the value of the fixture. When the fixture is an object the default representation is used:

======================================================================================================================================================================= test session starts ========================================================================================================================================================================
platform linux -- Python 3.9.2, pytest-6.2.2, py-1.10.0, pluggy-0.13.1
rootdir: /foo
plugins: cov-2.11.1, structlog-0.3
collected 2 items                                                                                                                                                                                                                                                                                                                                                  

tests/integration/logging_test.py .F                                                                                                                                                                                                                                                                                                                         [100%]

============================================================================================================================================================================= FAILURES =============================================================================================================================================================================
___________________________________________________________________________________________________________________________________________________________________ test_logger_works_correctly ____________________________________________________________________________________________________________________________________________________________________

log = <pytest_structlog.StructuredLogCapture object at 0x7f5940e59e50>   <--- Notice this.

    def test_logger_works_correctly(log):
        hmil_log.error('a unique error message')
        hmil_log.warning('a unique warning message')

>       assert False
E       assert False

tests/integration/logging_test.py:32: AssertionError

This PR changes the output to:

======================================================================================================================================================================= test session starts ========================================================================================================================================================================
platform linux -- Python 3.9.2, pytest-6.2.2, py-1.10.0, pluggy-0.13.1
rootdir: /foo
plugins: cov-2.11.1, structlog-0.3
collected 2 items                                                                                                                                                                                                                                                                                                                                                  

tests/integration/logging_test.py .F                                                                                                                                                                                                                                                                                                                         [100%]

============================================================================================================================================================================= FAILURES =============================================================================================================================================================================
___________________________________________________________________________________________________________________________________________________________________ test_logger_works_correctly ____________________________________________________________________________________________________________________________________________________________________

log = <StructuredLogCapture with [{'username': 'hmil', 'event': 'a unique error message', 'level': 'error'}, {'username': 'hmil', 'event': 'a unique warning message', 'level': 'warning'}]>

    def test_logger_works_correctly(log):
        hmil_log.error('a unique error message')
        hmil_log.warning('a unique warning message')

>       assert False
E       assert False

tests/integration/logging_test.py:29: AssertionError

[wimglenn]

Hi @olii, interesting idea. What is the format of your assertion? When I'm using log.has(...) method, the output is a bit too verbose.

Lib:

# eg.py
import structlog

log = structlog.get_logger()

def f():
    log.info("hello", k1="v1", k2="v2")

Test:

from eg import f

def test_f(log):
    f()
    assert log.has("hello", k3="v3")

Output

log = <StructuredLogCapture with [{'k1': 'v1', 'k2': 'v2', 'event': 'hello', 'level': 'info'}]>

    def test_f(log):
        f()
>       assert log.has("hello", k3="v3")
E       AssertionError: assert False
E        +  where False = <bound method StructuredLogCapture.has of <StructuredLogCapture with [{'k1': 'v1', 'k2': 'v2', 'event': 'hello', 'level': 'info'}]>>('hello', k3='v3')
E        +    where <bound method StructuredLogCapture.has of <StructuredLogCapture with [{'k1': 'v1', 'k2': 'v2', 'event': 'hello', 'level': 'info'}]>> = <StructuredLogCapture with [{'k1': 'v1', 'k2': 'v2', 'event': 'hello', 'level': 'info'}]>.has

test_eg.py:5: AssertionError

The captured events are represented four times, it's a bit much. I wonder if we can do better here...

[wimglenn]

By the way, the reason I've procrastinated on doing something here is there might be a richer assertion hook available for use in a subsequent version of pytest ... https://github.com/pytest-dev/pytest/issues/5535

[olii]

Good observation. My test was very synthetic, e.g.:

def test_f(log):
    # Do some logging.
    structlogger.info("hello", k1="v1", k2="v2")

    # Make the test always failing and see the console how the `log` is rendered.
    assert False

I played with this and studied the low-level details of Pytest AST rewriter and I come up with this: https://gist.github.com/olii/8e8a134cd53b8abd0ba0b120afb542ec

pytest tests/
================================================================================================== test session starts ==================================================================================================
platform linux -- Python 3.9.2, pytest-6.2.2, py-1.10.0, pluggy-0.13.1
rootdir: /home/olii/Desktop/work/experimental/pytest-structlog
plugins: structlog-0.3
collected 1 item                                                                                                                                                                                                        

tests/test_log.py F                                                                                                                                                                                               [100%]

======================================================================================================= FAILURES ========================================================================================================
_______________________________________________________________________________ test_structuredlogcapture_returns_correct_representation ________________________________________________________________________________

log = <StructuredLogCapture with [{'event': 'a', 'level': 'info'}]>

    def test_structuredlogcapture_returns_correct_representation(log):
        logger.info("a")

>       assert log.has('', event='b', level="info")
E       AssertionError: assert False
E        +  where False = <bound method StructuredLogCapture.has of <StructuredLogCapture [1 log(s)]>>('', event='b', level='info')
E        +    where <bound method StructuredLogCapture.has of <StructuredLogCapture [1 log(s)]>> = <StructuredLogCapture [1 log(s)]>.has

tests/test_log.py:12: AssertionError
================================================================================================ short test summary info ================================================================================================
FAILED tests/test_log.py::test_structuredlogcapture_returns_correct_representation - AssertionError: assert False
=================================================================================================== 1 failed in 0.02s ===================================================================================================

[wimglenn]

Rather than using __repr__ here, I think a cleaner approach will be for the log fixture to remember what it has been compared against, and then print some reporting during fixture teardown in case of a failed test (i.e. after the yield statement in the log fixture impl).

Advantages:

• will work with both log.has and the direct comparisons against log.events
• verbosity level can be configurable by user
• ability to look for similar events (e.g. context or event) and provide a diff, rather than just dumping out every event (of which there might be very many)

[olii]

I totally agree with you. With the current pytest I was unable to find a viable solution.

[wimglenn]

@olii I've tried the teardown idea in v0.4

For this test file:

# test_something.py
import structlog

logger = structlog.get_logger()

def test_one(log):
    logger.debug("ok")
    logger.info("yeah", k=1)
    assert log.has("no")

def test_two(log):
    logger.info("nah", k=2)
    assert log.has("nah", k=3)

failed tests will now produce a dedicated "Captured structlog call" section in the report, with events dumped out. It looks something like this:

plugins: structlog-0.4
collected 2 items

test_something.py FF                                                     [100%]

=================================== FAILURES ===================================
___________________________________ test_one ___________________________________

log = <pytest_structlog.StructuredLogCapture object at 0x7fffe9881ac0>

    def test_one(log):
        logger.debug("ok")
        logger.info("yeah", k=1)
>       assert log.has("no")
E       AssertionError: assert False

test_something.py:10: AssertionError
--------------------------- Captured structlog call ----------------------------
{'event': 'ok', 'level': 'debug'}
{'k': 1, 'event': 'yeah', 'level': 'info'}
___________________________________ test_two ___________________________________

log = <pytest_structlog.StructuredLogCapture object at 0x7fffe9881130>

    def test_two(log):
        logger.info("nah", k=2)
>       assert log.has("nah", k=3)
E       AssertionError: assert False

test_something.py:15: AssertionError
--------------------------- Captured structlog call ----------------------------
{'k': 2, 'event': 'nah', 'level': 'info'}
=========================== short test summary info ============================
FAILED test_something.py::test_one - AssertionError: assert False
FAILED test_something.py::test_two - AssertionError: assert False
============================== 2 failed in 0.02s ===============================

I think this will be more flexible and extensible than overriding __repr__ going forward, and should address the basic need just as well (print the content of the captured log events when a test fails).