Sporadic failures in `Popen()` under Windows with processes left in `subprocess._active` list #508

ankostis · 2016-09-04T14:10:30Z

Under Windows, when running test-cases creating different temporary repositories consecutively, I get sporadic failures when executing the git process:

 File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\repo\base.py", line 872, in init
    git.init(**kwargs)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 466, in <lambda>
    return lambda *args, **kwargs: self._call_process(name, *args, **kwargs)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 910, in _call_process
    return self.execute(make_call(), **_kwargs)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 630, in execute
    raise GitCommandNotFound(str(err))
git.exc.GitCommandNotFound: [WinError 6] The handle is invalid

Digging a bit further, I noticed that before executing the failing Popen(), the subprocess._active list contains 2 leftovers processes, while this list is always empty when not failing.
I tried to add some delays with time.sleep() but it did not help.
It did help when I simplified my test-cases, i.e. dropping some commit actions.
Tested under:
- Windows 10,
- WinPython 3.5.2:
- gitpython: both latest in PyPi v2.0.8 and latest master from github(df65f51) (2.0.9-dev0).
- smmap: 0.9.0
- gitdb: 0.6.4

An minor note: the try-catch Popen() code assumes that any exception caught is because git was not found, while above it obviously not the case.

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

ankostis · 2016-09-04T15:19:28Z

The following TC reproduces stochastically the failure:

import git, io, os.path as osp, tempfile

def do_repo():
    with tempfile.TemporaryDirectory() as td:
        r = git.Repo.init(td)
        newfile = osp.join(r.working_dir, 'foo')
        with io.open(newfile, 'wt') as fd:
            fd.write('Hi!')
        r.index.add([newfile])
        r.index.commit('c1')

class TestRepoTempPaths(unittest.TestCase):
    def test_repo(self):
        for i in range(5):
            print('Try %d' % i)
            do_repo()

When I run it, on my PC it fails the 3rd time:

Try 1
Try 2
Try 3
ERROR

======================================================================
ERROR: test_repo (tests.sampling.test_project.TestTemp)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\objects\commit.py", line 393, in create_from_tree
    repo.head.set_commit(new_commit, logmsg=message)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 218, in set_commit
    self.set_object(commit, logmsg)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 247, in set_object
    return self._get_reference().set_object(object, logmsg)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\reference.py", line 60, in set_object
    oldbinsha = self.commit.binsha
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 183, in _get_commit
    obj = self._get_object()
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 176, in _get_object
    return Object.new_from_sha(self.repo, hex_to_bin(self.dereference_recursive(self.repo, self.path)))
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 125, in dereference_recursive
    hexsha, ref_path = cls._get_ref_info(repo, ref_path)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 157, in _get_ref_info
    raise ValueError("Reference at %r does not exist" % ref_path)
ValueError: Reference at 'refs/heads/master' does not exist

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 627, in execute
    **subprocess_kwargs
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 842, in __init__
    _cleanup()
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 505, in _cleanup
    res = inst._internal_poll(_deadstate=sys.maxsize)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 1259, in _internal_poll
    if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
OSError: [WinError 6] The handle is invalid

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\foo\tests\sampling\test_project.py", line 304, in test_repo
    do_repo()
  File "D:\foo\tests\sampling\test_project.py", line 297, in do_repo
    r.index.commit('c1')
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\index\base.py", line 949, in commit
    author_date=author_date, commit_date=commit_date)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\objects\commit.py", line 397, in create_from_tree
    master = git.refs.Head.create(repo, repo.head.ref, new_commit, logmsg="commit (initial): %s" % message)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 527, in create
    return cls._create(repo, path, cls._resolve_ref_on_create, reference, force, logmsg)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 494, in _create
    ref.set_reference(target, logmsg)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 321, in set_reference
    self.log_append(oldbinsha, logmsg)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\refs\symbolic.py", line 375, in log_append
    committer_or_reader = self.commit.committer
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\gitdb\util.py", line 237, in __getattr__
    self._set_cache_(attr)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\objects\commit.py", line 143, in _set_cache_
    binsha, typename, self.size, stream = self.repo.odb.stream(self.binsha)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\db.py", line 45, in stream
    hexsha, typename, size, stream = self._git.stream_object_data(bin_to_hex(sha))
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 1014, in stream_object_data
    cmd = self._get_persistent_cmd("cat_file_all", "cat_file", batch=True)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 980, in _get_persistent_cmd
    cmd = self._call_process(cmd_name, *args, **options)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 910, in _call_process
    return self.execute(make_call(), **_kwargs)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 630, in execute
    raise GitCommandNotFound(str(err))
