pip sometimes includes debug messages on stdout

[woodruffw]

This is an abbreviated copy of #115 and #116, since those have been filled up with additional debugging.

Summary: In rare cases (currently N=1), we fail to collect environmental dependencies from PipSource. PipSource uses pip-api internally, which boils down to pip list --format=json.

What seems to happen is that the pip list --format=json command doesn't emit just JSON. Instead, it also emits a trailing log message that looks like this:

Given no hashes to check 181 links for project 'pip': discarding no candidates

According to pip's source code, that message is produced by a call to log.debug, which should be going to stderr instead of stdout. pip-api only uses stdout from pip subprocesses, so this is a strong indicator that the two streams are being mixed and/or confused somewhere, potentially with a logging override. The original reporter also traced the process and confirmed that the log was produced on stdout.

The original reporter found this on Python 3.9, pip version 20.3.3. I was unable to reproduce it locally, and they were also unable to reliably reproduce it locally.

[di]

Another instance of this in #155 seems to indicate that it depends on what directory pip-audit is being run in.

[westonsteimel]

@woodruffw and @di, I am able to reliably reproduce this using the following Dockerfile:

FROM python:3.8.11-slim

RUN pip install \
    CacheControl==0.12.10 \
    certifi==2021.10.8 \
    charset-normalizer==2.0.9 \
    cyclonedx-python-lib==0.11.1 \
    html5lib==1.1 \
    idna==3.3 \
    lockfile==0.12.2 \
    msgpack==1.0.3 \
    packageurl-python==0.9.6 \
    packaging==21.3 \
    pip-api==0.0.25 \
    pip-audit==1.1.0 \
    progress==1.6 \
    pyparsing==3.0.6 \
    rapid-client==0.0.0 \
    requests==2.26.0 \
    requirements-parser==0.2.0 \
    resolvelib==0.8.1 \
    six==1.16.0 \
    toml==0.10.2 \
    types-setuptools==57.4.4 \
    types-toml==0.10.1 \
    urllib3==1.26.7 \
    webencodings==0.5.1 \
    pip==21.1.1 \
    setuptools==50.3.2 \
    --disable-pip-version-check

CMD ["pip-audit"]

docker run --rm -it <test-image-name>

Produces:

WARNING: You are using pip version 21.1.1; however, version 21.3.1 is available.
You should consider upgrading via the '/usr/local/bin/python -m pip install --upgrade pip' command.
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pip_audit/_dependency_source/pip.py", line 72, in collect
    for (_, dist) in pip_api.installed_distributions(
  File "/usr/local/lib/python3.8/site-packages/pip_api/_installed_distributions.py", line 94, in installed_distributions
    return _new_installed_distributions(local, paths)
  File "/usr/local/lib/python3.8/site-packages/pip_api/_installed_distributions.py", line 75, in _new_installed_distributions
    for raw_dist in json.loads(result):
  File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.8/json/decoder.py", line 340, in decode
    raise JSONDecodeError("Extra data", s, end)
json.decoder.JSONDecodeError: Extra data: line 2 column 1 (char 3190)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/bin/pip-audit", line 8, in <module>
    sys.exit(audit())
  File "/usr/local/lib/python3.8/site-packages/pip_audit/_cli.py", line 263, in audit
    for (spec, vulns) in auditor.audit(source):
  File "/usr/local/lib/python3.8/site-packages/pip_audit/_audit.py", line 60, in audit
    yield from self._service.query_all(specs)
  File "/usr/local/lib/python3.8/site-packages/pip_audit/_service/interface.py", line 115, in query_all
    for spec in specs:
  File "/usr/local/lib/python3.8/site-packages/pip_audit/_dependency_source/pip.py", line 91, in collect
    raise PipSourceError("failed to list installed distributions") from e
pip_audit._dependency_source.pip.PipSourceError: failed to list installed distributions

and

docker run --rm -it <test-image-name> pip list --format=json

Produces:

[{"name": "CacheControl", "version": "0.12.10"}, {"name": "certifi", "version": "2021.10.8"}, {"name": "charset-normalizer", "version": "2.0.9"}, {"name": "cyclonedx-python-lib", "version": "0.11.1"}, {"name": "html5lib", "version": "1.1"}, {"name": "idna", "version": "3.3"}, {"name": "lockfile", "version": "0.12.2"}, {"name": "msgpack", "version": "1.0.3"}, {"name": "packageurl-python", "version": "0.9.6"}, {"name": "packaging", "version": "21.3"}, {"name": "pip", "version": "21.1.1"}, {"name": "pip-api", "version": "0.0.25"}, {"name": "pip-audit", "version": "1.1.0"}, {"name": "progress", "version": "1.6"}, {"name": "pyparsing", "version": "3.0.6"}, {"name": "rapid-client", "version": "0.0.0"}, {"name": "requests", "version": "2.26.0"}, {"name": "requirements-parser", "version": "0.2.0"}, {"name": "resolvelib", "version": "0.8.1"}, {"name": "setuptools", "version": "50.3.2"}, {"name": "six", "version": "1.16.0"}, {"name": "toml", "version": "0.10.2"}, {"name": "types-setuptools", "version": "57.4.4"}, {"name": "types-toml", "version": "0.10.1"}, {"name": "urllib3", "version": "1.26.7"}, {"name": "webencodings", "version": "0.5.1"}, {"name": "wheel", "version": "0.37.0"}]
WARNING: You are using pip version 21.1.1; however, version 21.3.1 is available.
You should consider upgrading via the '/usr/local/bin/python -m pip install --upgrade pip' command.

I have observed that doing pip install without specifying --disable-pip-version-check corrects the problem

[westonsteimel]

Perhaps you could make use of --disable-pip-version-check within the pip list call in pip-api to get around it?

[woodruffw]

@westonsteimel thanks a ton for the in-depth debugging! I'll look into that workaround.

[woodruffw]

Yeah, so here's the message in question:

https://github.com/pypa/pip/blob/bbc7021cde307676a71e7a89e88a6fc20b8e2c26/src/pip/_internal/self_outdated_check.py#L170-L177

It's using logger.warning, so the underlying question of "why is it on stdout?" still isn't resolved. But I'll use your repro setup and, if it clears the problem for me too, we'll go ahead and fix it blindly 🙂

[woodruffw]

Okay, I'm also able to reliably reproduce the bug. If I do this:

docker run --rm -it pip-audit-bug pip list --format=json 2>/dev/null | less

I can see both the errant log and some terminal escapes are present on stdout:

I haven't fully dug through pip's logging code yet, but this looks like a bug. But even so we'll need a fix on our side for older pips. Working on one now.

[woodruffw]

Upstream (pip-api, not pip) fix: di/pip-api#114

[woodruffw]

Confirmed that the fix in di/pip-api#114 works!

Modified Dockerfile:

FROM python:3.8.11-slim

RUN apt update && apt install -y git

RUN pip install \
    CacheControl==0.12.10 \
    certifi==2021.10.8 \
    charset-normalizer==2.0.9 \
    cyclonedx-python-lib==0.11.1 \
    html5lib==1.1 \
    idna==3.3 \
    lockfile==0.12.2 \
    msgpack==1.0.3 \
    packageurl-python==0.9.6 \
    packaging==21.3 \
    git+git://github.com/woodruffw-forks/pip-api.git@ccdc0af0c9660d052756060992c8e539d7becedf \
    pip-audit==1.1.0 \
    progress==1.6 \
    pyparsing==3.0.6 \
    rapid-client==0.0.0 \
    requests==2.26.0 \
    requirements-parser==0.2.0 \
    resolvelib==0.8.1 \
    six==1.16.0 \
    toml==0.10.2 \
    types-setuptools==57.4.4 \
    types-toml==0.10.1 \
    urllib3==1.26.7 \
    webencodings==0.5.1 \
    pip==21.1.1 \
    setuptools==50.3.2 \
    --disable-pip-version-check

CMD ["pip-audit"]

Then:

docker build -t pip-audit-bug -f pip-audit-bug.dockerfile 
docker run --rm -it pip-audit-bug

Produces:

[woodruffw]

Will cut a release for this once there's a new pip-api release 🙂

[di]

Done: https://pypi.org/project/pip-api/0.0.26/

[woodruffw]

Fixed with #196!

[0-wiz-0]

I can confirm that this fixes the problem for me. Thank you!

[woodruffw]

Fantastic, thanks for confirming!