Repository navigation
rc.exe randomly not found (race condition?) #2212
Description
I've run into a issue on GitHub Actions where in like a small percent of the VMs spinned up, pip will fail with the error LINK : fatal error LNK1158: cannot run 'rc.exe':
error: command 'C:\\Program Files (x86)\\Microsoft Visual Studio\\2019\\Enterprise\\VC\\Tools\\MSVC\\14.26.28801\\bin\\HostX86\\x64\\link.exe' failed with exit status 1158
ERROR: Command errored out with exit status 1: 'C:\hostedtoolcache\windows\Python\3.6.8\x64\python.exe' -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'C:\\Users\\runneradmin\\kivy\\setup.py'"'"'; __file__='"'"'C:\\Users\\runneradmin\\kivy\\setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' develop --no-deps Check the logs for full command output.
Exception information:
Traceback (most recent call last):
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\cli\base_command.py", line 188, in _main
status = self.run(options, args)
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\cli\req_command.py", line 185, in wrapper
return func(self, options, args)
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\commands\install.py", line 407, in run
use_user_site=options.use_user_site,
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\req\__init__.py", line 71, in install_given_reqs
**kwargs
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\req\req_install.py", line 790, in install
unpacked_source_directory=self.unpacked_source_directory,
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\operations\install\editable_legacy.py", line 51, in install_editable
cwd=unpacked_source_directory,
File "C:\hostedtoolcache\windows\Python\3.6.8\x64\lib\site-packages\pip\_internal\utils\subprocess.py", line 241, in call_subprocess
raise InstallationError(exc_msg)
pip._internal.exceptions.InstallationError: Command errored out with exit status 1: 'C:\hostedtoolcache\windows\Python\3.6.8\x64\python.exe' -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'C:\\Users\\runneradmin\\kivy\\setup.py'"'"'; __file__='"'"'C:\\Users\\runneradmin\\kivy\\setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' develop --no-deps Check the logs for full command output.
Simply re-running the actions normally solves the issue. Here's an example of a good run https://github.com/kivy/kivy/runs/791883878?check_suite_focus=true, and a bad run https://github.com/kivy/kivy/runs/791983410?check_suite_focus=true.
My first thought was that this a GitHub Action environment issue, so I opened a bug report there: actions/runner-images#1087. However, after some investigation, it seemed this is more likely a bug in setuptools. The reason is that using process monitor to check all instantiations of link.exe we looked at the environmental PATH variable of the process when it started. And in the failing examples, python would call link.exe multiple times for each cython generated c-file, but some of these would be missing all the visual studio compiler paths from its PATH.
E.g. process monitor shows this during the compile step: 
.
But the first one's (6396) PATH is:
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\\Extensions\Microsoft\IntelliCode\CLI
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\VC\Tools\MSVC\14.26.28801\bin\HostX86\x64
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\VC\Tools\MSVC\14.26.28801\bin\HostX86\x86
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\VC\VCPackages
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TeamFoundation\Team Explorer
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\MSBuild\Current\bin\Roslyn
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Team Tools\Performance Tools\x64
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Team Tools\Performance Tools
C:\Program Files (x86)\Microsoft Visual Studio\Shared\Common\VSPerfCollectionTools\vs2019\\x64
C:\Program Files (x86)\Microsoft Visual Studio\Shared\Common\VSPerfCollectionTools\vs2019\
C:\Program Files (x86)\Microsoft SDKs\Windows\v10.0A\bin\NETFX 4.8 Tools\
C:\Program Files (x86)\HTML Help Workshop
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\CommonExtensions\Microsoft\FSharp\
C:\Program Files (x86)\Windows Kits\10\bin\10.0.19041.0\x86
C:\Program Files (x86)\Windows Kits\10\bin\x86
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\\MSBuild\Current\Bin
C:\windows\Microsoft.NET\Framework\v4.0.30319
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\
C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\Tools\
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\sdl2\bin
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\glew\bin
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\gstreamer\bin
....
while the second one's (6520) is much shorter and is missing 18 paths (Doesn't contain C:\Program Files (x86)\Windows Kits\10\bin\10.0.19041.0\x86 with rc.exe):
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\sdl2\bin
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\glew\bin
C:\hostedtoolcache\windows\Python\3.8.3\x64\share\gstreamer\bin
....
You can inspect a pared down process monitor log here (you need to open it in process monitor):
logfile.zip or get the full 100+MB file from this action: https://github.com/kivy/kivy/actions/runs/145338811. procmon-3.8-x64 is the good log, procmon-3.7-x64 is the bad log.
As far as I'm aware, the only path type stuff we manipulate is with the following when some package is imported. But I fail to see how this could cause it:
_root = sys.prefix
dep_bins = [join(_root, 'share', 'sdl2', 'bin')]
if isdir(dep_bins[0]):
os.environ["PATH"] = dep_bins[0] + os.pathsep + os.environ["PATH"]The question is, why randomly within one python -m pip install -e . command does some link.exe get created without the proper visual studio paths in its environment? It seems like it must be some kind of race condition where in some cases, the compiler gets called with the wrong env?
Activity
jaraco commentedon Jul 10, 2020
I'm afraid I don't have a lot to offer. You've already performed quite a bit of analysis deeper than I could. I did look at the failing kivy build log, and I don't see anything there that strikes me as abnormal.
I do observe that
distutils(on which Setuptools is based) does patch the PATH envar (also here) for MSVC compiler. I'm not certain that's the code path that gets hit, but it does seem likely. In particular, thespawnpatch is obviously thread-unsafe, so could be implicated in a race condition. I'm not aware of any concurrent processing that would allow for such a race.There are some recent builds of Setuptools that are attempting to adopt distutils (>=48.x,<49.1). If you want to try building with those, you can see if they're any better (as they'll incorporate many updates to distutils for Python 3.7-3.9). Soon I hope, Setuptools will adopt distutils in the latest release and we can add some debugging code.
Let me know if there's more I can do to help you investigate.
matham commentedon Jul 11, 2020
Thanks for the info, that helped me get a starting point.
For a first step, I copied over
_msvccompiler.pyandmsvc9compiler.pyand added print statements to see which spawn is being hit. And it turns out_msvccompiler.pyspawn is where the environment gets set and reset to include the visualstudio paths.I then tested replacing that
super().spawn(cmd)withsubprocess.check_output(cmd)and the issue went away so far after 7 CI runs. However, that doesn't mean anything if it's a race condition, because that could simply mess with the timing so the condition is not hit.So, to figure out where there threads are coming from given that there's no obvious thread usage, I added code to detect if spawn is called from multiple threads (https://gist.github.com/matham/a0da3beae05834a3607a8fdc9a6aacd4#file-_msvccompiler-py-L513). Turns out there are almost always two simultaneous calls to spawn from two threads. Following is the stack trace from one example where it detected that another thread concurrently called
spawn:and e.g.
Could this be the issue? If so, is there anything we could do for this, short for replacing
spawnwithsubprocessand explicitly pass in the env variable, rather than changing it in parent process?Allow spawn to accept environment. Avoid monkey-patching global state…
jaraco commentedon Jul 11, 2020
Nice work. Thanks for confirming my suspicion and tracing the threads. I wish I knew what was creating those threads, but at least knowing that there are more than one is confirmation enough.
That's actually my best recommendation -- avoid mutating global state and thread-unsafe operations.
In fde70b1, I've patched distutils to avoid this condition. If you install setuptools from this link, that's a preview of the aforementioned commit, you should be able to test this potential fix. Keep in mind that the distutils override feature is disabled by default in 49.1.2, so you'll also want to also set
SETUPTOOLS_USE_DISTUTILS=localin the environment to enable the adopted and modified copy of distutils.Can you try that in your environment and see if it corrects the issue?
matham commentedon Jul 11, 2020
Thanks for fixing this so quickly. I tried with the provided setuptools and there hasn't been any failures after 10 CI runs. Previously it would fail after a few runs, so this seems to indicate that the issue is fixed!
Allow spawn to accept environment. Avoid monkey-patching global state. …
jaraco commentedon Jul 12, 2020
The latest release of Setuptools, v49.1.3 should have this fix (still the
SETUPTOOLS_USE_DISTUTILS=localis required).openstack-setuptools: Autospec creation for update from version 49.1.…
setuptools: Autospec creation for update from version 49.1.1 to versi…