Better reporting on output from PEP 517 build backends

[konstin]

Currently, pip install and pip wheel on a PEP 517 compliant source tree hides all output on stdout and stderr from the build backend. Only if an error occurs, both are printed (though it sometimes misses parts of stdout). This means you can't show the user any information about the progress of long compilations (or even that it's still progressing and hasn't got stuck anywhere). It also hides any warnings.

Is there any designated way to communicate from build backends to the user, and if not, would it be possible for pip to forward the stdout and/or stderr from build backends?

Running with -v is also problematic because it contains lots of noise, duplicates the build backend's output in case of errors and prints an irrelevant stack trace. (Apparently, there's no difference between -v, -vv and -vvv with pip install). The current output capturing also means that all tools checking for a tty won't output any color, making error and log messages less readable.

[cjerdonek]

Running with -v is also problematic because it contains lots of noise, duplicates the build backend's output in case of errors and prints an irrelevant stack trace.

I think improving these things would be good, for a start. The second two seem pretty easy to address. (There is a separate issue to let people make the logs less noisy.)

[pradyunsg]

Thanks for filing this @konstin!

I think that this is related to more granular support for logging, something in the scope of #6119. Preventing the duplicated output in verbose mode should be much easier to tackle independently though.

---

PS: Put this in the wrong milestone; really need to move away from those. :)

[cjerdonek]

Also, what version of pip are you using?

[konstin]

pip 19.1.1. However this isn't related to any particular pip or python release, e.g. pip 19.0 shows the same behaviour.

[cjerdonek]

Can you paste in an example of the duplicated output in case of errors using the latest pip (19.1.1), with the irrelevant stack trace you were referring to, when verbose mode is used? You should leave in pip's intro / prefix text for the subprocess calls and error but you can remove unrelated lines to make the paste shorter.

[konstin]

I've created a gist with the full output: https://gist.github.com/konstin/20c5efdfcb87c34271dcc6157c684753. The find-links is for the wheel containing the build backend I'm working on.

The interesting part:

  Installing collected packages: pycparser, cffi


  Successfully installed cffi-1.12.3 pycparser-2.19
  Cleaning up...
  Cleaned build tracker '/tmp/pip-req-tracker-ol3ors44'
  Installing backend dependencies ... done
    Running command /home/konsti/pyo3-pack/venv/bin/python /home/konsti/pyo3-pack/venv/lib/python3.6/site-packages/pip/_vendor/pep517/_in_process.py prepare_metadata_for_build_wheel /tmp/tmpk1v_d2zq
    PRINTED TO STDERR
    PRINTED TO STDOUT
    Running `pyo3-pack pep517 write-dist-info --metadata-directory /tmp/pip-req-build-sphjswqi/pip-wheel-metadata --bindings=cffi`
    🐍 Using CPython 3.6m at python to generate the cffi bindings
    cffi_pure-0.1.0.dist-info

    Preparing wheel metadata ... done
  Source in /tmp/pip-req-build-sphjswqi has version 0.1.0, which satisfies requirement cffi-pure==0.1.0 from file:///home/konsti/pyo3-pack/test-crates/cffi-pure
  Removed cffi-pure==0.1.0 from file:///home/konsti/pyo3-pack/test-crates/cffi-pure from build tracker '/tmp/pip-req-tracker-ol3ors44'
Building wheels for collected packages: cffi-pure
  Created temporary directory: /tmp/pip-wheel-co8lln7h
  Destination directory: /tmp/pip-wheel-co8lln7h
  Running command /home/konsti/pyo3-pack/venv/bin/python /home/konsti/pyo3-pack/venv/lib/python3.6/site-packages/pip/_vendor/pep517/_in_process.py build_wheel /tmp/tmpumvwc0_7
     Compiling cffi-pure v0.1.0 (/tmp/pip-req-build-sphjswqi)
  error: Could not compile `cffi-pure`.

  To learn more, run the command again with --verbose.
  💥 pyo3-pack failed
  Cargo build finished with "exit code: 101": `cargo rustc --message-format json --manifest-path Cargo.toml --lib --`
  Failed to build a native library through cargo
  PRINTED TO STDERR
  PRINTED TO STDOUT
  Running `pyo3-pack build -i python --no-sdist --bindings=cffi`
  Error: Command '['pyo3-pack', 'build', '-i', 'python', '--no-sdist', '--bindings=cffi']' returned non-zero exit status 1.
  Building wheel for cffi-pure (PEP 517) ... error
  ERROR: Failed building wheel for cffi-pure
  Running setup.py clean for cffi-pure
  Running command /home/konsti/pyo3-pack/venv/bin/python -u -c 'import setuptools, tokenize;__file__='"'"'/tmp/pip-req-build-sphjswqi/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' clean --all
  Traceback (most recent call last):
    File "<string>", line 1, in <module>
  ModuleNotFoundError: No module named 'setuptools'
  ERROR: Failed cleaning build dir for cffi-pure
