Pin Python 3.9.16 on Cygwin CI

[EliahKagan]

The bug

The latest currently packaged version of Python 3.9 for Cygwin is 3.9.18 (provided by the Cygwin package python39 at version 3.9.18-1). That version, at least as we are using it, has a problem where pip stalls indefinitely on some PyPI package downloads. This is the problem encountered around the time #1813 was reviewed and merged, and discussed in comments there, but it was not triggered by that or any other change in GitPython.

Details

In #1813 (comment) I said I couldn't produce it locally, but since then I have been able to do so. I believe the reason I couldn't produce it locally at that time was that I had not cleared cached pip downloads in ~/.cache. I am unsure of the exact condition under which the problem occurs, but it is possibly when a single run of pip must download two packages; the first downloads, and the second stalls forever.

I have in some places, including some commit messages, described this as "blocking," but that was a guess, and a wrong one. When produced locally, the Cygwin python3.9 process uses a full CPU core until terminated (so it is "spinning" rather than "blocking"). I'm willing to rebase commits on request to correct that, but I lean toward not doing so for reasons of efficiency, in part because CI will run again on them. In Cygwin with the kill command, SIGTERM does not terminate it; SIGKILL does not seem to either, or at least not reliably. Right-clicking on the process in the "Details" tab of the Task Manager always terminates it immediately. Once terminated, pip can be attempted again, and it will succeed in downloading what it had just failed to download, but then fail on the next download if there is another one (which there usually is).

This happens whether or not I upgrade the PyPA packages (pip, setuptools, and wheel). It sometimes happens for wheel when I do, which is how a number of the CI runs have failed. When it doesn't, that pip run succeeds. Whether or not PyPA packages were upgraded, the subsequent run of pip install -e ".[test]", which installs many more packages, always encounters the problem. More specifically, it used to happen with the coverage package, but a few hours ago started usually happening with pytest instead, which I believe is just due to a different order in which packages are downloaded, triggered by the very recent release of pytest 8. If pip is terminated and rerun, it will happen on every second package, as far as I have observed.

This happens with multiple versions of the python39-pip Cygwin package, as well as with multiple versions of the PyPI pip package if requested explicitly. Therefore, while the problem happens when pip runs, I don't believe it is due to a bug in pip or even a bug in Cygwin's python39-pip package. It also does not seem to be affected by whether pip is run with pip or python3.9 -m pip, nor by whether or not pip is used in a virtual environment. It happens with multiple versions of the cygwin Cygwin package which provides cygwin1.dll. It can happen when attempting to download a source package or a wheel. It only happens on Cygwin, not native Windows or other platforms.

Examining the CI logs for commits from before and after the problem began reveals that the problem did not occur when the python39 Cygwin package was at version 3.9.16-1, and always occurred once it was at version 3.9.18-1. For example, 9b7e15f used 3.9.16-1 while 987dbf4 used 3.8.18-1. Specific versions were not requested, so typically the latest stable versions of Cygwin packages are installed, and it was on 26 January that python39 version 3.9.18-1 was promoted to stable. This does not occur with Python 3.8.

The workaround

Pinning 3.9.16-1

This pull request downgrades Python on Cygwin to the latest available patch version of 3.9 packaged for Cygwin of those that strictly precede 3.9.18 where the problem occurs. That version is 3.9.16, provided by the Cygwin package python39 at version 3.9.16-1.

This version may eventually no longer be available for download from Cygwin's repositories, so hopefully a real solution or better workaround will be found by then, or perhaps a future update to the package itself will fix the problem. Because 3.8 works, an existing backup workaround is to downgrade even further to 3.8.

Switching actions to facilitate pinning

Although GitHub code search finds repositories where the official cygwin/install-cygwin-action GitHub Action was used, or an attempt made to use it, with the package=version syntax for specifying Cygwin packages to be installed, that does not appear working. It doesn't report an error when I attempt it, but the version number seems always to be ignored. So in order to pin python39 at 3.9.16-1, I also switched to using egor-tensin/setup-cygwin. The dependency graph feature in GitHub reports them as being about equally popular (official, unofficial).

However, I removed add-to-path: false; it seems egor-tensin/setup-cygwin doesn't have such a feature. So it may be worthwhile to switch back once we can, to use that again. The main benefit of add-to-path: false is clarity about the environment from which we are using Cygwin facilities, but it can also help with cleanup/finalization performed by actions that that are run before Cygwin is installed: actions/checkout issues a warning and seems like it may not be cleaning up fully, due to attempting to use the Cygwin git for cleanup. I think it is okay for now because the GitHub hosted runners are virtual machines that get deleted and recreated each time; only self-hosted runners are (potentially) reused. But if we have to keep using it for a long time then that should be fixed.

Other things I tried

I tried a bunch of other things while investigating this, as well as trying a few variations on the downgrades (corresponding to some of the things I said made no difference above). If each of my original commits were its own commit in this pull request, the pull request would have more than 40 commits. Although this may not be inherently excessive, it seems to me that it was better to squash them down into two commits, represented the two actually useful workarounds I found (downgrading to 3.8, and downgrading only to 3.9.16) done in what seemed like the best of the ways I tried.

However, for future investigation, I preserved the full history by using GitHub itself to perform the squashes, from two fork-internal PRs, EliahKagan#2 and EliahKagan#3, which are linked and explained in the two commits. (I had to amend the second after squashing to fix a mistake in its title, which is why its hash differs from the hash the PR shows as merged.) The individual original commits can be examined in those PRs, though I don't believe it is at all necessary to look at that to review this PR (if I did, I wouldn't have squashed them). Note that some of those individual commits might be misleading individually because the changes did not always achieve what the messages described; in particular, attempts to pin packages before switching from cygwin/cygwin-install-action to egor-tensin/setup-cygwin did not actually do any pinning.

[Byron]

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.

[EliahKagan]

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.

[Byron]

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.

[EliahKagan]

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.

[Byron]

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 😁.

[EliahKagan]

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).

[Byron]

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.

[EliahKagan]

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.

[Byron]

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!