Missing lines of coverage when using redis

[krieghan]

I left an inquiry in the python coverage project (nedbat/coveragepy#1671). I'll repeat much of what I've said over there:

Describe the bug
When using asyncio with redis.asyncio, some lines that are definitely hit remain mysteriously uncovered, even when using a combination of different concurrency settings

To Reproduce

1. Python version 3.11.4, with coverage 7.3.0 and redis 5.0.0 (OS is Ubuntu 22.04)
2. My .coveragerc file:

[run]
source = .
parallel = True
concurrency = 
    thread
    gevent
    multiprocessing

(I've tried various combinations of concurrency, but I most often leave it blank. I suspect it's not even appropriate for my application, though I'm not certain)

My minimal example (coverage_test.py):

import asyncio

import redis.asyncio as redis


async def main():
    client = redis.Redis()
    result = await client.get('key')
    print('running main')

if __name__ == '__main__':
    asyncio.run(main())
    print('finished main')

I issue the coverage command with a bash script (coverage.sh) as follows:

coverage erase
coverage run coverage_test.py
coverage combine
coverage html
xdg-open htmlcov/index.html

The output of the script is:

running main
finished main

And the coverage of the file looks like this:

I would expect the last print statement (which is executed, according to the output) to be marked green. I see there are some similar issues (most notably nedbat/coveragepy#1082 and nedbat/coveragepy#1598), but as I mentioned I haven't found a concurrency setting that mitigates this.

I was wondering if any of the maintainers of redis-py had any particular insights about what might cause this. I haven't been able to reproduce it so far with other libraries.

** Update **

I've been experimenting a bit with copying code from redis-py and asyncio to illustrate exactly where this problem happens. Here is my longer example:

import asyncio
from asyncio import timeout as async_timeout

import redis.asyncio as redis


# These functions are lifted off the asyncio library.  I've done
# this to illustrate as much detail as I can about the condition
# where this abberant behavior in coverage manifests.  I've 
# called out the critical line with a comment below
async def stream_wait_for_data(stream, func_name):
    if stream._waiter is not None:
        raise RuntimeError(
            f'{func_name}() called while another coroutine is '
            f'already waiting for incoming data')

    assert not stream._eof, '_wait_for_data after EOF'

    if stream._paused:
        stream._paused = False
        stream._transport.resume_reading()

    stream._waiter = stream._loop.create_future()
    try:
        ###
        # This "return" is the key.  If it's here, the last
        # line of the file will be covered.  If it is missing, the last
        # line of the file will be uncovered.  In both conditions, it
        # prints to stdout, though
        ###
        return
        await stream._waiter
    finally:
        stream._waiter = None

async def stream_read(stream, n=-1):
    if stream._exception is not None:
        raise stream._exception

    if n == 0:
        return b''

    if n < 0:
        blocks = []
        while True:
            block = await stream_read(stream, stream._limit)
            if not block:
                break
            blocks.append(block)
        return b''.join(blocks)

    if not stream._buffer and not stream._eof:
        await stream_wait_for_data(stream, 'read')

    data = bytes(stream._buffer[:n])
    del stream._buffer[:n]

    stream._maybe_resume_transport()
    return data


# This function is lifted from the redis-py base parser
async def can_read_destructive(parser):
    try:
        stream = parser._stream
        async with async_timeout(0):
            return await stream_read(stream)
    except TimeoutError:
        return False


async def main():
    print('running main')
    client = redis.Redis()

    # Much of this logic below is just replicated from redis-py.  It's
    # the code that gets executed when you call "get" on the client
    await client.initialize()
    pool = client.connection_pool
    pool._checkpid()
    async with pool._lock:
        try:
            connection = pool._available_connections.pop()
        except IndexError:
            connection = pool.make_connection()
        pool._in_use_connections.add(connection)

    # ensure this connection is connected to Redis
    await connection.connect()
    try:
        parser = connection._parser
        return await can_read_destructive(parser) 

    except OSError as e:
        await connection.disconnect(nowait=True)
        host_error = connection._host_error()
        raise ConnectionError(f"Error while reading from {host_error}: {e.args}")

if __name__ == '__main__':
    asyncio.run(main())

    # This is the line missing coverage in certain conditions.  It is always
    # executed, though:
    print('finished main')

This is what coverage looks like with the return (the one in the example above, called out in the comment, in the "stream_wait_for_data" function):

And without:

[krieghan]

I saw that python released a new version for python 3.11.5. I've tried everything again with this new version. I still see the same behavior in coverage, but I am now seeing an additional traceback from redis as the script closes. I thought it might be related to this line of missing coverage. I'm including it here:

Exception ignored in: <function StreamWriter.del at 0x7fcd228adb20>
Traceback (most recent call last):
File "/usr/local/lib/python3.11/asyncio/streams.py", line 396, in del
self.close()
File "/usr/local/lib/python3.11/asyncio/streams.py", line 344, in close
return self._transport.close()
^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 860, in close
self._loop.call_soon(self._call_connection_lost, None)
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 761, in call_soon
self._check_closed()
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 519, in _check_closed
raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

[dmanthing]

redis 4.5.4 produces 100% coverage for me
new versions however seem to drop my coverage too when used with asyncio

[krieghan]

redis 4.5.4 produces 100% coverage for me

new versions however seem to drop my coverage too when used with asyncio

That's an interesting data point. I'll try moving my redis version back and see if I see the same.

[eugenelandau]

Any updates? The described problem still occurred in version 5.0.1. However, reverting back to 4.5.4 fixed the coverage issue.

[eugenelandau]

I believe this problem occurred after changes were made in this commit: c0833f6. These were introduced in version 4.5.5.

Specifically, in line 531, where the await asyncio.shield wrap was removed.

So, I fixed this problem with a small patch, like so:

import asyncio

class MyRedis(Redis):
    async def execute_command(self, *args, **options):
        return await asyncio.shield(
            super().execute_command(*args, **options)
        )

I'm not sure if it's the ideal solution, but I added this patch solely for running tests and it successfully restored the correct coverage.

[riconnon]

Also seeing this behaviour using redis-py with channels-redis

[riconnon]

@eugenelandau I tried running my tests with this patch on redis-py 54545ca which is, I think, equivalent to what you've proposed above.
It didn't seem to resolve the issue for me.