Failed to build cffi-pure
Cleaning up...
  Removing source in /tmp/pip-req-build-sphjswqi
Removed build tracker '/tmp/pip-req-tracker-ol3ors44'
ERROR: Could not build wheels for cffi-pure which use PEP 517 and cannot be installed directly
Exception information:
Traceback (most recent call last):
  File "/home/konsti/pyo3-pack/venv/lib/python3.6/site-packages/pip/_internal/cli/base_command.py", line 178, in main
    status = self.run(options, args)
  File "/home/konsti/pyo3-pack/venv/lib/python3.6/site-packages/pip/_internal/commands/install.py", line 385, in run
    ", ".join(r.name for r in build_failures)))
pip._internal.exceptions.InstallationError: Could not build wheels for cffi-pure which use PEP 517 and cannot be installed directly

I've just realized that the duplicate output is actually due to get_requires_for_build_wheel being called before build_wheel, so that's actually fine. The traceback is at the end showing some of pip's internal call hierarchy, and there's another one about the missing setuptools. I don't see the tracebacks themselves as distinct problems, but rather as part of -v being too noisy for being a simple solution for the default verbosity not showing any output at all.

I can make a reproducible example tomorrow, if required. The project pyo3-pack and a 0.7.0-beta.1 should be published to pypi as soon as travis ci is finished

[cjerdonek]

What solution are you proposing? The problem I see is that if the output is shown by default, then that could be too noisy for most users. Are you suggesting an option "between" verbose and default, where the default log messages are shown, plus the output from the subprocesses? Or are you suggesting verbose showing less in general?

(I do agree the tracebacks can be cleaned up, btw.)

[cjerdonek]

The traceback is at the end showing some of pip's internal call hierarchy, and there's another one about the missing setuptools.

Is the first traceback actually from pip? It looks like that one is coming from the underlying subprocess.

[cjerdonek]

Maybe one way to improve the situation could be to better delineate the output from the subprocess, e.g. by prefixing each line or putting some kind of divider at the beginning and end.

[cjerdonek]

I'm marking this "discussion needed" instead of "awaiting PR" because I think it would be good to discuss what a PR should do before work goes into writing one. For example, some of the issues mentioned in the original post turned out not to be issues. Also, we might find that more than one improvement would be worth implementing, and so more than one PR.

[pradyunsg]

Sounds good to me @cjerdonek!

[konstin]

What solution are you proposing? The problem I see is that if the output is shown by default, then that could be too noisy for most users. Are you suggesting an option "between" verbose and default, where the default log messages are shown, plus the output from the subprocesses? Or are you suggesting verbose showing less in general?

pip install and pip wheel should stop capturing stdout and stderr when calling the build backend. sys.stdout.isatty() and sys.stderr.isatty() should stay true if they were true for pip. If forwarding stdout is too verbose with other build backends, only stderr should be forwarded.

Ideally, I think the combined output should look something like this, but with terminal colors and a progress bar that I can't show in markdown:

$ pip install .
Processing /home/konsti/pyo3-pack/test-crates/cffi-pure
Installing build dependencies ... done
Getting requirements to build wheel ... done
Installing backend dependencies ... done
Preparing wheel metadata ...
🐍 Using CPython 3.6m at python to generate the cffi bindings
Successfully prepared metadata for cffi-pure-0.1.0
Building wheel for cffi-pure (PEP 517)
   Compiling aho-corasick v0.7.3
   Compiling quote v0.6.12
   Compiling mashup-impl v0.1.9
   Compiling mashup v0.1.9
   Compiling pyo3 v0.7.0
   Compiling pyo3-derive-backend v0.7.0
   Compiling ctor v0.1.9
   Compiling inventory-impl v0.1.3
   Compiling ghost v0.1.0
   Compiling inventory v0.1.3
   Compiling pyo3cls v0.7.0
   Compiling pyo3-pure v2.1.0 (/home/konsti/pyo3-pack/test-crates/pyo3-pure)
    Finished dev [unoptimized + debuginfo] target(s) in 37.36s
Successfully built cffi-pure-0.1.0
Uninstalling existing installation cffi-pure-0.1.0 ... done
Installing collected packages: cffi-pure ... done
Successfully installed cffi-pure-0.1.0

Since we've already discussed it, the output of pip install . -v should become less verbose. I'd say at least the "Found link" / "Skipping link" lines and the InstallationError backtrace should go away. The output of -vv and -vvv is fine, those can also keep showing backtraces.

Is the first traceback actually from pip? It looks like that one is coming from the underlying subprocess.

Afaik that traceback comes from the setup.py fallback at _internal/req/req_install.py

Maybe one way to improve the situation could be to better delineate the output from the subprocess, e.g. by prefixing each line or putting some kind of divider at the beginning and end.

I think using Building XY and Successfully build XY/Failed to build XY makes a good delimiter. I'd like to avoid prefixing each line because that breaks isatty() and thereby terminal colors and progress bars.

