WIndows 3.7 redirector script issue

[sfc-gh-mkeller]

Issue

Version 20.0.34 with Python 3.7 on Windows seems to have messed up how tox runs.
It appears to be caused by PR #1976

Environment

Provide at least:

• OS: Microsoft Windows Server 2019 - GitHub actions

• pip list of the host python where virtualenv is installed:

  appdirs-1.4.4 colorama-0.4.4 distlib-0.3.1 filelock-3.0.12 importlib-metadata-2.0.0 packaging-20.4 pluggy-0.13.1 py-1.9.0 pyparsing-2.4.7 six-1.15.0 toml-0.10.1 tox-3.20.1 tox-external-wheels-0.1.7 virtualenv-20.0.34 zipp-3.3.0

Output of the virtual environment creation

The tox output is available here: https://github.com/snowflakedb/snowflake-connector-python/runs/1250254992?check_suite_focus=true

It appears as calling the virtualenv is just like calling the system wide Python without having its dependencies injected to the system wide Python.

Here's the important part of the output:

py37-extras-ci installed: <snip>,requests==2.23.0,<snip>
py37-extras-ci run-test-pre: PYTHONHASHSEED='436'
py37-extras-ci run-test: commands[0] | python test/extras/run.py --debug
Traceback (most recent call last):
  File "test\extras\no_use_pycon.py", line 8, in <module>
    import requests
ModuleNotFoundError: No module named 'requests'
Full path: ['D:\\a\\snowflake-connector-python\\snowflake-connector-python\\test\\extras', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\python37.zip', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\DLLs', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\lib', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64', 'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci', 'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci\\lib\\site-packages']
Current process information
PID: 4328
Name: python.exe
Cmdline: C:\hostedtoolcache\windows\Python\3.7.9\x64\python.exe test/extras/run.py --debug

I have checked the changelog and I think there might be an issue in the redirector script, but I haven't actually looked at the code myself.

I have verified that pinning virtualenv==20.0.33 outside of tox solves the issue.

Thank you!

[sfc-gh-mkeller]

After some more thinking, I think the issue might be because we do the following:
https://github.com/snowflakedb/snowflake-connector-python/blob/6e151f716d0e6bb90596959bac394e4165ce04e0/test/extras/run.py#L16
So if the redirector script didn't set something up just right then the executable python could resolve to the system wide install of Python instead of the one inside of the virtualenv.

[gaborbernat]

Can you change that script to do python -c 'import sys; print(sys.executable)' and python -m site and come back with the output of those?

[sfc-gh-mkeller]

I wasn't sure if you wanted those comments to run in tox or in the subprocess.run, so i did it for both

