Race condition failure when starting Debugger with python Gunicorn using virtual environment (venv) using VSCode & WSL

[gil0109]

Environment data

• VS Code version: 1.49.1
• Extension version (available under the Extensions sidebar): v2020.9.111407
• OS and version: Windows 10 Enterprise 1909
• Python version (& distribution if applicable, e.g. Anaconda): Python 3.6.9
• Type of virtual environment used (N/A | venv | virtualenv | conda | ...): venv
• Relevant/affected Python packages and their versions: N/A
• Relevant/affected Python-related VS Code extensions and their versions: N/A
• Value of the python.languageServer setting: Mircrosoft

Expected behaviour

(.venv) gillani@NE023769:/mnt/c/git/queue-management$  cd /mnt/c/git/queue-management/api ; /usr/bin/env /mnt/c/git/queue-management/.venv/bin/python3 /home/gillani/.vscode-server/extensions/ms-python.python-2020.9.111407/pythonFiles/lib/python/debugpy/launcher 53426 -- /mnt/c/git/queue-management/.venv/bin/gunicorn wsgi --bind=0.0.0.0:5000 --access-logfile=- --config=/mnt/c/git/queue-management/api/gunicorn_config.py --timeout=9999 
[2020-09-23 17:47:03 -0700] [17483] [INFO] Starting gunicorn 20.0.4
[2020-09-23 17:47:03 -0700] [17483] [INFO] Listening at: http://0.0.0.0:5000 (17483)
[2020-09-23 17:47:03 -0700] [17483] [INFO] Using worker: eventlet
[2020-09-23 17:47:04 -0700] [17498] [INFO] Booting worker with pid: 17498
==> SQLALCHEMY_ENGINE_OPTIONS (Engine: postgresql
{'max_overflow': 20, 'pool_pre_ping': False, 'pool_size': 10}

Actual behaviour

/usr/bin/env /mnt/c/git/queue-management/.venv/bin/python3 /home/gillani/.vscode-server/extensions/ms-python.python-2020.9.111407/pythonFiles/lib/python/debugpy/launcher 53413 -- /mnt/c/git/queue-management/.venv/bin/gunicorn wsgi --bind=0.0.0.0:5000 --access-logfile=- --config=/mnt/c/git/queue-management/api/gunicorn_config.py --timeout=9999 
gillani@NE023769:/mnt/c/git/queue-management$  /usr/bin/env /mnt/c/git/queue-management/.venv/bin/python3 /home/gillani/.vscode-server/extensions/ms-python.python-2020.9.111407/pythonFiles/lib/python/debugpy/launcher 53413 -- /mnt/c/git/queue-management/.venv/bin/gunicorn wsgi --bind=0.0.0.0:5000 --access-logfile=- --config=/mnt/c/git/queue-management/api/gunicorn_config.py --timeout=9999 
source /mnt/c/git/queue-management/.venv/bin/activate
[2020-09-23 17:46:21 -0700] [17438] [INFO] Starting gunicorn 20.0.4
[2020-09-23 17:46:21 -0700] [17438] [INFO] Listening at: http://0.0.0.0:5000 (17438)
[2020-09-23 17:46:21 -0700] [17438] [INFO] Using worker: eventlet
[2020-09-23 17:46:22 -0700] [17453] [INFO] Booting worker with pid: 17453
[2020-09-23 17:46:22 -0700] [17453] [ERROR] Exception in worker process
Traceback (most recent call last):
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/workers/geventlet.py", line 99, in init_process
    super().init_process()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/workers/base.py", line 119, in init_process
    self.load_wsgi()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/workers/base.py", line 144, in load_wsgi
    self.wsgi = self.app.wsgi()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 67, in wsgi
    self.callable = self.load()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 49, in load
    return self.load_wsgiapp()
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 39, in load_wsgiapp
    return util.import_app(self.app_uri)
  File "/mnt/c/git/queue-management/.venv/lib/python3.6/site-packages/gunicorn/util.py", line 358, in import_app
    mod = importlib.import_module(module)
  File "/usr/lib/python3.6/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 994, in _gcd_import
  File "<frozen importlib._bootstrap>", line 971, in _find_and_load
  File "<frozen importlib._bootstrap>", line 953, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'wsgi'
[2020-09-23 17:46:22 -0700] [17453] [INFO] Worker exiting (pid: 17453)
[2020-09-23 17:46:22 -0700] [17438] [INFO] Shutting down: Master
[2020-09-23 17:46:22 -0700] [17438] [INFO] Reason: Worker failed to boot.
gillani@NE023769:/mnt/c/git/queue-management$ source /mnt/c/git/queue-management/.venv/bin/activate
(.venv) gillani@NE023769:/mnt/c/git/queue-management$ 

Steps to reproduce:

[NOTE: Self-contained, minimal reproducing code samples are extremely helpful and will expedite addressing your issue]

1. Running WSL
2. Add following in launch.json:

       {
            // This task runs the main API Python Gunicorn process.
            "name": "Python: Gunicorn",
            "type": "python",
            "request": "launch",
            // Change the `program` value to a path  of your virtualenv's gunicorn file.
            // This should be a path to the virtualenv used for project
            // But instead of  `env/bin/activate`  we put `env/bin/gunicorn`
            // e.g. when developing locally, I'd do `source queue-env/bin/activate`.
            "program": "${workspaceFolder}/.venv/bin/gunicorn",
            "gevent": true,
            "cwd": "${workspaceFolder}/api",
            // High timeout, so gunicorn won't kill process if we hit a debugging breakpoint
            "args": ["wsgi", "--bind=0.0.0.0:5000", "--access-logfile=-", "--config=${workspaceFolder}/api/gunicorn_config.py", "--timeout=9999"],
        },

3. Run Debugger to make fail
   Note: Logs indicate missing packages, I suspect it fails because python virtual environment isn't set in time.
4. Run Debugger again and the gunicorn server starts with no issues.

Logs

N/A

[brettcannon]

Specifically, the import failure seems to be due to the cwd setting not being respected/occurring when the debugger starts.

[fabioz]

@gil0109 can you provide the logs for this?

To get the logs, set "logToFile": true in the launch.

I'm not sure where it puts them in the WSL case (when running in the terminal the path should appear when DEBUGPY_LOG_DIR is set, or you can print it from the program with: print(os.environ['DEBUGPY_LOG_DIR'])).

@int19h @brettcannon that output shows the venv activation being done at the end.

i.e.:

first command:
/usr/bin/env /mnt/c/git/queue-management/.venv/bin/python3 /home/gillani/.vscode-server/extensions/ms-python.python-2020.9.111407/pythonFiles/lib/python/debugpy/launcher 53413 -- /mnt/c/git/queue-management/.venv/bin/gunicorn wsgi --bind=0.0.0.0:5000 --access-logfile=- --config=/mnt/c/git/queue-management/api/gunicorn_config.py --timeout=9999 

second command:
source /mnt/c/git/queue-management/.venv/bin/activate

This seems backwards. I think that the venv activation is done by vscode-python (and not really debugpy)... right?

[int19h]

It's done by the extension, but it does that by, effectively, simulating typing the command in the terminal. So when the terminal is freshly created for a debug session, it can sometimes end up doing it after the debugger command line gets sent, or even in the middle of it. It's a known issue with Conda, and right now the only reliable workaround is to activate the conda environment manually in some terminal, and then launch VSCode from that terminal with auto-activation disabled.

[int19h]

However, it does seem that the gunicorn script used here is intended to activate on its own before starting the app.

[gil0109]

@fabioz Did you still need the logs?

I agree with @int19h , the microsoft python extension adds the activate venv command. Just late and hence the race condition.
Adding the activate venv in the .bashrc doesn't seem to have any effect, I assumed it would run first.

Do you know if there is a way to delay the "program" command ?

[int19h]

@gil0109

When running for the first time, VSCode creates a terminal and runs the shell in it with cwd already set to whatever was specified, so you are not supposed to see cd ... in the terminal for that. But subsequent attempts should use cd, so long as you don't close the Python Debug Console terminal.

I wonder if the way your shell is set up, it forcibly changes the current directory when it's spawned (e.g. you have cd in your .bashrc)? If so, then subsequent runs with explicit cd should work.

[gil0109]

@int19h Yes, I have a cd in the .bashrc script move to the main area of the repo. Taking that out FIXED the issue.

THANK YOU So much.

[int19h]

Thank you for confirming!