git.exc.GitCommandNotFound: [WinError 6] The handle is invalid

----------------------------------------------------------------------
Ran 1 test in 0.756s

FAILED (errors=1)
Exception ignored in: <bound method Git.AutoInterrupt.__del__ of <git.cmd.Git.AutoInterrupt object at 0x0000023E868FFEF0>>
Traceback (most recent call last):
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\site-packages\git\cmd.py", line 290, in __del__
    if proc.poll() is not None:
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 1082, in poll
    return self._internal_poll()
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 1259, in _internal_poll
    if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
OSError: [WinError 6] The handle is invalid
Exception ignored in: <bound method Popen.__del__ of <subprocess.Popen object at 0x0000023E86907A90>>
Traceback (most recent call last):
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 999, in __del__
    self._internal_poll(_deadstate=_maxsize)
  File "D:\Apps\WinPython-64bit-3.5.2.1\python-3.5.2.amd64\lib\subprocess.py", line 1259, in _internal_poll
    if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
OSError: [WinError 6] The handle is invalid

ankostis · 2016-09-04T15:38:39Z

I managed to workaround it by adding repo.git.clear_cache() at the end after the commit, like that:

def do_repo():
    with tempfile.TemporaryDirectory() as td:
        r = git.Repo.init(td)
        newfile = osp.join(r.working_dir, 'foo')
        with io.open(newfile, 'wt') as fd:
            fd.write('Hi!')
        r.index.add([newfile])
        r.index.commit('c1')
    r.git.clear_cache()

But is this expected?

Byron · 2016-09-11T16:05:50Z

Thanks for describing the issue in such great detail, and actually digging down to the root cause of it ! What we might see here is GitPython's failure to cleanup its system resources correctly, as it was made in a time when destructors actually ran deterministically even in python. GitPython itself seems to expect this, even though that never runs in newer python interpreters as the GC runs too rarely.

The side-effect of the resource leakage appears to be the issue you have noticed.

It's a general problem, and the only workaround I see is to make these calls manually. The problem is that everything allocating resources should in fact be used in a context to assure proper cleanup, which would require something like GitPython 3.0. The latter will require a lot of community effort to make happen.

@ankostis What do you think can be sensibly be done here ?

ankostis · 2016-09-11T17:31:38Z

Thank you for your frank clarification of the problem.

In cases like that, where I now the problem but it's huge and I don't have the resources, I enter damage control mode: adding "Known Limitations" sections in the manual, or marking every possible resource method as problematic in the docs.

In the good case, people start to get annoyed and search for workarounds.
If I'm lucky, one fits better :-).

Byron · 2016-09-11T18:47:43Z

Great idea ! I have just added a new Limitations section in the Readme and the documentation, which should help let people known what they are getting themselves into ;).
Also I chose the easy way out, as searching for __del__ usually is all one needs to learn about required cleanup.

ankostis · 2016-09-13T11:51:46Z

I have identified another "deterministic" failure, with the index code relying on destructor in py3.5. The following code reproduces it:

import git

r = git Repo()

def add_bad_blob():
    r.index.add([git.Blob(r, b'f' * 20, 'bad-permissions', 'foo')])

try:
    ## 1st fail on purpose adding into index.
    add_bad_blob()
except Exception as ex:
    """
    git\index\base.py in add()           @799
    git\index\base.py in write()         @213
    git\index\base.py in _serialize()    @180 
    git\index\fun.py in write_cache()    @133
    """
    assert "required argument is not an integer" in str(ex)

try:
    ## 2nd time fails due to stray lock-file.
    add_bad_blob()
