GeezerVison

Thanks a lot for the investigation, and for coming up with a fix after what seems like arduous work with more than 40 attempts.

What surprises me the most is that I didn't see a link to an official tracking issue for this bug in what might the c-python repository - after all, a lot of people should have encountered it (but apparently didn't). Definitely still puzzling.

I think the bug is probably in the downstream Cygwin package for Python 3.9.18, or in some other component of Cygwin but only triggered due to changes in 3.9.18. But I haven't found anything about it on the Cygwin mailing lists. I might investigate it further. Now that I can produce it locally, I could try to come up with a minimal way to produce it, then observe that with Cygwin's strace.

That's great to hear! I have a feeling that this bug is great for denial of service attacks against toolchains given that it spins hot forever and ignores all non-fatal signals as well. If you can track it down that might be preventing further damage to the wider internet - part of me probably can't believe that GitPython is so special it's the only project experiencing the issue.

It turns out that the more specific trigger in pip, for this problem that manifested as an indefinite stall with a progress bar at 0%, may not been downloading, but the progress bar itself. Passing --progress-bar off after pip install enables the step to succeed, both locally and on CI. The first progress bar is okay, but subsequent progress bars drawn by the same invocation of pip seem to cause the problem. This works both locally and on CI. I say "may not" because I haven't looked into what else pip does differently when progress bars are disabled; perhaps it does something synchronously that would otherwise be asynchronous. Other things, which seem related, are also going wrong, so it's not reasonable at this time to go back to 3.9.18 by using --progress-bar off.

Contrary to what my experiments described above had led me to think, this does actually depend to some extent on the version of pip that is used. If an old enough version is used, it draws progress bars in a different way that is not affected. In the past, pip vendored progress and used it to draw progress bars; that vendored dependency was removed in pip 22.1. Recent versions of pip use a feature of their vendored rich dependency to draw progress bars. Because a version of pip with a differently implemented progress bar doesn't stall, I suspect the problem may really be triggered by the progress bar drawing code.

However, the bug still appears to be in Python 3.9.18 as packaged for Cygwin, and not in rich or pip, unless the other indefinite stalling problem, detailed below, that happens after this one is overcome, turns out, somehow, to be altogether separate.

Details

I experimented with turning off the progress bars is in 6f57fe5. In that commit's Cygwin run, it gets past TestBase::test_with_bare_rw_repo. The next test, which it fails to start, is TestBase::test_with_rw_remote_and_rw_repo. Before that starts, pytest stalls indefinitely on CI. The way we are running pytest on CI, progress bars are not printed, but I tried turning off colorization (9b7e2bc), and that made no difference.

I have not managed to produce that locally because I get a different effect. Locally, the malfunction is at the same point, on the way into the decorator wrapper for TestBase::test_with_rw_remote_and_rw_repo, but instead of stalling, the Python process is silently terminated with an exit status of 0.

This happens when the decorator wrapper sets up a remote repository. Surprisingly, the problem seems unrelated to the wrapper's use of git-daemon. Instead, it is in the call to the Remote.fetch method that something triggers termination. This happens whenever I call that method, and it happens a short time after the Remote.fetch call successfully completes. In this one-liner, on my machine, the list of FetchInfo objects is always printed, and then OK. is sometimes printed and sometimes not, such that decreasing the sleep time causes it to always be printed and increasing it causes it never to be printed:

python -c 'import time, git; print(git.Repo().remote().fetch()); time.sleep(0.12); print("OK.")'

pdb output only shows that the call succeeded and shows nothing for the termination. It is not processed as a SystemExit exception and catching that, or even all exceptions (including others not deriving from Exception) does not catch it. Adding print as a Python auditing hook reveals the subprocess.Popen event as expected, but nothing else afterwards.

When I produce the problem interactively in a REPL or pdb, the next prompt displays, and shortly thereafter Python terminates. This happens even when the pdb command n was just used (to advance only one step). No cleanup appears to be done, judging from how I usually have to issue reset in my shell (or make an new terminal) after testing it interactively, for shell commands to appear correctly as I type them.

The problem might be triggered by something in Git.AutoInterrupt, since Remote.fetch uses as_process=True in a self.repo.git.fetch call, but I am guessing that Git.AutoInterrupt is unrelated because manually testing with it, including with the dynamic fetch method on a Git object (as well as in direct Git.execute calls) does not produce the problem. The next thing Remote.fetch does after calling self.repo.git.fetch is to call its _get_fetch_info_from_stderr method, which handles progress, but not in the same sense as a pip progress bar: it reads from the subprocess and parses its output.

It appears NumPy's CI is also affected

My earlier web searches had not turned up other projects that had a similar problem to what this PR works around. But more recently, a search revealed numpy/numpy#25708, which seems to be the same problem, in which Python stalls on Cygwin since the upgrade from the downstream 3.9.16 to the downstream 3.9.18.

