ASGI app misses coverage lines after awaiting async sqlalchemy code

[daviskirk]

Describe the bug

This may be a very specialized problem, but since it concerns very widely used libraries I thought it would be helpful to report:

Within an ASGI app (the example uses starlette here), using the new async/await engine in sqlalchemy results in any lines AFTER usage of the database engine not being recognized in coverage.

To Reproduce

How can we reproduce the problem? Please be specific. Don't just link to a failing CI job. Answer the questions below:

What version of Python are you using?:

3.8.5 (virtual environment using conda)

What version of coverage.py are you using? The output of coverage debug sys is helpful.

-- sys -------------------------------------------------------
                        version: 5.3
                       coverage: /home/user/env/lib/python3.8/site-packages/coverage/__init__.py
                         tracer: -none-
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
              configs_attempted: .coveragerc
                                 setup.cfg
                                 tox.ini
                                 pyproject.toml
                   configs_read: /home/backend/pyproject.toml
                    config_file: /home/backend/pyproject.toml
                config_contents: b'[tool.coverage.report]\nshow_missing = true\n'
                      data_file: -none-
                         python: 3.8.5 (default, Sep  4 2020, 07:30:14) [GCC 7.3.0]
                       platform: Linux-5.4.0-56-generic-x86_64-with-glibc2.10
                 implementation: CPython
                     executable: /home/user/env/bin/python
                   def_encoding: utf-8
                    fs_encoding: utf-8
                            pid: 2488889
                            cwd: /home/user/backend
                           path: /home/user/env/bin
                                 /home/user/env/lib/python38.zip
                                 /home/user/env/lib/python3.8
                                 /home/user/env/lib/python3.8/lib-dynload
                                 /home/user/.local/lib/python3.8/site-packages
                                 /home/user/env/lib/python3.8/site-packages
                    environment: CONDA_PYTHON_EXE = /home/user/anaconda/bin/python
                   command_line: /home/user/env/bin/coverage debug sys
                sqlite3_version: 2.6.0
         sqlite3_sqlite_version: 3.33.0
             sqlite3_temp_store: 0
        sqlite3_compile_options: COMPILER=gcc-7.3.0
                                 ENABLE_COLUMN_METADATA
                                 ENABLE_DBSTAT_VTAB
                                 ENABLE_FTS3
                                 ENABLE_FTS3_TOKENIZER
                                 ENABLE_FTS4
                                 ENABLE_FTS5
                                 ENABLE_GEOPOLY
                                 ENABLE_JSON1
                                 ENABLE_RTREE
                                 ENABLE_UNLOCK_NOTIFY
                                 MAX_DEFAULT_PAGE_SIZE=32768
                                 MAX_EXPR_DEPTH=10000
                                 MAX_VARIABLE_NUMBER=250000
                                 SECURE_DELETE
                                 THREADSAFE=1

What versions of what packages do you have installed? The output of pip freeze is helpful.

starlette==0.13.6
sqlalchemy==0.14.0b1
coverage==5.3

What code are you running? Give us a specific commit of a specific repo that we can check out.

Given the packages above, the code should run "as is":

https://gist.github.com/daviskirk/7e8495ca5b8150f9002c5bc80630fa5a#file-starlette_async_sqlalchemy_coverage_bug-py

What commands did you run?

https://gist.github.com/daviskirk/7e8495ca5b8150f9002c5bc80630fa5a#file-run-sh

Expected behavior

I expect all lines to be covered, since all lines were run (acording to the output (see the printed result) and setting breakpoints).

Instead, the lines following the database operations are skipped:

Additional context

• Note that the sqlalchemy version is in beta, but since it is very widely used I expect this to be a problem for many people.
• Sqlalchemy uses the "greenlets" library to pass through context. I can guess that this might have something to do with the missing coverage? However, normal applications (mine included) using starlette or fastapi (or most of the other asgi frameworks), can't switch to the --coverage "greenlet" version since all wsgi endpoints run in a thread (and then none of those are covered).
• I have no problem concluding that this isn't coverages problem ;), if that is indeed the case. But I wanted to document it for anyone else running into the issue (or perhaps a solution if one does exist).

[frnkvieira]

SQLAlchemy 1.4 uses greenlets and FastAPI uses threads when using synchronous routes.
The problem is that we can't mix concurrency models in coverage as stated in #1012
@daviskirk I avoided the problem by going full blow async (to prevent using threads at all) which is the best option in my opinion.

[daviskirk]

Yes, that is a possibility, but there will be many applications that cannot go full async because they depend on sync code.
For example, anything that uses celery. #1012 is indeed the correct issue, I fear that sqlachemy will trigger this problem for many more projects than previous projects that use greenlets because of it's reach and scope.
In any case, if the scope itself isn't enough to have this issue around for people to find that are transitioning to async sqlalchemy I'm find with closing this as #1012 is the actual problem.

[Kludex]

@daviskirk I've tested with your snippet, and if I add the flag --concurrency=gevent I do get 100% coverage.

EDIT: Works with greenlet as well.

[daviskirk]

@daviskirk I've tested with your snippet, and if I add the flag --concurrency=gevent I do get 100% coverage.

@Kludex Sorry, the snippet only showed the async route to make clear that it wasn't covered by the default concurrency model.
I updated the snippet to show the problem more clearly (added default, gevent and greenlet).

