search

ycm-core / YouCompleteMe

A code-completion engine for Vim
http://ycm-core.github.io/YouCompleteMe/
GNU General Public License v3.0
25.44k stars 2.81k forks source link

Wrong intepreter when inside a virtualenv shell on macOS #3383

Closed rdbisme closed 4 years ago

rdbisme commented 5 years ago

Issue Prelude

Please complete these steps and check these boxes (by putting an x inside the brackets) before filing your issue:

Thank you for adhering to this process! It ensures your issue is resolved quickly and that neither your nor our time is needlessly wasted.

Issue Details

When opening a python file within a virtualenv shell

pew workon db-model-MCWC4LsT
# or
source ~/.envs/db-model-MCWC4LsT/bin/activate

YcmDebugInfo shows the system interpreter instead of the virtualenv one. This seems to not happen on Linux (and Python 3.6).

I chatted for few days on the Gitter to understand if it was my problem, but it seems related to the jedi.create_environment method, on macOS. The thing is that if I run the following code on an interactive shell within the virtualenv:

PYTHONPATH=../parso python
Python 3.7.3 (default, Mar 30 2019, 03:37:43)
[Clang 10.0.0 (clang-1000.11.45.5)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import jedi
>>> interpreter_path = '/Users/*****/.envs/db-model-MCWC4LsT/bin/python'
>>> environment = jedi.create_environment(interpreter_path, safe = False)
>>> environment.executable
'/Users/*****/.envs/db-model-MCWC4LsT/bin/python'

I correctly get the intepreter inside the virtualenv.

Rewriting these lines like this:

if interpreter_path:
  LOGGER.info('%s - truthy', interpreter_path)
  environment = jedi.create_environment( interpreter_path, safe = False )
else:
  LOGGER.info('%s - falsey', interpreter_path)
  environment = jedi.get_default_environment()
LOGGER.info( '%s', environment.excutable)

I get the following output in the logs:

2019-04-24 23:02:45,235 - DEBUG - Event name: FileReadyToParse
2019-04-24 23:02:45,235 - INFO - Adding buffer identifiers for file: /Users/*****/app.py
2019-04-24 23:02:45,279 - INFO - /Users/*****/.envs/db-model-MCWC4LsT/bin/python - truthy
2019-04-24 23:02:45,392 - INFO - /opt/local/bin/python
2019-04-24 23:02:45,444 - INFO - Received filetype completion available request
2019-04-24 23:02:51,785 - INFO - Received debug info request
2019-04-24 23:02:56,344 - INFO - Received debug info request

For whatever reason, inside ycmd the retrieved intepreter is the system one instead of the virtualenv one

Include steps to reproduce here.

Minimal .vimrc

set rtp+=~/.vim/bundle/Vundle.vim
call vundle#begin()

Plugin 'VundleVim/Vundle.vim'

Plugin 'altercation/vim-colors-solarized'

Plugin 'Valloric/YouCompleteMe'

call vundle#end()            " required
filetype plugin indent on    " required

let $LANG = 'en_US'

set backspace=indent,eol,start
set nocompatible              " be iMproved, required
filetype off                  " required
set mouse=a                   " Mouse mode
syntax enable                 " Syntax Coloring
set background=dark           "
set hidden                    " Allow hidden unsaved buffers

let g:ycm_server_python_interpreter = '/opt/local/bin/python'
let g:ycm_log_level = 'debug'
let g:ycm_max_diagnostics_to_display = 0
let g:ycm_python_binary_path = 'python'

Then runvim app.py.

Include description of a minimal test case, including any actual code required to reproduce the issue.

Just run vim on a python file with the minimal .vimrc provided when inside a (Python 3.7?) virtualenv Check YcmDebugInfo

The Python intepreter should have been the one in the virtualenv (/Users/*****/.envs/db-model-MCWC4LsT/bin/python)

Include description of the expected behaviour.

The Python interpreter is instead the system one

Diagnostic data

Output of vim --version

VIM - Vi IMproved 8.1 (2018 May 18, compiled Jan 10 2019 23:39:07)
macOS version
Included patches: 1-577
Compiled by MacPorts
Huge version without GUI.  Features included (+) or not (-):
+acl               +extra_search      +mouse_netterm     +tag_old_static
+arabic            +farsi             +mouse_sgr         -tag_any_white
+autocmd           +file_in_path      -mouse_sysmouse    -tcl
+autochdir         +find_in_path      +mouse_urxvt       +termguicolors
-autoservername    +float             +mouse_xterm       +terminal
-balloon_eval      +folding           +multi_byte        +terminfo
+balloon_eval_term -footer            +multi_lang        +termresponse
-browse            +fork()            -mzscheme          +textobjects
++builtin_terms    +gettext           +netbeans_intg     +timers
+byte_offset       -hangul_input      +num64             +title
+channel           +iconv             +packages          -toolbar
+cindent           +insert_expand     +path_extra        +user_commands
-clientserver      +job               -perl              +vartabs
+clipboard         +jumplist          +persistent_undo   +vertsplit
+cmdline_compl     +keymap            +postscript        +virtualedit
+cmdline_hist      +lambda            +printer           +visual
+cmdline_info      +langmap           +profile           +visualextra
+comments          +libcall           +python/dyn        +viminfo
+conceal           +linebreak         +python3/dyn       +vreplace
+cryptv            +lispindent        +quickfix          +wildignore
-cscope            +listcmds          +reltime           +wildmenu
+cursorbind        +localmap          +rightleft         +windows
+cursorshape       +lua               -ruby              +writebackup
+dialog_con        +menu              +scrollbind        -X11
+diff              +mksession         +signs             -xfontset
+digraphs          +modify_fname      +smartindent       -xim
-dnd               +mouse             +startuptime       -xpm
-ebcdic            -mouseshape        +statusline        -xsmp
+emacs_tags        +mouse_dec         -sun_workshop      -xterm_clipboard
+eval              -mouse_gpm         +syntax            -xterm_save
+ex_extra          -mouse_jsbterm     +tag_binary        
   system vimrc file: "/opt/local/etc/vimrc"
     user vimrc file: "$HOME/.vimrc"
 2nd user vimrc file: "~/.vim/vimrc"
      user exrc file: "$HOME/.exrc"
       defaults file: "$VIMRUNTIME/defaults.vim"
  fall-back for $VIM: "/opt/local/share/vim"
Compilation: /usr/bin/clang -c -I. -Iproto -DHAVE_CONFIG_H   -I/opt/local/include -isysroot/Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.14.sdk -DMACOS_X -DMACOS_X_DARWIN  -pipe -Os -isysroot/Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.14.sdk -arch x86_64 -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1       
Linking: /usr/bin/clang   -L/opt/local/lib -Wl,-headerpad_max_install_names -Wl,-syslibroot,/Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.14.sdk -arch x86_64 -o vim        -lm  -lncurses -liconv -lintl -framework AppKit  -L/opt/local/lib -llua

Python 3.7

Output of YcmDebugInfo

Printing YouCompleteMe debug information...
-- Client logfile: /var/folders/zl/sy9_75n97ds_v99_8bf6fsc00000gn/T/ycm_9xno0knc.log
-- Server Python interpreter: /opt/local/bin/python
-- Server Python version: 3.7.3
-- Server has Clang support compiled in: True
-- Clang version: clang version 7.0.0 (tags/RELEASE_700/final)
-- No extra configuration file found
-- Python completer debug information:
--   Python interpreter: /opt/local/bin/python
--   Python path: ['/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python37.zip', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7', '/opt/local/Library/Framew
orks/Python.framework/Versions/3.7/lib/python3.7/lib-dynload', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/site-packages']
--   Python version: 3.7.3
--   Jedi version: 0.13.3
--   Parso version: 0.3.4
-- Server running at: http://127.0.0.1:61458
-- Server process ID: 48302
-- Server logfiles:
--   /var/folders/zl/sy9_75n97ds_v99_8bf6fsc00000gn/T/ycmd_61458_stdout_h84wctk5.log
--   /var/folders/zl/sy9_75n97ds_v99_8bf6fsc00000gn/T/ycmd_61458_stderr_f9zwuqik.log

OS version, distribution, etc.

macOS Mojave 10.14.4

micbou commented 5 years ago

I can't reproduce with almost the same configuration (macOS 10.14 and Python 3 from Homebrew). :YcmDebugInfo returns the following:

Printing YouCompleteMe debug information...
-- Client logfile: /var/folders/zy/rsczmz7n72v4gqd2zg024p3h0000gn/T/ycm_qozbzj59.log
-- Server Python interpreter: /usr/local/opt/python/bin/python3.7
-- Server Python version: 3.7.3
-- Server has Clang support compiled in: True
-- Clang version: clang version 8.0.0 (tags/RELEASE_800/final)
-- No extra configuration file found
-- Python completer debug information:
--   Python interpreter: /usr/local/Cellar/python/3.7.3/bin/python3.7
--   Python path: ['/Users/micbou/.local/share/virtualenvs/myvirtualenv/lib/python37.zip', '/Users/micbou/.local/share/virtualenvs/myvirtualenv/li
b/python3.7', '/Users/micbou/.local/share/virtualenvs/myvirtualenv/lib/python3.7/lib-dynload', '/usr/local/Cellar/python/3.7.3/Frameworks/Python.f
ramework/Versions/3.7/lib/python3.7', '/Users/micbou/.local/share/virtualenvs/myvirtualenv/lib/python3.7/site-packages']
--   Python version: 3.7.3
--   Jedi version: 0.13.3
--   Parso version: 0.3.4
-- Server running at: http://127.0.0.1:50042
-- Server process ID: 24915
-- Server logfiles:
--   /var/folders/zy/rsczmz7n72v4gqd2zg024p3h0000gn/T/ycmd_50042_stdout_lg3qkgzb.log
--   /var/folders/zy/rsczmz7n72v4gqd2zg024p3h0000gn/T/ycmd_50042_stderr_x6vx7arr.log

after starting Vim in a virtual environment activated with Pew (pew new myvirtualenv). I don't even have to set the g:ycm_python_binary_path to 'python' but it also works with that option.

So I am not sure why it doesn't work for you but maybe it's an issue with your version of Pew. Are you using the latest version?

$ pew version
1.2.0
rdbisme commented 5 years ago

Shouldn't this: 

-- Python completer debug information:
--   Python interpreter: /usr/local/Cellar/python/3.7.3/bin/python3.7

Be the one from the virtualenv instead. I also tried directly sourcing the virtualenv activate script instead of using pew... I'll try again with the new version and report back.

(In any case I'm also missing the right paths from the Python path)

micbou commented 5 years ago

Be the one from the virtualenv instead.

Yes, that's something I would expect but for some reason the interpreter path returned by Jedi depends on the Python it's running on:

$ /Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python -c "import jedi; print(jedi.create_environment('/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python', safe=False).executable)"
/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python
$ /usr/local/Cellar/python/3.7.3/bin/python3 -c "import jedi; print(jedi.create_environment('/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python', safe=False).executable)"
/usr/local/Cellar/python/3.7.3/bin/python3
$ /usr/local/Frameworks/Python.framework/Versions/3.7/bin/python3 -c "import jedi; print(jedi.create_environment('/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python', safe=False).executable)"
/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/bin/python3
$ /usr/bin/python -c "import jedi; print(jedi.create_environment('/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python', safe=False).executable)"
/Users/micbou/.local/share/virtualenvs/myvirtualenv/bin/python

It's not the issue though because all of these paths actually point to the same Python (/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/bin/python3.7). The important part is that the Python path line in the output of :YcmDebugInfo contains the virtualenv paths.

Could you run the command (replace the *****)

PYTHONPATH=../parso python -c "import jedi; print(jedi.create_environment('/Users/*****/.envs/db-model-MCWC4LsT/bin/python', safe=False).get_sys_path())"

in the YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi folder and paste its output?

rdbisme commented 5 years ago

This works as expected. 

['/Users/*****/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso', '/Users/*****/.envs/db-model-MCWC4LsT/lib/python37.zip', '/Users/*****/.envs/db-model-MCWC4LsT/lib/python3.7', '/Users/*****/.envs/db-model-MCWC4LsT/lib/python3.7/lib-dynload', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7', '/Users/*****/.envs/db-model-MCWC4LsT/lib/python3.7/site-packages']

Also

PYTHONPATH=../parso python -c "import jedi; print(jedi.create_environment('/Users/*****/.envs/db-model-MCWC4LsT/bin/python', safe=False).executable)"
/Users/*****/.envs/db-model-MCWC4LsT/bin/python

The thing is that in the interactive virtualenv shell jedi works as expected. It's inside ycmd that I have problems...

micbou commented 5 years ago

The thing is that in the interactive virtualenv shell jedi works as expected.

Did you try outside the virtualenv? It should work as well.

rdbisme commented 5 years ago 
PYTHONPATH=../parso python -c "import jedi; print(jedi.create_environment('/Users/****/.envs/db-model-MCWC4LsT/bin/python', safe=False).get_sys_path())"
['/Users/*****/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python37.zip', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/lib-dynload', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/site-packages']
PYTHONPATH=../parso python -c "import jedi; print(jedi.create_environment('/Users/***/.envs/db-model-MCWC4LsT/bin/python', safe=False).executable)"
/opt/local/bin/python

This is what I get from running the same commands, but outside the virtualenv. So it gets the system python instead.

rdbisme commented 5 years ago

Ehi, any idea on how to solve here? :)

rdbisme commented 5 years ago

Hello, I'm still experiencing this issue... Is there anything I can do to help you out with the debug?

rdbisme commented 5 years ago

I'm trying to debug this. I delved a bit inside jedi create_environment function. It creates an Environment object with the correct python binary path (i.e. the one from the virtualenv).

The problem arises when the instance of Environment calls self._get_subprocess. What self._get_subprocess does is creating a customized subprocess.Popen and so executing the virtualenv Python intepreter in a subprocess (Link).

What it does then, is sending the function _get_info to the subprocess and it captures the output.

def _get_info():
    return (
        sys.executable,
        sys.prefix,
        sys.version_info[:3],
    )

I tried to log a bit what's happening when the Subprocess is created, so I added few logging entries in the source code jedi/evaluate/compiled/subprocess/__init__.py

    def _send(self, evaluator_id, function, args=(), kwargs={}):
        if self.is_crashed:
            raise InternalError("The subprocess %s has crashed." % self._executable)

        if not is_py3:
            # Python 2 compatibility
            kwargs = {force_unicode(key): value for key, value in kwargs.items()}

        data = evaluator_id, function, args, kwargs
        import logging
        LOGGER = logging.getLogger('ycmd')
        LOGGER.info(data)
        LOGGER.info(f'Process args: {self._process.args}')
        try:
            pickle_dump(data, self._process.stdin, self._pickle_protocol)
        except (socket.error, IOError) as e:
            # Once Python2 will be removed we can just use `BrokenPipeError`.
            # Also, somehow in windows it returns EINVAL instead of EPIPE if
            # the subprocess dies.
            if e.errno not in (errno.EPIPE, errno.EINVAL):
                # Not a broken pipe
                raise
            self._kill()
            raise InternalError("The subprocess %s was killed. Maybe out of memory?"
                                % self._executable)

        try:
            is_exception, traceback, result = pickle_load(self._process.stdout)
            import logging
            LOGGER = logging.getLogger('ycmd')
            LOGGER.info(result)
        except EOFError as eof_error:
            try:
                stderr = self._process.stderr.read().decode('utf-8', 'replace')
            except Exception as exc:
                stderr = '<empty/not available (%r)>' % exc
            self._kill()
            _add_stderr_to_debug(self._stderr_queue)
            raise InternalError(
                "The subprocess %s has crashed (%r, stderr=%s)." % (
                    self._executable,
                    eof_error,
                    stderr,
                ))

        _add_stderr_to_debug(self._stderr_queue)

        if is_exception:
            # Replace the attribute error message with a the traceback. It's
            # way more informative.
            result.args = (traceback,)
            raise result
        return result

    def delete_evaluator(self, evaluator_id):
        """
        Currently we are not deleting evalutors instantly. They only get
        deleted once the subprocess is used again. It would probably a better
        solution to move all of this into a thread. However, the memory usage
        of a single evaluator shouldn't be that high.
        """
        # With an argument - the evaluator gets deleted.
        self._evaluator_deletion_queue.append(evaluator_id)

And this is what I get:

2019-07-23 15:42:52,543 - INFO - Received ready request
2019-07-23 15:42:52,606 - INFO - Received event notification
2019-07-23 15:42:52,607 - INFO - Received event notification
2019-07-23 15:42:52,607 - INFO - Adding buffer identifiers for file: /Users/rubendibattista/git/x/josiepy/josie/solver/solver.py
2019-07-23 15:42:52,655 - INFO - data: (None, <function _get_info at 0x10fc42320>, (), {})
2019-07-23 15:42:52,658 - INFO - Process args: ('/Users/rubendibattista/.envs/josiepy-B4k-0ZyT/bin/python', '/Users/rubendibattista/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi/jedi/evaluate/compiled/subprocess/__main__.py', '/Users/rubendibattista/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso', '3.7.4')
2019-07-23 15:42:52,771 - INFO - ('/opt/local/bin/python', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7', (3, 7, 4))
2019-07-23 15:42:52,771 - INFO - data: (None, <function get_sys_path at 0x10fd7f710>, (), {})
2019-07-23 15:42:52,772 - INFO - Process args: ('/Users/rubendibattista/.envs/josiepy-B4k-0ZyT/bin/python', '/Users/rubendibattista/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi/jedi/evaluate/compiled/subprocess/__main__.py', '/Users/rubendibattista/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso', '3.7.4')
2019-07-23 15:42:52,772 - INFO - ['/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python37.zip', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/lib-dynload', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/site-packages']
2019-07-23 15:42:52,814 - INFO - Received filetype completion available request
2019-07-23 15:42:54,463 - INFO - Received debug info request

So if we examine the args passed to the Popen, we see that in facts the provided interpreter is /Users/rubendibattista/.envs/josiepy-B4k-0ZyT/bin/python. (according to Popen documentation the first arg is the program to execute). Unfortunately the result is:

('/opt/local/bin/python', '/opt/local/Library/Frameworks/Python.framework/Versions/3.7', (3, 7, 4))

It seems to me that the jedi subprocess, despite being run with the virtualenv python interpreter, executes instead the system python. I'm not very familiar with the jedi internals and why this happens, but it looks to me that this is a bug.

puremourning commented 5 years ago

seems to me that the jedi subprocess, despite being run with the virtualenv python interpreter, executes instead the system python. I'm not very familiar with the jedi internals and why this happens, but it looks to me that this is a bug.

Thanks for the detail, based on that I think this should be raised with Jedi not us.

puremourning commented 4 years ago

not sure there's anything for YCM to change here.

rdbisme commented 4 years ago

Just a ping here, that in the jedi issue, help is wanted ;).

I'm still experiencing the bug...