Recently hitting consistent timeout (pexpect.exceptions.TIMEOUT), looking for a coherent output.

[vityas]

Hey folks, recently, pipenv has been quite unreliable. and while some issues can be done away by clearing cache && hours of debugging, but this one is really driving me crazy.

Issue description

pipenv lock times out for an unknown reason. I'm installing around 200 packages.
why do I call it a bug?

1. because pipenv --verbose should give some insight on what package is actually timing out. Does someone know how can we hack ourway to see what specific package is timing out ??
2. installing the first 100 packages works fine and the second half works fine too. clearly a mess up here.

Expected result

(first of all I expect the lock to succeed)

• I expect --verbose mode to print out the logs as the events were happening, not just the error

Actual result

verbose mode is identical to non-verbose mode

Steps to replicate

that's easy. take any Pipfile. say like that:

[packages] 
urllib3 = "==1.25.10"

and lets just force timeout by reducing the wait time to 1 second, if your internet is fast pick a bigger package

export PIPENV_INSTALL_TIMEOUT=1
pipenv lock -v

nothing in that log will tell you about what you need

pipenv lock -v

Locking [dev-packages] dependencies…
Locking [packages] dependencies…
Building requirements...
Resolving dependencies...
Traceback (most recent call last):
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/bin/pipenv", line 8, in
sys.exit(cli())
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 829, in call
return self.main(*args, **kwargs)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 782, in main
rv = self.invoke(ctx)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 1259, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 1066, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 610, in invoke
return callback(*args, **kwargs)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/decorators.py", line 73, in new_func
return ctx.invoke(f, obj, *args, **kwargs)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/core.py", line 610, in invoke
return callback(*args, **kwargs)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/click/decorators.py", line 21, in new_func
return f(get_current_context(), *args, **kwargs)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/cli/command.py", line 368, in lock
do_lock(
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/core.py", line 1102, in do_lock
venv_resolve_deps(
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/utils.py", line 1323, in venv_resolve_deps
c = resolve(cmd, sp)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/utils.py", line 1136, in resolve
result = c.expect(u"\n", timeout=environments.PIPENV_INSTALL_TIMEOUT)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/delegator.py", line 215, in expect
self.subprocess.expect(pattern=pattern, timeout=timeout)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/pexpect/spawnbase.py", line 343, in expect
return self.expect_list(compiled_pattern_list,
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/pexpect/spawnbase.py", line 372, in expect_list
return exp.expect_loop(timeout)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/pexpect/expect.py", line 181, in expect_loop
return self.timeout(e)
File "/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv/vendor/pexpect/expect.py", line 144, in timeout
raise exc
pexpect.exceptions.TIMEOUT: <pexpect.popen_spawn.PopenSpawn object at 0x10c747520>
searcher: searcher_re:
0: re.compile('\n')
<pexpect.popen_spawn.PopenSpawn object at 0x10c747520>
searcher: searcher_re:
0: re.compile('\n')

-------------------------------------------------------------------------------

$ pipenv --support

Pipenv version: '2020.8.13'

Pipenv location: '/usr/local/Cellar/pipenv/2020.8.13/libexec/lib/python3.8/site-packages/pipenv'

Python location: '/usr/local/Cellar/pipenv/2020.8.13/libexec/bin/python3.8'

Python installations found:

• 3.8.5: /usr/local/bin/python3.8
• 3.8.2: /usr/bin/python3
• 3.7.8: /usr/local/bin/python3
• 3.7.8: /usr/local/bin/python3.7m
• 3.7.8: /usr/local/bin/python3.7
• 3.6.7: /usr/local/bin/python3.6
• 3.6.7: /usr/local/bin/python3.6m
• 3.6.4: /Users/vitya/.pyenv/versions/3.6.4/bin/python3
• 3.6.2: /Users/vitya/.pyenv/versions/3.6.2/bin/python3
• 2.7.16: /usr/bin/python2
• 2.7.16: /usr/bin/python2.7

PEP 508 Information:

{'implementation_name': 'cpython',
 'implementation_version': '3.8.5',
 'os_name': 'posix',
 'platform_machine': 'x86_64',
 'platform_python_implementation': 'CPython',
 'platform_release': '19.6.0',
 'platform_system': 'Darwin',
 'platform_version': 'Darwin Kernel Version 19.6.0: Thu Jun 18 20:49:00 PDT '
                     '2020; root:xnu-6153.141.1~1/RELEASE_X86_64',
 'python_full_version': '3.8.5',
 'python_version': '3.8',
 'sys_platform': 'darwin'}

System environment variables:

• PATH
• GREP_COLOR
• TERM_PROGRAM
• PYENV_ROOT
• NVM_CD_FLAGS
• SHELL
• TERM
• GIT_PROMPT_FETCH_REMOTE_STATUS
• HISTSIZE
• CLICOLOR
• TMPDIR
• TERM_PROGRAM_VERSION
• TERM_SESSION_ID
• OBJC_DISABLE_INITIALIZE_FORK_SAFETY
• USER
• HISTFILESIZE
• NVM_DIR
• PIPENV_IGNORE_VIRTUALENVS
• COMMAND_MODE
• SSH_AUTH_SOCK
• PGUSER
• __CF_USER_TEXT_ENCODING
• LSCOLORS
• _
• LaunchInstanceID
• PWD
• LANG
• ITERM_PROFILE
• XPC_FLAGS
• HISTIGNORE
• XPC_SERVICE_NAME
• COLORFGBG
• HOME
• SHLVL
• PYENV_SHELL
• LC_TERMINAL_VERSION
• GREP_OPTIONS
• ITERM_SESSION_ID
• LOGNAME
• NVM_BIN
• PIPENV_INSTALL_TIMEOUT
• DISPLAY
• LC_TERMINAL
• SECURITYSESSIONID
• COLORTERM
• PIP_DISABLE_PIP_VERSION_CHECK
• PYTHONDONTWRITEBYTECODE
• PIP_SHIMS_BASE_MODULE
• PIP_PYTHON_PATH
• PYTHONFINDER_IGNORE_UNSUPPORTED

Pipenv–specific environment variables:

• PIPENV_IGNORE_VIRTUALENVS: 1
• PIPENV_INSTALL_TIMEOUT: 1

Debug–specific environment variables:

• PATH: /usr/local/Cellar/pipenv/2020.8.13/libexec/tools:/Users/vitya/.nvm/versions/node/v11.7.0/bin:/Users/vitya/.pyenv/shims:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/opt/X11/bin:/Users/vitya/Library/Python/3.6/bin
• SHELL: /bin/bash
• LANG: en_US.UTF-8
• PWD: /Users/vitya/temp/proj1

---

Contents of Pipfile ('/Users/vitya/temp/proj1/Pipfile'):

[[source]]
url = "https://pypi.python.org/simple"
verify_ssl = true
name = "pypi"

[packages] 
urllib3 = "==1.25.10"

Contents of Pipfile.lock ('/Users/vitya/temp/proj1/Pipfile.lock'):

{
    "_meta": {
        "hash": {
            "sha256": "14b462030f651ac7b330ae833537157fba96aeb48561598d3cdc6851a5adb73b"
        },
        "pipfile-spec": 6,
        "requires": {},
        "sources": [
            {
                "name": "pypi",
                "url": "https://pypi.org/simple",
                "verify_ssl": true
            }
        ]
    },
    "default": {
        "urllib3": {
            "hashes": [
                "sha256:91056c15fa70756691db97756772bb1eb9678fa585d9184f24534b100dc60f4a",
                "sha256:e7983572181f5e1522d9c98453462384ee92a0be7fac5f1413a1e35c56cc0461"
            ],
            "index": "pypi",
            "version": "==1.25.10"
        }
    },
    "develop": {}
}

[frostming]

The issue is identified and addressed in #4425

As a workaround, you can raise the timeout value to make installation pass by overriding the env var PIPENV_INSTALL_TIMEOUT=1800