Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Pip install logs not shown with verbose option. #10556

Open
Tracked by #13862
peterroelants opened this issue Mar 16, 2021 · 12 comments
Open
Tracked by #13862

Pip install logs not shown with verbose option. #10556

peterroelants opened this issue Mar 16, 2021 · 12 comments

Comments

@peterroelants
Copy link

peterroelants commented Mar 16, 2021

Current Behavior

Installing a conda environemnt with
conda env create -vv --file ./env.yml seems to get stuck at the pip installation.

It seems that the verbose option -vv does not enable pip install logs to be shown.

Steps to Reproduce

conda env create -vv --file env.yml

Where env.yml has pip packages to install.

This seems to wait at Installing pip dependencies: ...working... without forwarding pip install log output untill the pip install is finished.

This "hangs" for quite a while without any feedback if custom pip-install compile flags are being used because it doesn't forward any logs until the compilation is finished. When pip install finishes, it prints the non-verbose pip install log after Ran pip subprocess with arguments:

For example use conda env create -vv --file env.yml where env.yml has the following content:

name: prefect_sharepoint
channels:
  - defaults
dependencies:
  - dask-core=2021.3.0
  - distributed=2021.3.0
  - Cython
  - pip=21.0.1
  - python=3.8.8
  - requests=2.25.1
  - nomkl=3.0
  - pip:
    - "--no-binary pydantic"
    - "--global-option=build_ext"
    - "--global-option=-j8"
    - kafka-python==2.0.2
    - prefect==0.14.12
    - pydantic==1.8.1
    - python-box==5.3.0
    - shareplum==0.5.1

Expected Behavior

  • pip install logs to be piped through directly to stdout
  • pip install logs to follow the conda --verbose and -vv options.

Environment Information

`conda info`

❯ conda info

     active environment : None
            shell level : 0
       user config file : /home/peter/.condarc
 populated config files : /home/peter/.condarc
          conda version : 4.9.2
    conda-build version : not installed
         python version : 3.8.5.final.0
       virtual packages : __cuda=11.2=0
                          __glibc=2.31=0
                          __unix=0=0
                          __archspec=1=x86_64
       base environment : /home/peter/miniconda3  (writable)
           channel URLs : https://repo.anaconda.com/pkgs/main/linux-64
                          https://repo.anaconda.com/pkgs/main/noarch
                          https://repo.anaconda.com/pkgs/r/linux-64
                          https://repo.anaconda.com/pkgs/r/noarch
          package cache : /home/peter/miniconda3/pkgs
                          /home/peter/.conda/pkgs
       envs directories : /home/peter/miniconda3/envs
                          /home/peter/.conda/envs
               platform : linux-64
             user-agent : conda/4.9.2 requests/2.25.1 CPython/3.8.5 Linux/5.8.0-44-generic ubuntu/20.04.2 glibc/2.31
                UID:GID : 1000:1000
             netrc file : None
           offline mode : False


`conda config --show-sources`

==> /home/peter/.condarc <==
auto_activate_base: False

`conda list --show-channel-urls`