py37-extras-ci run-test: commands[0] | python -c 'import sys; print(sys.executable)'
D:\a\snowflake-connector-python\snowflake-connector-python\.tox\py37-extras-ci\Scripts\python.EXE
py37-extras-ci run-test: commands[1] | python -m site
sys.path = [
    'D:\\a\\snowflake-connector-python\\snowflake-connector-python',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\python37.zip',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\DLLs',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\lib',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64',
    'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci',
    'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci\\lib\\site-packages',
]
USER_BASE: 'C:\\Users\\runneradmin\\Python' (doesn't exist)
USER_SITE: 'C:\\Users\\runneradmin\\Python\\Python37\\site-packages' (doesn't exist)
ENABLE_USER_SITE: False

py37-extras-ci run-test: commands[2] | python test/extras/run.py --debug
C:\hostedtoolcache\windows\Python\3.7.9\x64\python.exe
sys.path = [
    'D:\\a\\snowflake-connector-python\\snowflake-connector-python',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\python37.zip',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\DLLs',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\lib',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64',
    'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\lib\\site-packages',
]
USER_BASE: 'C:\\Users\\runneradmin\\Python' (doesn't exist)
USER_SITE: 'C:\\Users\\runneradmin\\Python\\Python37\\site-packages' (doesn't exist)
ENABLE_USER_SITE: True

Full logs can be found at: https://github.com/snowflakedb/snowflake-connector-python/runs/1254675623?check_suite_focus=true

Commit for code reference: df35690 (#413)

[gaborbernat]

Any reason why you're using python within the run script and not sys.executable instead? I believe python resolves in your case to the the Windows builtin python, or the system one. Good question why this does not happen with earlier virtualenv version. But I don't believe we changed this part. What's the strategy here, how should python resolve? (at least it should be python.exe on Windows and not python to have some chance of success). Within the run script can you print what's the PATH variable containing? The content of `D:\a\snowflake-connector-python\snowflake-connector-python\.tox\py37-extras-ci`` would also be interesting to see.

[sfc-gh-mkeller]

I used python because the tox documentation here (https://tox.readthedocs.io/en/latest/config.html#conf-commands) says:

the virtual environment binary path (the bin folder within) is prepended to the os PATH, meaning commands will first try to resolve to an executable from within the virtual environment, and only after that outside of it. Therefore python translates as the virtual environments python (having the same runtime version as the basepython), and pip translates as the virtual environments pip.

This is the full path in the run script:

['D:\\a\\snowflake-connector-python\\snowflake-connector-python\\test\\extras', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\python37.zip', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\DLLs', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64\\lib', 'C:\\hostedtoolcache\\windows\\Python\\3.7.9\\x64', 'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci', 'D:\\a\\snowflake-connector-python\\snowflake-connector-python\\.tox\\py37-extras-ci\\lib\\site-packages']

What I think is happening that the redirector script is removing the virtualenv's bin folder from the path to redirect the python call to the system wide python install. Because of this python would have no other option but to resolve to the system wide python executable.

Does this sound like what could be going on @gaborbernat ?

[gaborbernat]

The tox documentation applies for content within commands, not for the content of scripts invoked. tox resolves python for you within commands, but has no control for what happens within scripts called from there.

[sfc-gh-mkeller]

That's fair, but this also means that if someone has a virtualenv activated (on Windows with 3.7, or above) and they start a python subprocess from it then they will have no access to scripts installed into that virtualenv. For example if I installed precommit-hooks into my currently active virtualenv then I will not be able to do subprocess.call(['precommit-hooks', 'arg1', ..]) because the bin folder is not in the path anymore.

However, this is at least a behavior change between versions. Which I think would have deserved more than a patch bump and proper documentation as this difference in behavior will always be present between Unix and Windows.

[gaborbernat]

This is likely a bug (though still need to replicate it). But its not virtualenv bug, both a venv one within Cpython.

[gaborbernat]

The wrapper comes from venv of Cpython it's not provided by virtualenv.

[sfc-gh-mkeller]

The wrapper comes from venv of Cpython it's not provided by virtualenv.

My apologies, I thought that this was specific to virtualenv.

I have come up with a minimal reproducing script to help with this issue here: repro.tar.gz

After you unzip this, setup 2 virtualenvs (3.6 and 3.8) like this:

mkeller@MARKKELLER6EDC MINGW64 ~/package
$ py -3.6 -m virtualenv venv36
created virtual environment CPython3.6.8.final.0-64 in 1031ms
creator CPython3Windows(dest=C:\Users\mkeller\package\venv36, clear=False, global=False)
seeder FromAppData(download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy,
app_data_dir=C:\Users\mkeller\AppData\Local\pypa\virtualenv)
added seed packages: pip==20.2.3, setuptools==50.3.0, wheel==0.35.1
activators
BashActivator,BatchActivator,FishActivator,PowerShellActivator,PythonActivator,XonshActivator
(venv)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ py -3.8 -m virtualenv venv38
created virtual environment CPython3.8.2.final.0-64 in 828ms
creator CPython3Windows(dest=C:\Users\mkeller\package\venv38, clear=False, global=False)
seeder FromAppData(download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy,
app_data_dir=C:\Users\mkeller\AppData\Local\pypa\virtualenv)
added seed packages: pip==20.2.3, setuptools==50.3.0, wheel==0.35.1
activators
BashActivator,BatchActivator,FishActivator,PowerShellActivator,PythonActivator,XonshActivator
(venv)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ source venv36/Scripts/activate
(venv36)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ pip install pytest
Collecting pytest
<snip>
Successfully installed atomicwrites-1.4.0 attrs-20.2.0 colorama-0.4.4 importlib-metadata-2.0.0 iniconfig-1.1.1 packaging-20.4 pluggy-0.13.1 py-1.9.0 pyparsing-2.4.7 pytest-6.1.1 six-1.15.0 toml-0.10.1 zipp-3.3.0
(venv36)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ deactivate
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ source venv38/Scripts/activate
(venv38)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ pip install pytest
Collecting pytest
<snip>
Successfully installed atomicwrites-1.4.0 attrs-20.2.0 colorama-0.4.4 iniconfig-1.1.1 packaging-20.4 pluggy-0.13.1 py-1.9.0 pyparsing-2.4.7 pytest-6.1.1 six-1.15.0 toml-0.10.1

Please look at the difference in what happens:

(venv38)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ python run_scripts.py
path: ['C:\\Users\\mkeller\\package', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\python38.zip', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\DLLs', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\lib', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38', 'C:\\Users\\mkeller\\package\\venv38', 'C:\\Users\\mkeller\\package\\venv38\\lib\\site-packages']
/c/Users/mkeller/package/venv38/Scripts/python
path: ['C:\\Users\\mkeller\\package', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\python38.zip', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\DLLs', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\lib', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38', 'C:\\Users\\mkeller\\AppData\\Local\\Programs\\Python\\Python38\\lib\\site-packages']
Traceback (most recent call last):
  File "script1.py", line 4, in <module>
    import pytest
ModuleNotFoundError: No module named 'pytest'
Traceback (most recent call last):
  File "run_scripts.py", line 8, in <module>
    sub_process.check_returncode()
  File "C:\Users\mkeller\AppData\Local\Programs\Python\Python38\lib\subprocess.py", line 444, in check_returncode
    raise CalledProcessError(self.returncode, self.args, self.stdout,
subprocess.CalledProcessError: Command '['python', 'script1.py']' returned non-zero exit status 1.

and

(venv36)
mkeller@MARKKELLER6EDC MINGW64 ~/package
$ python run_scripts.py
path: ['C:\\Users\\mkeller\\package', 'C:\\Users\\mkeller\\package\\venv36\\Scripts\\python36.zip', 'C:\\Program Files\\Python36\\DLLs', 'C:\\Program Files\\Python36\\lib', 'C:\\Program Files\\Python36', 'C:\\Users\\mkeller\\package\\venv36', 'C:\\Users\\mkeller\\package\\venv36\\lib\\site-packages']
/c/Users/mkeller/package/venv36/Scripts/python
path: ['C:\\Users\\mkeller\\package', 'C:\\Users\\mkeller\\package\\venv36\\Scripts\\python36.zip', 'C:\\Program Files\\Python36\\DLLs', 'C:\\Program Files\\Python36\\lib', 'C:\\Program Files\\Python36', 'C:\\Users\\mkeller\\package\\venv36', 'C:\\Users\\mkeller\\package\\venv36\\lib\\site-packages']

I know I pasted quite a bit of stuff here, but the first big blob isn't that important, just make sure you install pytest into both 36 and 38 virtualenvs.

Something interesting I learned while making this minimal example is that whatever is removing the virtualenv's bin from the path is smart enough not to do this when you call a script from that virtualenv. Like if I had a test folder, had script1.py moved and renamed to test/test_basic.py, had pytest imported there and the subrpocess call called pytest that works without issue. I guess this issue is specific to calling a sub process on python.

edit: copying from Windows cmd.exe screwed up my output, I have simplified it now and fixed it. Sorry!

[gaborbernat]

In the above if you swap virtualenv calls with python -m venv can you reproduce the same issue? If yes you'll need to report the bug to https://bugs.python.org/ for fix. If not then it's related to virtualenv, and is our bug. Though here I suspect is venv issue. (Based on the findings we might be able to patch it here, while upstream fixes the issue, but first we must identify exactly the underlying cause).

[sfc-gh-mkeller]

Yup, you are right. I get the same error with venv 😓 .
I'll get on reporting this to Python and post a link here once I have done so

[gaborbernat]

For reference upstream issue reproted under https://bugs.python.org/issue42041

[gaborbernat]

Per the upstream issue passing in just python into subprocess is not supported on Windows. It might have worked before, but not by design.

[sfc-gh-mkeller]

@gaborbernat thank you one more time for responding so quickly and helping me with this issue! 😄

Could I suggest for this behavior to be documented also in virtualenv's documentation? Maybe just point to however Python ends up documenting this?

Köszönöm szépen!

[gaborbernat]

Sure 😃

[gaborbernat]

For reference upstream clarification 👍 python/cpython#22715