Please make async tests capture logs! 🙏

[kstech-roadie]

TL;DR: Only sync tests capture logs, not async.

Desired behavior: Async captures logs too.

Impact: Logs are critical test data. However this is the only solution I can find in the entire Python ecosystem (other than hand-rolling something) that runs tests using cooperative concurrency. Therefore, I'm stuck selecting between two critical needs.

Bottom line: Capturing logs would be a huge win for this plugin!

Repro:

from logging import getLogger

import pytest

log = getLogger(__name__)

@pytest.mark.asyncio_cooperative
async def test_foo():
    log.info("foo")

@pytest.mark.asyncio_cooperative
async def test_bar():
    log.info("bar")

@pytest.mark.asyncio_cooperative
async def test_baz():
    log.info("baz")

@pytest.mark.asyncio_cooperative
async def test_boop():
    log.info("boop")

def test_zap():
    log.info("zap")

pytest.ini

[pytest]
addopts=-rA
log_level=INFO
log_cli=true
log_cli_level=INFO

command

poetry run pytest -vv

output

============================================================================================================================ test session starts =============================================================================================================================
platform darwin -- Python 3.11.1, pytest-7.4.0, pluggy-1.2.0 -- /Users/kstech/Library/Caches/pypoetry/virtualenvs/simple-py-async-coop-logging-test-b8ZNhF3X-py3.11/bin/python
cachedir: .pytest_cache
rootdir: /Volumes/workspace/tmp/simple-py-async-coop-logging-test
configfile: pytest.ini
plugins: asyncio-cooperative-0.30.0
collected 5 items

test_foo.py::test_bar PASSED                                                                                                                                                                                                                                           [ 20%]
test_foo.py::test_baz PASSED                                                                                                                                                                                                                                           [ 40%]
test_foo.py::test_boop PASSED                                                                                                                                                                                                                                          [ 60%]
test_foo.py::test_foo PASSED                                                                                                                                                                                                                                           [ 80%]
test_foo.py::test_zap PASSED                                                                                                                                                                                                                                           [100%]

=================================================================================================================================== PASSES ===================================================================================================================================
__________________________________________________________________________________________________________________________________ test_zap __________________________________________________________________________________________________________________________________
----------------------------------------------------------------------------------------------------------------------------- Captured log call ------------------------------------------------------------------------------------------------------------------------------
INFO     test_foo:test_foo.py:26 zap
========================================================================================================================== short test summary info ===========================================================================================================================
PASSED test_foo.py::test_bar
PASSED test_foo.py::test_baz
PASSED test_foo.py::test_boop
PASSED test_foo.py::test_foo
PASSED test_foo.py::test_zap
============================================================================================================================= 5 passed in 0.02s ==============================================================================================================================

[kstech-roadie]

I am finding my project using this module is beset with logging issues. For one, the above. The module eliminates pytest's log capturing mechanism. So then I started developing a workaround using structlog, which I nearly have working the way I'd like. Now the 0.30->0.31 update regressed my ability to bind contextvars into my pytest scopes.

I appreciate that this module is a bit of magic, so I'm feeling quite patient with these issues. In fact for my purposes now I'll likely just pin the 0.30 release and call it good enough. That said, I think a coherent approach to logging is a critical need for this to be a serious testing tool.

Thanks for taking the time to hear my concerns.

[kstech-roadie]

I have forked the repo from the 0.30 release here and applied several changes and fixes to get my structlog solution working.

• Honor session -> package -> module -> class -> function scope prioritization for fixtures from pytest docs
• Honor autouse prioritization from same docs
• Pass fixture kwargs in several places where they could appear (probably need more, this is just what I ran into)
• Cache module scoped fixtures at module scope instead of session scope

At this time, these fixes against the 0.30 release appear to allow a lightweight logging solution with structlog that goes roughly:

• structlog.configure() and bind session context vars in pytest_configure hook
• autouse module fixture in conftest that binds the module id
• autouse func fixture in conftest that binds module id + test id

Obviously this only works for structlog and standard logs are still dropped.

I'm happy to work directly on this project, but I would need to look into the 0.31 update in more detail. I'm not sure if those changes are compatible with my approach.

BTW, structlog seems like a natural fit here, given that concurrent tests will have interleaved log lines, and structlog gives you the ability to bind id's at each scope to disambiguate them. :)

[gerlero]

• Honor session -> package -> module -> class -> function scope prioritization for fixtures from pytest docs
• Honor autouse prioritization from same docs
• Pass fixture kwargs in several places where they could appear (probably need more, this is just what I ran into)
• Cache module scoped fixtures at module scope instead of session scope

I'm very interested in these, but I need 0.31 because I want concurrent fixtures (#37). Can you open PRs against this repo?

As for the logging issue, is there a possible solution without structlog? I ask because I'm not familiar with that package. I guess interleaved logs might be a problem for some but to me it seems they should be expected with anything that runs concurrently.

[kstech-roadie]

• Honor session -> package -> module -> class -> function scope prioritization for fixtures from pytest docs
• Honor autouse prioritization from same docs
• Pass fixture kwargs in several places where they could appear (probably need more, this is just what I ran into)
• Cache module scoped fixtures at module scope instead of session scope

I'm very interested in these, but I need 0.31 because I want concurrent fixtures (#37). Can you open PRs against this repo?