Thanks so much for sharing this early result, a very interesting read!

Can strace reveal more about the order of operations that lead to python exiting? It would also be interesting to know if the stall on CI is causing high-CPU (even though I vaguely remember that it indeed does spin hot). Maybe strace on CI can also reveal which syscalls are involved, if any, and debugging this more with the tmate extension should be quite pleasant.

While reading, I thought "threads, pipes, subprocess spawning, lots of syscalls, forks, locks" as things that probably happen concurrently here. And the fact that it's not the whole world suffering from this probably means is something rather specific at the intersection of numpy and GitPython (and who knows which else).

The silent exit 0 the could be produced locally makes me think that it can't be the work of a signal, but would be typical for what happens once a forked process exits successfully. It's like the memory of the parent of the fork gets messed with, causing it to exit instead. This shouldn't be possible with a normal fork() implementation, but might be possible with vfork() which expects no change to shared memory at all before exec is called. It truly seems like it's a threading-related issue, maybe even something related to the GIL changes that everyone was talking about?

Anyway, that's all I've got 😁.

This has been found to affect Pillow's CI (as well as GitPython's and NumPy's):

• Pin to Python 3.9.16-1 python-pillow/Pillow#7762

It has also been reported to the Cygwin mailing list (Cygwin does not use a separate bug tracker):

• by Daniel Abrahamsson - in pip install
• by Andrew Murray - in Pillow tests

Can strace reveal more about the order of operations that lead to python exiting?

Yes, Daniel Abrahamsson found that exception c0000005 at 0000000000000000 appears repeatedly an strace log during the hang.

When I ran the strangely terminating case described above with GitPython's Remote.fetch, I could see that too.

It looks like terminating may be a rare manifestation of the bug, and that looping forever is much more common. When I simplified the Remote.fetch case into something more useful for debugging the underlying issue, it hanged and strace produced such messages without end.

import hashlib
import threading
import time
t1 = threading.Thread(target=lambda: print("hello"))
t2 = threading.Thread(target=lambda: print("goodbye"))
t1.start()
time.sleep(1)
print("in between")
t2.start()
t1.join()
t2.join()

Key point: While hashlib is unused, the problem does not occur with that script if that import is omitted.

Other observations:

• t1 can be joined before t2 is started and the problem still occurs. That is, t1.join() can be moved to immediately follow t1.start(). [Edit: Added missing text "before t2 is started".]
• The threads don't have to print or have other side effects (I did that so it would be clear they were running), nor is it required for the main thread to print.
• time.sleep(1) achieves a brief delay, and other ways of achieving a delay are also effective; this can be done in a REPL, in which case the delay between manually entering the statements is sufficient, and time need not be imported.
• If t1 is joined before t2 is started, the problem sometimes occurs even if time.sleep(1) is omitted. I presume this is simply because of the short delay incurred by the join.

Although I got to that by starting with experiments in GitPython, that script produces the problem outside a virtual environment (i.e., in a global environment where GitPython is not installed). I ran it from a Cygwin bash shell with:

/usr/bin/python3.9 simple.py

And, for strace, with:

strace -o strace.out /usr/bin/python3.9 simple.py

By the time I killed the process in the strace run, strace.out had grown to 1819328 lines, most of which were:

--- Process 25112 (pid: 20768), exception c0000005 at 0000000000000000

I made a copy of the first 6610 lines of the file in truncated.out and uploaded it to a gist. This keeps 8 of the repeated lines.

I expect some of this information may be useful to the Cygwin Python package maintainer and possibly other users/developers, and I will try to post to the Cygwin mailing list soon.

In case it turns out to be useful in subsequent experimentation on GitPython, the relationship between the short script shown above and code in GitPython that runs in a Remote.fetch is that Remote.fetch, through _get_fetch_info_from_stderr, calls git.cmd.handle_process_output, which uses zero, one, or two child threads to read the subprocess's stdout and stderr.

These child threads may sometimes correspond to t1 and t2 above, but I think that is uncommon. They are started too close in time to each other to produce the effect described above. I think multiple calls to handle_process_output, or a call to handle_process_output after other threads have been created in some other way, is more likely what happens in the tests. I'm not sure, and I am not certain how well this captures how it arises in GitPython's tests.

I tested with a shell script that outputs both to stdout and stderr, initially with Git.execute, but subsequently with direct calls to handle_process_output, which I then extracted and gradually simplified. This is the shell script, countdown:

#!/bin/bash

for i in {9..0}; do
    sleep 0.1
    if ((i % 2 == 0)); then
        printf '%d\n' "$i"
    else
        printf '%d\n' "$i" >&2
    fi
done