# packages in environment at /home/peter/miniconda3/envs/prefect_sharepoint:
#
# Name                    Version                   Build  Channel
_libgcc_mutex             0.1                        main    defaults
blas                      1.0                    openblas    defaults
brotlipy                  0.7.0           py38h27cfd23_1003    defaults
ca-certificates           2021.1.19            h06a4308_1    defaults
certifi                   2020.12.5        py38h06a4308_0    defaults
cffi                      1.14.5           py38h261ae71_0    defaults
chardet                   4.0.0           py38h06a4308_1003    defaults
click                     7.1.2              pyhd3eb1b0_0    defaults
cloudpickle               1.6.0                      py_0    defaults
croniter                  0.3.37                   pypi_0    pypi
cryptography              3.4.6            py38hd23ed53_0    defaults
cython                    0.29.22          py38h2531618_0    defaults
cytoolz                   0.11.0           py38h7b6447c_0    defaults
dask-core                 2021.3.0           pyhd3eb1b0_0    defaults
distributed               2021.3.0         py38h06a4308_0    defaults
docker                    4.4.4                    pypi_0    pypi
heapdict                  1.0.1                      py_0    defaults
idna                      2.10               pyhd3eb1b0_0    defaults
kafka-python              2.0.2                    pypi_0    pypi
ld_impl_linux-64          2.33.1               h53a641e_7    defaults
libffi                    3.3                  he6710b0_2    defaults
libgcc-ng                 9.1.0                hdf63c60_0    defaults
libstdcxx-ng              9.1.0                hdf63c60_0    defaults
lxml                      4.6.2                    pypi_0    pypi
marshmallow               3.10.0                   pypi_0    pypi
marshmallow-oneofschema   2.1.0                    pypi_0    pypi
msgpack-python            1.0.2            py38hff7bd54_1    defaults
mypy-extensions           0.4.3                    pypi_0    pypi
natsort                   7.1.1                    pypi_0    pypi
ncurses                   6.2                  he6710b0_1    defaults
nomkl                     3.0                           0    defaults
ntlm-auth                 1.5.0                    pypi_0    pypi
openssl                   1.1.1j               h27cfd23_0    defaults
pendulum                  2.1.2                    pypi_0    pypi
pip                       21.0.1           py38h06a4308_0    defaults
prefect                   0.14.12                  pypi_0    pypi
psutil                    5.8.0            py38h27cfd23_1    defaults
pycparser                 2.20                       py_2    defaults
pydantic                  1.8.1                    pypi_0    pypi
pyopenssl                 20.0.1             pyhd3eb1b0_1    defaults
pysocks                   1.7.1            py38h06a4308_0    defaults
python                    3.8.8                hdb3f193_4    defaults
python-box                5.3.0                    pypi_0    pypi
python-dateutil           2.8.1                    pypi_0    pypi
python-slugify            4.0.1                    pypi_0    pypi
pytz                      2021.1                   pypi_0    pypi
pytzdata                  2020.1                   pypi_0    pypi
pyyaml                    5.4.1            py38h27cfd23_1    defaults
readline                  8.1                  h27cfd23_0    defaults
requests                  2.25.1             pyhd3eb1b0_0    defaults
requests-ntlm             1.1.0                    pypi_0    pypi
requests-toolbelt         0.9.1                    pypi_0    pypi
setuptools                52.0.0           py38h06a4308_0    defaults
shareplum                 0.5.1                    pypi_0    pypi
six                       1.15.0           py38h06a4308_0    defaults
sortedcontainers          2.3.0              pyhd3eb1b0_0    defaults
sqlite                    3.35.0               hdfb4753_0    defaults
tabulate                  0.8.9                    pypi_0    pypi
tblib                     1.7.0                      py_0    defaults
text-unidecode            1.3                      pypi_0    pypi
tk                        8.6.10               hbc83047_0    defaults
toml                      0.10.2                   pypi_0    pypi
toolz                     0.11.1             pyhd3eb1b0_0    defaults
tornado                   6.1              py38h27cfd23_0    defaults
typing-extensions         3.7.4.3                  pypi_0    pypi
urllib3                   1.26.4             pyhd3eb1b0_0    defaults
websocket-client          0.58.0                   pypi_0    pypi
wheel                     0.36.2             pyhd3eb1b0_0    defaults
xz                        5.2.5                h7b6447c_0    defaults
yaml                      0.2.5                h7b6447c_0    defaults
zict                      2.0.0              pyhd3eb1b0_0    defaults
zlib                      1.2.11               h7b6447c_3    defaults

@peterroelants
Copy link
Author

peterroelants commented Mar 16, 2021

Some notes:

I think the "hanging" is because conda/gateways/subprocess.any_subprocess uses process.communicate(), which blocks until the process ends.

This SO post illustrates how to read the output from the subprocess and stream it to the conda install stdout.

@Sysa
Copy link

Sysa commented Sep 14, 2021

Can confirm, faced the same issue (Azure ML instances).
Sometime it can take hours with no clear reason for delaying and showing only Installing pip dependencies. While pip dependencies itself, without conda, takes seconds to resolve from the same machine.

@jarandaf
Copy link

I am also experiencing this issue.

@FeryET
Copy link

FeryET commented Mar 31, 2022

I am also experiencing this issue, trying to debug what is actually going wrong with my pip installs that takes this long. Any progress on this?

@lpasselin
Copy link

Dirty workaround to see pip logs in real time. Unfortunately this shows verbose pip logs and not only pip stdout.

