Called process error output doesn’t all go to stderr

[flying-sheep]

pip 19.1.1, Python: 3.8-dev, Ubuntu xenial

My travis build with Python 3.8 fails: https://travis-ci.org/theislab/scanpy/jobs/550248884#L285

The error occurs when trying to install scipy’s build requirements via pyproject.toml. Confusingly, it reports an environment marker not matching (and the subsequent ignoring of the dependency) as an error:

Installing build dependencies ... error
ERROR: Complete output from command
       …/python …/pip install --ignore-installed --no-user --prefix …/overlay \
       --no-warn-script-location --no-binary :none: --only-binary :none: \
       -i https://pypi.org/simple -- wheel setuptools 'Cython>=0.29.2' \
       'numpy==1.13.3; python_version=='"'"'3.5'"'"'' \
       'numpy==1.13.3; python_version=='"'"'3.6'"'"'' \
       'numpy==1.14.5; python_version>='"'"'3.7'"'"'':
ERROR: Ignoring numpy: markers 'python_version == "3.5"' don't match your environment 
Ignoring numpy: markers 'python_version == "3.6"' don't match your environment

As you can see, the subsequent ignoring of the second line is not reported as an error (as I would expect).

[cjerdonek]

This can be fixed by merging these two log messages into a single message:

pip/src/pip/_internal/utils/misc.py

Lines 835 to 839 in 0dbab23

	subprocess_logger.error(
	'Complete output from command %s:', command_desc,
	)
	# The all_output value already ends in a newline.
	subprocess_logger.error(''.join(all_output) + LOG_DIVIDER)

[flying-sheep]

Well, that would fix the part about one of two identical messages being reported as error.

But I still don’t understand what the error here is. It shouldn’t be an error if some environment marker in the build deps doesn’t match, that dep should simply be skipped.

[cjerdonek]

But I still don’t understand what the error here is.

It looks like you didn't provide all of the output towards the end. Is there more?

[flying-sheep]

The link in the issue descriptions goes there.

And you’re right! The real error(s) happen(s) later but due to only the first line being sent to stdout, I didn’t see that. It’s numpy/numpy#13790

[cjerdonek]

Okay, yeah, I saw after I clicked on it. Basically, this is a formatting / presentation issue IMO where we need to better delineate the beginning and end of the command output (the "Complete output from command" mentioned above).

[cjerdonek]

FYI, I posted PR #6655 to address this.

It would remove the confusing ERROR: before the "Ignoring numpy: ..." line, and it would also improve the formatting more generally. The beginning of the log message lines would look more like this:

ERROR: Command errored out with exit status 1:
 command: /home/travis/virtualenv/python3.8-dev/bin/python ...
     cwd: /tmp/pip-install-12n4c4tn/numpy/
Complete output (7500 lines):
Ignoring numpy: markers 'python_version == "3.5"' don't match your environment 
Ignoring numpy: markers 'python_version == "3.6"' don't match your environment
...
...
...
----------------------------------------

[cjerdonek]

@flying-sheep What is making you think the output is not all going to stderr? It should all already have been going to stderr in the error case you encountered since the log message(s) were logged at ERROR level.

[flying-sheep]

Check out the link to the build failure. The line

ERROR: Ignoring numpy: markers 'python_version == "3.5"' don't match your environment

is red, i.e. on stderr, while the subsequent line

Ignoring numpy: markers 'python_version == "3.6"' don't match your environment

is gray, i.e. on stdout.

[cjerdonek]

Okay, thanks. That’s actually just an issue with the coloring getting applied to the log message. All those lines are still going to stderr (the subprocess error gets logged as one giant ~7500 line message). It’s just that only the first line of the error message is colored. That should probably be filed as a separate issue.

[flying-sheep]

Ah. Is that a travis bug then? I assume travis colors the stderr stuff?

[cjerdonek]

pip is doing the coloring using a third-party module. More likely the issue is with how pip is doing its logging in conjunction with the coloring. Feel free to open a new issue for that.

[flying-sheep]

Sure, this one is muddied enough as it is by my confusion