I'm marking this "discussion needed" instead of "awaiting PR" because I think it would be good to discuss what a PR should do before work goes into writing one. For example, some of the issues mentioned in the original post turned out not to be issues. Also, we might find that more than one improvement would be worth implementing, and so more than one PR.

Totally agree; I opened the issue to discuss what the best solution for logging/error reporting would be. Just making pip not capture stdout and stderr took less time then writing up the initial post.

[cjerdonek]

It seems like six different issues or proposed improvements are being mentioned:

1. Verbose mode logs too many messages
2. The setup.py clean traceback isn't needed
3. The InstallationError traceback at the end isn't needed
4. The subprocess build output (stdout and/or stderr) shouldn't require verbose mode to display
5. The build output should forward directly to the console instead of going through pip when displayed (e.g. to take advantage of tty)
6. The beginning and end of the build output should be distinguished / delineated better (This was addressed by PR Fix #6651: Improve error message formatting when a command errors out #6655.)

To keep the discussions manageable, I think it would be best to separate these into different issues. Each one can be discussed separately, and any resolution / PR if it gets to that point could likely be implemented independent of the PR for any other. Here it seems like the interest is mainly in (4) and (5). I would suggest creating a new issue for each one you think should be addressed.

I started by creating an issue for (2) here: #6642
(But I'm not completely sure it's an issue after starting to investigate.)

[st-pasha]

What solution are you proposing? The problem I see is that if the output is shown by default, then that could be too noisy for most users. Are you suggesting an option "between" verbose and default, where the default log messages are shown, plus the output from the subprocesses? Or are you suggesting verbose showing less in general?

May I suggest the following solution, which seems to be minimally invasive:

Allow the build backend to request log = logging.getLogger("pip") (or more generally getLogger("build-frontend")), and then emit messages to pip via standard log.info(...), log.debug(...), log.warn(...), etc, with different levels of messages displayed or filtered out depending on the number of -vvvs in pip's arglist.

However, by itself this is not enough: users usually don't specify any verbose options, and having no indication of any progress is less than ideal. I would therefore suggest to also add a non-standard method log.progress(amount, message), which the backend can use to communicate to the frontend how far along it is. Then the users will see by default something like this:

Installing `mypackage`...
36% [#########                ]  Compiling something.cc  ETA 2m:34s

This would allow pip to stay in control of how much info gets displayed to the user, allowing flexibility to show as much or as little as requested. The only thing I'm not sure about is how to transmit the messages from the subprocess where the backend runs to the frontend, while at the same time capturing all stdout/stderr. But presumably there exist standard IPC channels in python?

[pfmoore]

May I suggest the following solution, which seems to be minimally invasive:

I'm not sure this is possible, as PEP 517 backends run in a separate subprocess, and have no access to pip's logging streams, or any other parts of pip's internal details. The only way a frontend like pip can communicate with a backend is via (a) the stdio streams of the backend (and backends are explicitly allowed to place arbitrary data on their stdio streams), (b) the return code of the backend, or (c) any custom IPC mechanism that we (or rather the pep517 library, which we use behind the scenes) implement to pass richer data between the subprocesses.

[st-pasha]

It is my understanding that PEP 517 puts the backend into a passive position, while giving the frontend full control over the process. Thus, the backend's job is merely to define and export function build_wheel(), while the frontend's responsibility is to locate and run that function, within an isolated environment.

So, a minimal frontend could simply create file "runscript.py", and then launch a subprocess with ["python", "runscript.py"]. The script would contain something along these lines

import {backend}
whl_file = {backend}.build_wheel({wheel_dir}, context=None)
print(whl_file)

(or use the pep517 module that you mentioned). Ultimately, it is the frontend that determines what gets included in the script. It might as well add import pip; pip.start_logger(). And at least some amount of communication between the script and the front is already necessary: the script has to inform the frontend of the file name that was returned from the build_wheel() function.

It is possible for the logger to use the stdout to pass its messages, provided they are formatted in a way that allows the frontend distinguish them from regular stdout output. Something like

<pip-logger/info>message, properly escaped</>
<pip-logger/progress>0.23 status string</>

P.S. I'm not very familiar with pep517 module yet, and where the line that separates responsibilities of pip and pep517 lies. Perhaps that module is a better place to implement this functionality?

[pradyunsg]

Running with -v is also problematic because it contains lots of noise, duplicates the build backend's output in case of errors and prints an irrelevant stack trace.

These issues are no longer a concern. We've improved handling of output from the build-backends in 22.0 and also reduced the verbosity of a single -v flag in releases since this issue was filed.

I'm going to go ahead and close this now -- I think we're in a good spot w.r.t. output handling from build backends, but if folks think there's specific improvements we can make, I'd like you to chip in at https://discuss.python.org/t/13779/ (you can log in via GitHub) since the relevant changes here likely affect more tools than just pip (at the very least, it affects build backends).

[konstin]

The 22.0 -v output is much better, thank you!