export PIP_LOG="/tmp/pip_log.txt"
touch ${PIP_LOG}
tail -f ${PIP_LOG} & 
conda env create --prefix ${CONDA_ENV_PATH} -f "${TMP_ENV_DIR}/train/conda_dependencies.yml"
killall tail
rm ${PIP_LOG}

Horrendous oneliner for dockerfile:

RUN export PIP_LOG="/tmp/pip_log.txt" && touch ${PIP_LOG} && tail -f ${PIP_LOG} & conda env create --prefix ${CONDA_ENV_PATH} -f "${TMP_ENV_DIR}/train/conda_dependencies.yml" && killall tail && rm ${PIP_LOG}

@uberj
Copy link

uberj commented May 11, 2022

Also hitting this issue on Azure ML model deploy. Installing pip dependencies: ...working... until timeout.

@PeterSenyszyn
Copy link

Still running into this issue. Conda version 4.12.0, hangs forever on "Installing pip dependencies".

Running macOS Monterey on Intel Macbook pro.

@rinukkusu
Copy link

Same on Windows 10 with version 4.13.0.
This is really frustrating.

@avbentem
Copy link

avbentem commented Sep 7, 2022

Horrendous oneliner for dockerfile

Looks wonderfu! But no cigar for me. Just some details in case someone else is still not seeing output:

Somehow this does not work for me when using Mamba in Docker on a Mac: silent as ever, until done and then showing the logging after the fact, after first printing "Ran pip subprocess with arguments" and sometimes also Docker's "[output clipped, log limit 1MiB reached]".

I did not investigate a lot yet; the clipping may even be related to BuildKit for what I've read.

Exact command that does not print logging until done
FROM continuumio/miniconda3:latest
...
RUN export PIP_LOG="/tmp/pip_log.txt" && touch ${PIP_LOG} && tail -f ${PIP_LOG} & mamba env create -n myenv --file conda_environment.yml && conda clean --all && killall tail && rm ${PIP_LOG}

@lpasselin
Copy link

@avbentem I tested with your small example and it works for me on linux (docker 19.03.05). Replaced mamba with conda in your example.

logs when building on linux
lpasselin@appliedai-ws1:~/tmp$ ls -lahtr
total 16K
-rw-rw-r--  1 lpasselin lpasselin  234 Sep  7 13:44 conda_environment.yml
-rw-rw-r--  1 lpasselin lpasselin  275 Sep  7 13:44 Dockerfile
drwxr-xr-x 18 lpasselin lpasselin 4.0K Sep  7 13:44 ..
drwxrwxr-x  2 lpasselin lpasselin 4.0K Sep  7 13:44 .
lpasselin@appliedai-ws1:~/tmp$ docker build . --no-cache
Sending build context to Docker daemon  3.072kB
Step 1/3 : FROM continuumio/miniconda3:latest
 ---> ce7d119281a1
Step 2/3 : COPY conda_environment.yml conda_environment.yml
 ---> 2411d2b767c4
Step 3/3 : RUN export PIP_LOG="/tmp/pip_log.txt" && touch ${PIP_LOG} && tail -f ${PIP_LOG} & conda env create -n myenv --file conda_environment.yml && conda clean --all && killall tail && rm ${PIP_LOG}
 ---> Running in 37e573cd9e1c
Collecting package metadata (repodata.json): ...working... done
Solving environment: ...working... done


==> WARNING: A newer version of conda exists. <==
  current version: 4.12.0
  latest version: 4.14.0

Please update conda by running

    $ conda update -n base -c defaults conda