As #1082 (comment) mentions going full async or full thread is an option, but mixing is not possible any more which I guess might just be how it is (it might not be feasible to really fix this), but I do know that starlette and fastapi advertise the "mixing" of concurrency models a lot which might be problematic.

[Kludex]

@daviskirk I see. Thank you for the clarification!

I guess if there's a mix, maybe appending the coverage reports will be the way to go. 🤔

[dgilmanTORQATA]

I'm also testing against a FastAPI project with a mix of async routes, async SQLAlchemy and synchronous FastAPI dependencies. Instructing coverage to use concurrency = gevent works in async routes that use SQLAlchemy but breaks coverage elsewhere in places like the FastAPI dependencies.

Adding a voodoo await asyncio.sleep(0) right after the last line that coverage picks up on (so right after the line that awaits on a SQLAlchemy coroutine) lets coverage get back up to speed and correctly detect coverage on the following lines.

[nedbat]

Thanks for this example. If I pin starlette==0.13.6, I get the same results you did. I'm re-opening this issue, because I don't yet understand how #1012 relates, since you aren't trying to use multiple concurrency settings here.

I also don't understand why you have Route('/run2', run), don't you want to route /run2 to the run2 function?

Sorry if I'm not understanding parts of this.

[Kludex]

@nedbat I think it was a typo. I've fixed the snippet here: https://github.com/Kludex/coverage-issue

[nedbat]

OK, thanks. I made a few more fixes to the example:

diff --git a/bug.py b/bug.py
index be18d4c..7d9ef71 100644
--- a/bug.py
+++ b/bug.py
@@ -20,7 +20,7 @@ async def run(*args, **kwargs):
     return JSONResponse(records)
 
 def run2(*args, **kwargs):
-    print('start')
+    print('start2')
     with engine2.begin() as conn:
         result = conn.execute(sa.text("select 1"))
         records = dict(result.mappings().first())
diff --git a/run.sh b/run.sh
index 2561747..30587f3 100755
--- a/run.sh
+++ b/run.sh
@@ -1,6 +1,6 @@
 docker-compose up -d
 
-echo "runing with default concurrency"
+echo "running with default concurrency"
 coverage run bug.py
 coverage report -m
 coverage html
@@ -11,6 +11,6 @@ coverage report -m
 coverage html -d htmlcov_greenlet
 
 echo "running with gevent"
-coverage run --concurrency greenlet bug.py
+coverage run --concurrency gevent bug.py
 coverage report -m
-coverage html -d htmlcov_greenlet
+coverage html -d htmlcov_gevent

Can you help me out with what I am seeing here? I get this result:

coverage-issue-1082_postgres_1 is up-to-date
running with default concurrency
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      3    90%   17-20
--------------------------------------
TOTAL       29      3    90%
Wrote HTML report to htmlcov/index.html
running with greenlet
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      6    79%   23-29
--------------------------------------
TOTAL       29      6    79%
Wrote HTML report to htmlcov_greenlet/index.html
running with gevent
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      6    79%   23-29
--------------------------------------
TOTAL       29      6    79%
Wrote HTML report to htmlcov_gevent/index.html

What should the result be? What exactly is the bug here? I'm not saying there's no bug, I'm saying I'm a concurrency newb that needs it explained.

[Kludex]

Can you help me out with what I am seeing here? I get this result:

Sure! :)

Let's start with the first one:

running with default concurrency
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      3    90%   17-20
--------------------------------------
TOTAL       29      3    90%
Wrote HTML report to htmlcov/index.html

What we see here is the function run() being called, but on line 16, we have that SQLAlchemy makes use of greenlet, and after using it, the lines 17-20 are executed, but the coverage is not able to compute them.

As for the other two:

running with greenlet
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      6    79%   23-29
--------------------------------------
TOTAL       29      6    79%
Wrote HTML report to htmlcov_greenlet/index.html
running with gevent
start
{'?column?': 1}
start2
{'?column?': 1}
Name     Stmts   Miss  Cover   Missing
--------------------------------------
bug.py      29      6    79%   23-29
--------------------------------------
TOTAL       29      6    79%
Wrote HTML report to htmlcov_gevent/index.html

They are just meant to show that using those concurrency options, we are able to cover the missing lines from before. But then we are not able to have a full coverage anyway - because non async functions will not be covered.

Just to give you more context about the situation here: when developing with Starlette (or FastAPI, fwiw) non-async endpoint functions are executed in a ThreadPoolExecutor (the reason why the last 2 reports don't have full coverage, I guess). If you're interested, you can check the code where this is implemented here.

Let me know if something is not clear, I'd be happy to clarify.

[Kludex]

Not sure if I was clear, but what is expected: have a way to have 100% coverage on the snippet using a single report command.

[nedbat]

Thanks. The concurrency setting in coverage.py is used to know where to look to decide that a new stack is being used. I can see how to accommodate threads and one of the "light threads" packages (greenlet, eventlet, gevent). Do we also need to deal with more than one of the light thread packages at the same time?

[Kludex]

For this issue, I think it will be enough threads and one "light threads" packages, as you said, but I don't know about other use-cases. 😞

[nedbat]

Now you can specify --concurrency=thread,gevent (or whatever) as of commit c9d821d. This fixes this problem.

[Kludex]

Thanks @nedbat ! :)

[nedbat]

This is now released as part of coverage 6.2.

[serialbandicoot]

I know this is closed, however I thought I would just add that if you're using .coveragerc then just add in the concurrency = greenlet or whichever thread option.