As for the logging issue, is there a possible solution without structlog? I ask because I'm not familiar with that package. I guess interleaved logs might be a problem for some but to me it seems they should be expected with anything that runs concurrently.

Interleaved logs per se are fine and a natural outcome of concurrency. My main interest is in tracing log lines to the tests that produced them. structlog comes with functionality that binds contextvars within a task or thread, and imo is a natural fit for binding pytest's ids to log lines, which disambiguates and provides traceability.

In order to successfully do this I need certain synchronization points, hence my use of 0.30 and some of the updates around fixture ordering.

Do you think it makes sense to have scope ordering and autouse prioritization but within those modalities (i.e. multiple fixtures which all meet the same criteria, e.g. 2 fixtures are both autouse and module scoped, say), concurrency can be used with no guaranteed order?

Such an implementation could make sense, however it may need to be optional for users that don't care about such things and simply want all their fixtures gathered up and run concurrently regardless of scope.

[gerlero]

Interleaved logs per se are fine and a natural outcome of concurrency. My main interest is in tracing log lines to the tests that produced them. structlog comes with functionality that binds contextvars within a task or thread, and imo is a natural fit for binding pytest's ids to log lines, which disambiguates and provides traceability.

Is there a way to capture stdout with structlog so that users don't have to change the code/tests? If so, I think a case can be made for adding it as a dependency and using it to handle logging with this plugin.

Do you think it makes sense to have scope ordering and autouse prioritization but within those modalities (i.e. multiple fixtures which all meet the same criteria, e.g. 2 fixtures are both autouse and module scoped, say), concurrency can be used with no guaranteed order?

Oh, thanks; hadn't really thought that through. Yes, with what I need and have in mind I'm against that kind of implicit synchronization.

However, I have to say there seems to be some kind of implicit synchronization already in the package when dealing with fixtures of fixtures, which is currently asserted in tests (I mention it in #37 as my excuse for not making fixtures of fixtures concurrent there too). If you ask me, I'd say that should be a a bug too. OTOH, I'm not using fixtures of fixtures nor different scoped fixtures that don't depend on each other right now, so it won't really affect me. I'd like to know @willemt's thought on this...

Such an implementation could make sense, however it may need to be optional for users that don't care about such things and simply want all their fixtures gathered up and run concurrently regardless of scope.

Yeah, you're right; and given what I said above I don't think I need it and agree with it not being the default. To me it makes sense to roughly follow pytest's ordering when starting the tasks, but then run everything concurrently as far as explicit dependencies (i.e., fixtures) allow.

[gerlero]

BTW, for the the other two changes:

• Pass fixture kwargs in several places where they could appear (probably need more, this is just what I ran into)

This one fixes #31, right? (or at least, makes it better?)

• Cache module scoped fixtures at module scope instead of session scope

This one clear-cut reads like a bug that needs to be fixed.

[kstech-roadie]

given that pytest is a framework, lots of decisions will be made for users. imho the ideal is to have optionality on as many of these synchronization points as possible. the fixture dependency tree can be the standard synchronous and blocking, fully collapsed into a flat gather, or anything in between. thats the ideal i think. neither of our use cases are anything to be for or against, just different and probably possible to support.

Yes and yes to your second set of questions, though the kwargs fix would likely need to be extended given the 4 or so flavors of fixture functions that are supported.

[kstech-roadie]

Is there a way to capture stdout with structlog so that users don't have to change the code/tests? If so, I think a case can be made for adding it as a dependency and using it to handle logging with this plugin.

writing to stdout is default behavior for structlog, but its not the handler/sink that makes the difference here, its the way you hook it up using fixtures and hooks. i have a solution implemented that is invisible to the test writer using the forked repo i linked, conftest, pytest_configure hook, and autouse fixtures for the scopes where i want to hook and bind pytest id's into my log lines. everything logs neatly to the handler/sink of your choice, fully tagged up with a run_id, module_id and test_id for every api req/res pair and all the other logging. this is only possible because i pinned at 0.30 and implemented even more ordering guarantees on fixture fulfillment. this is okay for me because i encapsulated all of my automation into a separate layer / separate dependency and only need 1 fixture to do everything. 1 fixture to declare my setup state, and then many concurrent tests against that state.

[kstech-roadie]

as written i think our updates to this lib are incompatible. but i could see them coexisting and made user configurable.

[willemt]

Thank you very much for this issue and comments.

The main issue is that logging in pytest is written as a plugin via pluggy which is synchronous.

I believe that the best path forward is using an "asynchronous pluggy" then re-implementing the synchronous logging plugin bits inside this "asynchronous pluggy".

I will look into this now.

[gerlero]

the fixture dependency tree can be the standard synchronous and blocking, fully collapsed into a flat gather, or anything in between. thats the ideal i think. neither of our use cases are anything to be for or against, just different and probably possible to support.

@kstech-roadie Agree. Although I think I can make a case for having fully concurrent fixtures (at least by default), given that (a) that's how this plugin runs the tests and (b) it is not difficult to force a definite run order via fixture dependencies and synchronization primitives when that is needed. But I agree that it might or might not be what you need.

I will look into this now.

@willemt thanks!

[kstech-roadie]

@willemt Seems accurate to me. @gerlero thank you for the discussion. :)

I'll be watching any developments here closely.

[tmandrysz]

Hello @willemt. Is there any chance that you have a look at this logging issue? I'm using asyncio-cooperative in one of my projects, the only thing that I'm missing now is to be able to capture the logs.