Downloading and Extracting Packages
libgomp-11.2.0       | 560 KB    | ########## | 100%
_openmp_mutex-5.1    | 20 KB     | ########## | 100%
ld_impl_linux-64-2.3 | 732 KB    | ########## | 100%
readline-8.1.2       | 423 KB    | ########## | 100%
wheel-0.37.1         | 31 KB     | ########## | 100%
libstdcxx-ng-11.2.0  | 6.1 MB    | ########## | 100%
certifi-2022.6.15    | 156 KB    | ########## | 100%
xz-5.2.5             | 389 KB    | ########## | 100%
ncurses-6.3          | 1.1 MB    | ########## | 100%
sqlite-3.39.2        | 1.5 MB    | ########## | 100%
ca-certificates-2022 | 131 KB    | ########## | 100%
tk-8.6.12            | 3.3 MB    | ########## | 100%
libffi-3.3           | 54 KB     | ########## | 100%
_libgcc_mutex-0.1    | 3 KB      | ########## | 100%
libgcc-ng-11.2.0     | 8.5 MB    | ########## | 100%
openssl-1.1.1q       | 3.8 MB    | ########## | 100%
zlib-1.2.12          | 130 KB    | ########## | 100%
setuptools-61.2.0    | 1.3 MB    | ########## | 100%
pip-21.1.2           | 2.0 MB    | ########## | 100%
python-3.8.13        | 22.7 MB   | ########## | 100%
Preparing transaction: ...working... done
Verifying transaction: ...working... done
Executing transaction: ...working... done
Installing pip dependencies: ...working... Ran pip subprocess with arguments:
['/opt/conda/envs/myenv/bin/python', '-m', 'pip', 'install', '-U', '-r', '/condaenv.qcjrhpho.requirements.txt']
Pip subprocess output:
Collecting seaborn
  Downloading seaborn-0.12.0-py3-none-any.whl (285 kB)
Collecting numpy>=1.17
  Downloading numpy-1.23.2-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (17.1 MB)
Collecting matplotlib>=3.1
  Downloading matplotlib-3.5.3-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.whl (11.3 MB)
Collecting pandas>=0.25
  Downloading pandas-1.4.4-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (11.7 MB)
Collecting packaging>=20.0
  Downloading packaging-21.3-py3-none-any.whl (40 kB)
Collecting fonttools>=4.22.0
  Downloading fonttools-4.37.1-py3-none-any.whl (957 kB)
Collecting pyparsing>=2.2.1
  Downloading pyparsing-3.0.9-py3-none-any.whl (98 kB)
Collecting python-dateutil>=2.7
  Downloading python_dateutil-2.8.2-py2.py3-none-any.whl (247 kB)
Collecting cycler>=0.10
  Downloading cycler-0.11.0-py3-none-any.whl (6.4 kB)
Collecting kiwisolver>=1.0.1
  Downloading kiwisolver-1.4.4-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.whl (1.2 MB)
Collecting pillow>=6.2.0
  Downloading Pillow-9.2.0-cp38-cp38-manylinux_2_28_x86_64.whl (3.2 MB)
Collecting pytz>=2020.1
  Downloading pytz-2022.2.1-py2.py3-none-any.whl (500 kB)
Collecting six>=1.5
  Downloading six-1.16.0-py2.py3-none-any.whl (11 kB)
Installing collected packages: six, pyparsing, pytz, python-dateutil, pillow, packaging, numpy, kiwisolver, fonttools, cycler, pandas, matplotlib, seaborn
Successfully installed cycler-0.11.0 fonttools-4.37.1 kiwisolver-1.4.4 matplotlib-3.5.3 numpy-1.23.2 packaging-21.3 pandas-1.4.4 pillow-9.2.0 pyparsing-3.0.9 python-dateutil-2.8.2 pytz-2022.2.1 seaborn-0.12.0 six-1.16.0

done
#
# To activate this environment, use
#
#     $ conda activate myenv
#
# To deactivate an active environment, use
#
#     $ conda deactivate

Cache location: /opt/conda/pkgs
Will remove the following tarballs:

/opt/conda/pkgs
---------------
python-3.8.13-h12debd9_0.tar.bz2            22.7 MB
openssl-1.1.1q-h7f8727e_0.tar.bz2            3.8 MB
xz-5.2.5-h7f8727e_1.tar.bz2                  389 KB
certifi-2022.6.15-py38h06a4308_0.tar.bz2     156 KB
setuptools-61.2.0-py38h06a4308_0.tar.bz2     1.3 MB
_openmp_mutex-5.1-1_gnu.tar.bz2               20 KB
ca-certificates-2022.07.19-h06a4308_0.tar.bz2     131 KB
libstdcxx-ng-11.2.0-h1234567_1.tar.bz2       6.1 MB
ncurses-6.3-h5eee18b_3.tar.bz2               1.1 MB
libgcc-ng-11.2.0-h1234567_1.tar.bz2          8.5 MB
zlib-1.2.12-h7f8727e_2.tar.bz2               130 KB
wheel-0.37.1-pyhd3eb1b0_0.tar.bz2             31 KB
readline-8.1.2-h7f8727e_1.tar.bz2            423 KB
_libgcc_mutex-0.1-main.tar.bz2                 3 KB
tk-8.6.12-h1ccaba5_0.tar.bz2                 3.3 MB
sqlite-3.39.2-h5082296_0.tar.bz2             1.5 MB
pip-21.1.2-py38h06a4308_0.tar.bz2            2.0 MB
ld_impl_linux-64-2.38-h1181459_1.tar.bz2     732 KB
libgomp-11.2.0-h1234567_1.tar.bz2            560 KB
libffi-3.3-he6710b0_2.tar.bz2                 54 KB