For test and demonstration purposes, handle_process_output can be simplified while still resembling the original. The version in this Python script would definitely not be a sufficient implementation for GitPython, and I've changed the interface too, but it works for testing this bug and is still structured similarly. The following script produces the problem on the second call to run_job:

#!/usr/bin/env python

from subprocess import PIPE, Popen
import threading

import git


def handle_process_output(process, stdout_handler, stderr_handler):
    def pump_stream(stream, handler):
        try:
            for line in stream:
                handler(line)
        finally:
            stream.close()

    pumps = [
        (process.stdout, stdout_handler),
        (process.stderr, stderr_handler),
    ]

    threads = []

    for stream, handler in pumps:
        t = threading.Thread(target=pump_stream, args=(stream, handler))
        t.start()
        threads.append(t)

    for t in threads:
        t.join()


def run_job():
    proc = Popen(["bash", "countdown"], stdout=PIPE, stderr=PIPE)
    handle_process_output(
        proc,
        lambda line: print(f"stdout: {line!r}"),
        lambda line: print(f"stderr: {line!r}"),
    )
    proc.wait()


def main():
    for i in range(1, 11):
        print(f"Job {i}:")
        run_job()
    print("Done.")


if __name__ == "__main__":
    main()

Notice that the git module is imported but never used. Yet removing that import eliminates the problem. More specifically, it turns out that importing smmap is insufficient, but importing gitdb is sufficient. I had feared that this was due to gitdb globally instantiating a data structure defined in smmap, but that is not the case; it's gitdb's standard library imports. A bit of trial and error turned up that adding just a hashlib import is sufficient. Further simplification led to the much shorter script above, with the sleep call added once I noticed that the problem was easier and simpler to produce in a REPL (due to the delay of entering commands).

Key point: While hashlib is unused, the problem does not occur with that script if that import is omitted.

This is downright amazing, and I am impressed by your ability to minimise the reproducer testcase!

With it, it should be easy to find the culprit and fix it.

And excuse my ignorance here, but is it correct that the reproducer script will only trigger on particular versions of Python? Or only when running in a Cygwin environment?

I am asking because with it it should be possible to bisect the corresponding interpreter source-code to the exact breaking commit.

is it correct that the reproducer script will only trigger on particular versions of Python? Or only when running in a Cygwin environment?

The problem strongly appears specific to the intersection of Python 3.9.18 and Cygwin, and the script behaves accordingly.

This is to say that I found that script only to hang on that combination of system and Python version, and this is also where I was otherwise able to observe the bug (Cygwin being a "system" for this purpose). On systems I tested other than Cygwin, it always completed successfully, printing all three messages, including with Python 3.9.18. On Cygwin, it likewise completed successfully when tested with Python 3.8.18 and 3.9.16, but showcased the problem on 3.9.18.

As noted in the message I sent to the Cygwin mailing list, most of my testing was on my local machine, but it behaves accordingly on GitHub Actions. The maintainer will likely work on the issue soon.

(Although it was after my list message that I added native Windows to the CI experiment, the situation with it is still essentially as described there. I have not built unpatched versions of Python 3.9.16 and 3.9.18 for Windows, and there are no official python.org Windows builds for 3.9 past 3.9.13. The native Windows 3.9.16 and 3.9.18 builds used in the CI experiment are downstream conda-forge builds. They are unlikely to differ in a way relevant to this, but it's not necessarily a perfect comparison.)

I am asking because with it it should be possible to bisect the corresponding interpreter source-code to the exact breaking commit.

It might also be feasible to bisect using pip install, since the problem reliably occurs on the second progress bar drawn. (--no-cache-dir could be passed to avoid skipping downloads by using cached packages, which can cause fewer progress bars to be drawn.) The script may be faster since less processing has to be done, and it is simpler than pip so it may help with debugging, which is my hope.

I'm unsure how straightforward bisection would be, because I don't know if all upstream commits that work for upstream builds will build or run correctly when built for Cygwin and with Cygwin patches applied. Even for releases, not all 3.9.z versions are packaged downstream for Cygwin.

Although I recommend keeping the Cygwin python39 package pinned to 3.9.16-1 in GitPython's cygwin-test.yml workflow until a fix is available, the maintainer marked 3.9.18-1 as a test package version, rather than a stable package version, very soon after the original report to the mailing list. So we would get 3.9.16-1 again for now even if it were unpinned. I mention this not to recommend unpinning it before the problem is fixed, but because it is relevant to any existing feature branches; they should not need any merge or rebase for pushes to pass.

This is especially relevant to #1791, as it means that's probably already in the clear as far as this Cygwin issue is concerned, and nothing related to this has to be done there.

Thanks again for sharing and for taking the issue to the point where it's effectively fixed for everyone until a permanent fix is discovered by the maintainers - amazing work!