except Exception as ex:
    assert "index.lock' could not be obtained" in str(ex)

import gc
gc.collect()


try:
    ## After GC, lock-file gone.
    add_bad_blob()
except Exception as ex:
    assert "required argument is not an integer" in str(ex)

The problem originates at git/index/base.py#L211-214, and can be amended by enclosing them in a try-finally block:

    stream = lfd.open(write=True, stream=True)
    ok= False
    try:
        self._serialize(stream, ignore_extension_data)
        ok = True
    finally:
        if not ok:
            lfd.rollback()

But a more proper solution would be to retrifit LockedFD as a context-manager.

ankostis · 2016-09-13T11:59:24Z

I note that the previous "index" issue is a show-stopper, and impossible to workaround even when applying the advice you wrote in the manual, because the LockedFD variable instance goes out of scope.

So either you a) modify the project sources, or b) try-catch and explicitly invoke GC then, which is pretty ugly. I would really suggest ~~(b)~~ (a), specifically retrofitting LockedFD as a context manager.

By the way, I believe that the duplicated gitdb.utils.LockedFD class in that project is never used, and can be safely removed.

ankostis · 2016-09-13T12:03:18Z

@Byron I can open it as a new issue if you think it is worth it.

Byron · 2016-09-13T13:06:36Z

Thanks for your investigation , I would love to have an issue for this and
will be happy to attempt a fix.
Thanks again
On Tue, 13 Sep 2016 at 14:03, Kostis Anagnostopoulos <
notifications@github.com> wrote:

@Byron https://github.com/Byron I can open it as a new issue if you
think it is worth it.

—
You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub
#508 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD4hvMkVvHgSYpCoPLF20iYU5_pyUNBks5qppEGgaJpZM4J0ixt
.

Byron added the acknowledged label Sep 11, 2016

Byron added this to the v2.0.9 - Bugfixes milestone Sep 11, 2016

Byron added the waiting for feedback label Sep 11, 2016

Byron removed the waiting for feedback label Sep 11, 2016

Byron closed this as completed in 48c149c Sep 11, 2016

ankostis mentioned this issue Sep 14, 2016

Adding invalid blobs to Index leaves stray lock-file in python 3.5 due to non deterministic desctructors #514

Closed

ankostis added the tag.leaks label Oct 11, 2016

langfield mentioned this issue Aug 8, 2022

PermissionError (access denied) on F.rmtree(F.working_dir(remote_repo)) call in push() on Windows langfield/ki#25

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sporadic failures in `Popen()` under Windows with processes left in `subprocess._active` list #508

Sporadic failures in `Popen()` under Windows with processes left in `subprocess._active` list #508

ankostis commented Sep 4, 2016

ankostis commented Sep 4, 2016 •

edited

Loading

ankostis commented Sep 4, 2016 •

edited

Loading

Byron commented Sep 11, 2016

ankostis commented Sep 11, 2016

Byron commented Sep 11, 2016

ankostis commented Sep 13, 2016

ankostis commented Sep 13, 2016 •

edited

Loading

ankostis commented Sep 13, 2016

Byron commented Sep 13, 2016

Sporadic failures in Popen() under Windows with processes left in subprocess._active list #508

Sporadic failures in Popen() under Windows with processes left in subprocess._active list #508

Comments

ankostis commented Sep 4, 2016

ankostis commented Sep 4, 2016 • edited Loading

ankostis commented Sep 4, 2016 • edited Loading

Byron commented Sep 11, 2016

ankostis commented Sep 11, 2016

Byron commented Sep 11, 2016

ankostis commented Sep 13, 2016

ankostis commented Sep 13, 2016 • edited Loading

ankostis commented Sep 13, 2016

Byron commented Sep 13, 2016

Sporadic failures in `Popen()` under Windows with processes left in `subprocess._active` list #508

Sporadic failures in `Popen()` under Windows with processes left in `subprocess._active` list #508

ankostis commented Sep 4, 2016 •

edited

Loading

ankostis commented Sep 4, 2016 •

edited

Loading

ankostis commented Sep 13, 2016 •

edited

Loading