---------------------------------------------------
Total:                                      52.9 MB

Proceed ([y]/n)?
Removed python-3.8.13-h12debd9_0.tar.bz2
Removed openssl-1.1.1q-h7f8727e_0.tar.bz2
Removed xz-5.2.5-h7f8727e_1.tar.bz2
Removed certifi-2022.6.15-py38h06a4308_0.tar.bz2
Removed setuptools-61.2.0-py38h06a4308_0.tar.bz2
Removed _openmp_mutex-5.1-1_gnu.tar.bz2
Removed ca-certificates-2022.07.19-h06a4308_0.tar.bz2
Removed libstdcxx-ng-11.2.0-h1234567_1.tar.bz2
Removed ncurses-6.3-h5eee18b_3.tar.bz2
Removed libgcc-ng-11.2.0-h1234567_1.tar.bz2
Removed zlib-1.2.12-h7f8727e_2.tar.bz2
Removed wheel-0.37.1-pyhd3eb1b0_0.tar.bz2
Removed readline-8.1.2-h7f8727e_1.tar.bz2
Removed _libgcc_mutex-0.1-main.tar.bz2
Removed tk-8.6.12-h1ccaba5_0.tar.bz2
Removed sqlite-3.39.2-h5082296_0.tar.bz2
Removed pip-21.1.2-py38h06a4308_0.tar.bz2
Removed ld_impl_linux-64-2.38-h1181459_1.tar.bz2
Removed libgomp-11.2.0-h1234567_1.tar.bz2
Removed libffi-3.3-he6710b0_2.tar.bz2
WARNING: /root/.conda/pkgs does not exist
Cache location: /opt/conda/pkgs
Will remove the following packages:
/opt/conda/pkgs
---------------

_libgcc_mutex-0.1-main                         7 KB
_openmp_mutex-5.1-1_gnu                      102 KB

---------------------------------------------------
Total:                                       109 KB

Proceed ([y]/n)?
removing _libgcc_mutex-0.1-main
removing _openmp_mutex-5.1-1_gnu
/bin/sh: 1: killall: not found
The command '/bin/sh -c export PIP_LOG="/tmp/pip_log.txt" && touch ${PIP_LOG} && tail -f ${PIP_LOG} & conda env create -n myenv --file conda_environment.yml && conda clean --all && killall tail && rm ${PIP_LOG}' returned a non-zero code: 127
Dockerfile and conda_environment.yml Dockerfile ````Dockerfile FROM continuumio/miniconda3:latest COPY conda_environment.yml conda_environment.yml RUN export PIP_LOG="/tmp/pip_log.txt" && touch ${PIP_LOG} && tail -f ${PIP_LOG} & conda env create -n myenv --file conda_environment.yml && conda clean --all && killall tail && rm ${PIP_LOG} ````

conda_environment.yml

name: devcontainer_environment
channels:
  - default
  - anaconda
  - conda-forge
dependencies:
  - python==3.8.13
  - pip==21.1.2
  - pip:
      - seaborn

@brmarkus
Copy link

For later phases of the env creating the log-file works great.
However, in my case the phase Solving environment: ...working... is taking forever ... and no logs were created :-(

@stefansjs
Copy link

So subprocess has issues with large stdout buffers. Essentially once it's full it will stop consuming, and might even block the underlying subprocess if it's implemented to block on stdout.

the executor package does have a solution to this where it writes to a temporary file, and optionally reads that back for real-time monitoring of logs https://executor.readthedocs.io/en/latest/api.html#executor.ExternalCommand.buffered

Since pip can really go off the rails with output, it's not a good idea to try and stream the output of pip using subprocess without some extra stream buffer handling.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: 🆕 New
Development

No branches or pull requests