pypy3 + coverage: unclosed file <_io.FileIO fd=3 mode='rb' closefd=True> #807

asottile · 2019-06-01T03:37:23Z

Describe the bug

Occasionally while running coverage with pypy3 on a specific testsuite it causes "unclosed file" warnings in random parts of code only when instrumented by coverage.

Apologies, I haven't narrowed down the root cause yet but I do have a pretty-consistent reproduction using docker.

To Reproduce

Here's a dockerfile:

FROM ubuntu:xenial

RUN : \
    && apt-get update \
    && apt-get install -y --no-install-recommends \
        bzip2 \
        curl \
        git \
        virtualenv \
    && apt-get clean \
    && rm -rf /var/lib/apt/lists/*

RUN : \
    && curl --silent --location --output /usr/local/bin/dumb-init https://github.com/Yelp/dumb-init/releases/download/v1.2.2/dumb-init_1.2.2_amd64 \
    && echo '37f2c1f0372a45554f1b89924fbb134fc24c3756efaedf11e07f599494e0eff9 /usr/local/bin/dumb-init' | sha256sum --check \
    && chmod +x /usr/local/bin/dumb-init

RUN : \
    && curl --silent --location --output pypy.tar.bz2 https://bitbucket.org/pypy/pypy/downloads/pypy3.5-v7.0.0-linux64.tar.bz2 \
    && echo '729e3c54325969c98bd3658c6342b9f5987b96bad1d6def04250a08401b54c4b  pypy.tar.bz2' | sha256sum --check \
    && tar -xf pypy.tar.bz2 \
    && rm pypy.tar.bz2

RUN : \
    && git clone https://github.com/pre-commit/pre-commit \
    && git -C pre-commit checkout fff3ad51

WORKDIR pre-commit

RUN : \
    && virtualenv /venv -p ../pypy3.5-v7.0.0-linux64/bin/pypy3 \
    && /venv/bin/pip install -r requirements-dev.txt

CMD [ \
    "dumb-init", \
    "/venv/bin/coverage", "run", "-m", "pytest", "tests/clientlib_test.py" \
]

Build this with

docker build -t pypy-coverage-bug .

You can run this with the following command, however it only reproduces about 1 every 10 times and it's a bit slow to stop and start docker repeatedly:

docker run --rm pypy-coverage-bug

The easier way that I've been reproducing is by doing this

docker run --rm -ti pypy-coverage-bug bash
# and then once inside the docker container (adjust the `-n` for the number of iterations)
yes | head -n 10 | xargs --replace /venv/bin/coverage run -m pytest tests/clientlib_test.py

When it passes it looks like this (which happens most of the time):

============================= test session starts ==============================
platform linux -- Python 3.5.3[pypy-7.0.0-final], pytest-4.5.0, py-1.8.0, pluggy-0.12.0
rootdir: /pre-commit, inifile: tox.ini
plugins: env-0.6.2
collected 37 items                                                             

tests/clientlib_test.py .....................................            [100%]

========================== 37 passed in 1.46 seconds ===========================

When it fails it looks like this:

============================= test session starts ==============================
platform linux -- Python 3.5.3[pypy-7.0.0-final], pytest-4.5.0, py-1.8.0, pluggy-0.12.0
rootdir: /pre-commit, inifile: tox.ini
plugins: env-0.6.2
collected 37 items                                                             

tests/clientlib_test.py .............................E........           [100%]

==================================== ERRORS ====================================
__________ ERROR at teardown of test_meta_hook_invalid[config_repo0] ___________

tp = <class 'AssertionError'>, value = None, tb = None

    def reraise(tp, value, tb=None):
        try:
            if value is None:
                value = tp()
            if value.__traceback__ is not tb:
                raise value.with_traceback(tb)
>           raise value

/venv/site-packages/six.py:693: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

recwarn = WarningsRecorder(record=True)

    @pytest.fixture(autouse=True)
    def no_warnings(recwarn):
        yield
        warnings = []
        for warning in recwarn:  # pragma: no cover
            message = str(warning.message)
            # ImportWarning: Not importing directory '...' missing __init__(.py)
            if not (
                isinstance(warning.message, ImportWarning) and
                message.startswith('Not importing directory ') and
                ' missing __init__' in message
            ):
                warnings.append(
                    '{}:{} {}'.format(warning.filename, warning.lineno, message),
                )
>       assert not warnings
E       assert not ["/venv/site-packages/coverage/pytracer.py:107 unclosed file <_io.FileIO fd=3 mode='rb' closefd=True>"]

tests/conftest.py:40: AssertionError
====================== 37 passed, 1 error in 2.74 seconds ======================

What version of Python are you running? Python 3.5.3[pypy-7.0.0-final]
What versions of what packages do you have installed? The output of pip freeze is very helpful.

root@34a9d341816b:/pre-commit# /venv/bin/pip freeze --all
aspy.yaml==1.3.0
atomicwrites==1.3.0
attrs==19.1.0
cffi==1.12.0
cfgv==2.0.0
coverage==4.5.3
entrypoints==0.3
flake8==3.7.7
greenlet==0.4.13
identify==1.4.3
importlib-metadata==0.17
importlib-resources==1.0.2
mccabe==0.6.1
mock==3.0.5
more-itertools==7.0.0
nodeenv==1.3.3
pathlib2==2.3.3
pip==19.1.1
pkg-resources==0.0.0
pluggy==0.12.0
-e git+https://github.com/pre-commit/pre-commit@fff3ad518cb9a9bf169346aa4727fb70a67a4e30#egg=pre_commit
py==1.8.0
pycodestyle==2.5.0
pyflakes==2.1.1
pytest==4.5.0
pytest-env==0.6.2
PyYAML==5.1
readline==6.2.4.1
setuptools==41.0.1
six==1.12.0
toml==0.10.0
virtualenv==16.6.0
wcwidth==0.1.7
wheel==0.33.4
zipp==0.5.1

What code are you running? Give us a specific commit of a specific repo that we can check out. (shown above, it's pre-commit
What commands did you run? (see above)

Expected behavior
Not to crash (see above)

Additional context

Thanks again for writing coverage, it has been instrumental to all of my python testing! Sorry I haven't narrowed down this bug enough yet, but figured I'd post this in case you have any ideas on where I should start looking!

This is currently flaking a lot for me in azure pipelines :(

The text was updated successfully, but these errors were encountered:

blueyed · 2019-06-01T05:33:44Z

assert not ["/venv/site-packages/coverage/pytracer.py:107 unclosed file <_io.FileIO fd=3 mode='rb' closefd=True>"]

Does it refer to this?

https://github.com/nedbat/coveragepy/blob/coverage-4.5.2/coverage/pytracer.py#L107

blueyed · 2019-06-01T05:34:30Z

Apart from that: do you have to use PyTracer?

asottile · 2019-06-01T05:35:39Z

The error points at a random line number in a random file and doesn't seem correlated with anything I've figured out yet

asottile · 2019-06-04T17:21:13Z

I'm now debugging in a --privileged container w/ strace:

seq 1 100 | xargs -P4 --replace bash -c '(strace -e trace=file -o {}.trace /venv/bin/coverage run -m pytest tests/clientlib_test.py -qq && rm {}.trace) || (echo -e "=====\n{}\n====" && exit 255)'

An example output:

______________ ERROR at teardown of test_validate_config_main_ok _______________

tp = <class 'AssertionError'>, value = None, tb = None

    def reraise(tp, value, tb=None):
        try:
            if value is None:
                value = tp()
            if value.__traceback__ is not tb:
                raise value.with_traceback(tb)
>           raise value

/venv/site-packages/six.py:693: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

recwarn = WarningsRecorder(record=True)

    @pytest.fixture(autouse=True)
    def no_warnings(recwarn):
        yield
        warnings = []
        for warning in recwarn:  # pragma: no cover
            message = str(warning.message)
            # ImportWarning: Not importing directory '...' missing __init__(.py)
            if not (
                isinstance(warning.message, ImportWarning) and
                message.startswith('Not importing directory ') and
                ' missing __init__' in message
            ):
                warnings.append(
                    '{}:{} {}'.format(warning.filename, warning.lineno, message),
                )
>       assert not warnings
E       assert not ["/venv/site-packages/yaml/scanner.py:166 unclosed file <_io.FileIO fd=3 mode='rb' closefd=True>"]

tests/conftest.py:40: AssertionError
=====
14
====
xargs: bash: exited with status 255; aborting

And strace:

# grep '= 3$' -- 14.trace  | tail -1
open("/pre-commit/.coverage", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 3

still not 100% what this means yet 🤔

asottile · 2019-06-04T17:28:54Z

interestingly sometimes I get this:

==================================== ERRORS ====================================
_____ ERROR at teardown of test_validate_warn_on_unknown_keys_at_top_level _____

tp = <class 'AssertionError'>, value = None, tb = None

    def reraise(tp, value, tb=None):
        try:
            if value is None:
                value = tp()
            if value.__traceback__ is not tb:
                raise value.with_traceback(tb)
>           raise value

/venv/site-packages/six.py:693: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
/venv/site-packages/six.py:693: in reraise
    raise value
/pypy3.5-v7.0.0-linux64/lib_pypy/_functools.py:80: in __call__
    return self._func(*(self._args + fargs), **fkeywords)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

recwarn = WarningsRecorder(record=True)

    @pytest.fixture(autouse=True)
    def no_warnings(recwarn):
        yield
        warnings = []
        for warning in recwarn:  # pragma: no cover
            message = str(warning.message)
            # ImportWarning: Not importing directory '...' missing __init__(.py)
            if not (
                isinstance(warning.message, ImportWarning) and
                message.startswith('Not importing directory ') and
                ' missing __init__' in message
            ):
                warnings.append(
                    '{}:{} {}'.format(warning.filename, warning.lineno, message),
                )
>       assert not warnings
E       assert not ["/venv/site-packages/yaml/scanner.py:277 unclosed file <_io.FileIO fd=22 mode='rb' closefd=True>"]

tests/conftest.py:40: AssertionError

root@a8e1f963ad16:/pre-commit# grep '= 22$' -- 8.trace  | tail -1
open("/pre-commit", O_RDONLY|O_CLOEXEC) = 22

asottile · 2019-06-04T17:41:18Z

if I also add ,close to the strace command (now this):

seq 1 100 | xargs -P4 --replace bash -c '(strace -e trace=file,close -o {}.trace /venv/bin/coverage run -m pytest tests/clientlib_test.py -qq && rm {}.trace) || (echo -e "=====\n{}\n====" && exit 255)'

I see this for the fd 22 issue:

>       assert not warnings
E       assert not ["/venv/site-packages/coverage/pytracer.py:124 unclosed file <_io.FileIO fd=22 mode='rb' closefd=True>"]

open("/pre-commit", O_RDONLY|O_CLOEXEC) = 22
stat("/pre-commit", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/pre-commit", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 24
close(24)                               = 0

🤔 so there's definitely an open() without a close() there

asottile · 2019-06-04T18:02:38Z

I've made quite a few leaps here on some guesses, I think I've narrowed it further...

the calls above appear to be coming from the importlib_metadata.version('pre-commit') and the leaks appear to be coming from zipp's call to zipfile (CC @jaraco since I'm essentially copying the implementation here)

import pytest
import zipfile
import zipp


@pytest.fixture(autouse=True)
def no_warnings(recwarn):
    yield
    warnings = []
    for warning in recwarn:  # pragma: no cover
        message = str(warning.message)
        warnings.append(
            '{}:{} {}'.format(warning.filename, warning.lineno, message),
        )
    assert not warnings


def test():
    for _ in range(10000):
        with pytest.raises(Exception):
            zipfile.ZipFile('.')

asottile · 2019-06-04T18:28:22Z

Here's an even more minimal case which takes zipp / zipfile out of the picture:

import io
import pytest
import warnings

def test():
    for _ in range(10000):
        with pytest.raises(IsADirectoryError):
            io.open('.')


with warnings.catch_warnings(record=True) as wrns:
    warnings.simplefilter('always')
    test()

if len(wrns):
    print('*' * 79)
    print('warnings: {}'.format(len(wrns)))
    print('first warning:')
    print('{}:{}:{}'.format(wrns[0].filename, wrns[0].lineno, wrns[0].message))
    print('*' * 79)

warnings: 4806
first warning:
/pre-commit/t.py:8:unclosed file <_io.FileIO fd=3 mode='rb' closefd=True>

asottile · 2019-06-04T18:29:28Z

and now I've eliminated coverage as well:

root@a8e1f963ad16:/pre-commit# /venv/bin/python t.py 
*******************************************************************************
warnings: 3314
first warning:
t.py:8:unclosed file <_io.FileIO fd=3 mode='rb' closefd=True>
*******************************************************************************

I'll take this to the pypy bug tracker 👍

blueyed · 2019-06-04T19:54:31Z

I'll take this to the pypy bug tracker

Please provide a reference.

asottile · 2019-06-04T19:59:56Z

oops used to github linking things, here it is: https://bitbucket.org/pypy/pypy/issues/3021/ioopen-directory-leaks-a-file-descriptor

pypy3 has a file-descriptor leak with `open('directory')` which `zipp.Path(...)` triggers. This preempts passing a directory and tickling that. More information: - https://bitbucket.org/pypy/pypy/issues/3021/ioopen-directory-leaks-a-file-descriptor - nedbat/coveragepy#807 - pytest-dev/pytest#5342

asottile added the bug Something isn't working label Jun 1, 2019

This was referenced Jun 1, 2019

Pass color option to git diff (on failure) pre-commit/pre-commit#1051

Merged

ResourceWarning during collection pytest-dev/pytest#5342

Closed

asottile closed this as completed Jun 4, 2019

jaraco mentioned this issue Oct 22, 2020

Skip zipp.Path when it is not a file - [merged] python/importlib_metadata#203

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

pypy3 + coverage: unclosed file <_io.FileIO fd=3 mode='rb' closefd=True> #807

pypy3 + coverage: unclosed file <_io.FileIO fd=3 mode='rb' closefd=True> #807

asottile commented Jun 1, 2019

blueyed commented Jun 1, 2019 •

edited

Loading

Uh oh!

blueyed commented Jun 1, 2019

Uh oh!

asottile commented Jun 1, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

blueyed commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

Uh oh!

pypy3 + coverage: unclosed file <_io.FileIO fd=3 mode='rb' closefd=True> #807

pypy3 + coverage: unclosed file <_io.FileIO fd=3 mode='rb' closefd=True> #807

Comments

asottile commented Jun 1, 2019

blueyed commented Jun 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

blueyed commented Jun 1, 2019

Uh oh!

asottile commented Jun 1, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

blueyed commented Jun 4, 2019

Uh oh!

asottile commented Jun 4, 2019

Uh oh!

blueyed commented Jun 1, 2019 •

edited

Loading