Improve logging on build failure by displaying file contents of `meson-log.txt`

[rgommers]

The current output from pip when encountering a build error is very poor. gh-231 will fix one part of that, by reducing the traceback of irrelevant pip/meson-python internals. There is a second part however which we need to improve on, which is showing the actual root cause of a build failure when possible. Now what happens is the user sees something like:

../../scipy/meson.build:40:0: ERROR: Command "/usr/bin/python3 -c import os; os.chdir(".."); import numpy; print(numpy.get_include())" failed with status 1.

A full log can be found at /tmp/pip-install-3okqoo15/scipy_a5afe2fae16c4250875f20d9db43706f/.mesonpy-u88p7q3f/build/meson-logs/meson-log.txt

and is then left wondering "why does import numpy fail, given numpy is a build dependency?". The answer is in meson-log.txt, which pip has unhelpfully already cleaned up. So it's impossible to diagnose the issue (latest example for scipy here).

Two options to improve here that I can think of:

1. Don't clean up the log file
2. Print to log file contents to stdout (possibly followed by repeating the root cause from the original stdout content)

(2) is probably better than (1).

[rgommers]

Follow-up: the way to not clean up the build dir (and hence the log file) is:

pip install . --config-settings=builddir=build

I'm not sure that that is guaranteed to stay working, it seems like a side-effect of the way Project.with_temp_working_dir is implemented. And it's actually meson-python that cleans things up; pip's --no-clean works as advertised for the build env itself.

[FFY00]

And it's actually meson-python that cleans things up; pip's --no-clean works as advertised for the build env itself.

We should consider this a bug, I think. There's no reason for us to clean things up on errors.

[rgommers]

I think we should do both avoid cleaning up ourselves and improve terminal output. Right now I think pip will still clean up for a regular isolated build, so the user trying to diagnose a build failure still has a problem.

[rgommers]

I had a look at this, it's a little complex with multiple nested context managers and a subprocess, so let me add my thoughts here first. This is the code in question that yields a new Project instance in a tmpdir:

https://github.com/mesonbuild/meson-python/blob/eacd23a31bf95036851ff3f3b6b7905ed1577394/mesonpy/init.py#L827-L829

That'll be something like .mesonpy-2tl1hhkq inside the current source dir. I'm thinking:

• the build front-end is responsible for creating a tmpdir and cleaning it up (or not, if the user uses --no-clean)
• in meson-python, we should remove any use of tempfile (which is only the lines above)
• what we want to do instead I think is create a regular directory with the same scheme (.mesonpy-<random-string-to-avoid-collisions>.

That would fix half of this issue. The other half (figuring out if and when to access meson-log.txt) is more tricky, so I'd start with not cleaning up here to make the problem easier to diagnose in local builds.

[dnicolodi]

I think there is some confusion on what is the role of the different directories. There are four relevant directories: the source directory, the build directory, the artifacts directory, the isolated build environment.

A good starting point to look at this is the PEP517 hook functions https://peps.python.org/pep-0517/#mandatory-hooks Let's take build_wheel() an example. The signature of this function is build_wheel(wheel_directory, config_settings=None, metadata_directory=None). The wheel_directory is the build artifacts directory, where the wheel should be placed. Clearly this should survive the build, thus is not a temporary build location. config_settings is a dictionary with the user settings. No directories there. metadata_directory is optional and for simplicity we can ignore it.

So the information that the backend explicitly gets from the frontend is only the artifacts directory. PEP 517 is not explicit on this, but it is assumed that the current working directory when the hooks are invoked is the source directory. The isolated build environment is the the Python environment executing the hook. There is no facility to pass a build directory.

I haven't found much information in the pip documentation, but looking at the pip source code, the --no-clean option refers to the build directories used by pip to download dependencies and eventually unpack sdists, not to build directories passed to the build backend. Indeed, pypa/build does not have an equivalent command line option.

The current meson-python behavior of creating a temporary build directory and cleaning it up on success is the current one.

I'm not sure that not cleaning up the temporary build directory on error is a good idea. I expect this to result in the users ending up with multiple .mesonpy-$random directories, without a clear way to distinguish them. I think that outputing the whole of meson-log.txt on error is not a great idea either. It can be very long and most often the cause for meson setup failing is easy to identify in the regular meson setup output. I would place that behind an option for extra verbose output. However, if it is behind an option, it would require the user to run the build again to get the verbose output. If this is is the case, the user can simply pass -Cbuilddir=foo and then do cat foo/meson-logs/meson-log.txt.

Why do not show meson-log.txt by default? I don't think it is useful in most circumstances and is an overwhelming amount of output. I think that the most common meson setup failures are errors in meson.build or missing dependencies. The content of meson-log.txt is not useful for diagnosing the first king of errors, and only seldomly useful for diagnosing the latter.

I think that this issue would be better solved with a bit of documentation. We could add a Debugging the build section to the manual where the python -m pip install -Cbuilddir=build . and cat build/meson-logs/meson-log.txt is explained.

[rgommers]

the --no-clean option refers to the build directories used by pip to download dependencies and eventually unpack sdists, not to build directories passed to the build backend.

Your description of the various directories sounds right to me. I believe --no-clean applies to downloaded sources from the package that is being built too - and in those cases, since the build starts from within that source dir, it therefore applies to the build dir as well.

I'm not sure that not cleaning up the temporary build directory on error is a good idea. I expect this to result in the users ending up with multiple .mesonpy-$random directories, without a clear way to distinguish them.

That is fair. I don't think we necessarily need the $random bit though. What setup.py based builds do is simply not use a tmpdir and create a dir named build inside the directory in which the build is invoked. This is simply left there. I don't think there's much wrong with that. We could do the same with our new default naming scheme (build/<abi-tag>). Then what happens is:

• the frontend is responsible for cleaning up when sources are downloaded from PyPI or GitHub directly (and --no-clean will then preserve source and build dirs)
• for a local build (e.g., pip wheel .) the default build dir remains available.

Why do not show meson-log.txt by default? I don't think it is useful in most circumstances and is an overwhelming amount of output.

Yes, I agree with this. I left it alone for now because this is clearly going to be confusing. Ideally I'd like to show only relevant content (e.g. last N lines of meson-log.txt if and only if the answer is hidden in there), but it's unclear if that's achievable. Let's pause on this part - the build-dir cleanup part is better to deal with first.

[dnicolodi]

Your description of the various directories sounds right to me.

It is not completely right, though. When I wrote it, I was thinking of the case of installing a local package, not an sdist downloaded from PyPI. In that case indeed the build directory created by meson-python is in the source directory that gets cleaned up by pip.

I'm not sure not cleaning up the build directory and leaving it to the build front-end to do that is of much help. How obvious is where the build directory is located when python -m pip install --no-clean is invoked? I just tried it and I've absolutely no clue of where to look for the build directory. The only way to discover it is to increase the verbosity of pip and look for the compilation log.

python -m pip install --no-clean --no-binary=siphash24 siphash24 --force-reinstall

results in a source directory located in /private/var/folders/6f/4l4d5n9x1y71cxyrprf_x35c0000gn/T//pip-install-qarix6w3/siphash24_e9768ce23fbc4806b9132cf1687685c8. macOS uses funny looking temporary directories, but even the part that is solely under the control of pip is hard to make sense of.

On the other hand, I can pass an explicit build directory

python -m pip install --config-settings=builddir=$(pwd)/build --no-binary=siphash24 siphash24 --force-reinstall

and the build directory and the build log are exactly where I want. The only tricky part is that an absolute path needs to be passed to builddir= because when pip invokes the build system the cwd is changed to the package source directory.

However, this does not work when installing more than one package as the builddir=$(pwd)/build option cannot be assumed to be understood by the build system of every package, and similarly when the package to debug is a dependency of the package that is actually being installed. Both, however, can be simplified to the case of a single package to be installed, without any loss, I think.

[rgommers]

How obvious is where the build directory is located when python -m pip install --no-clean is invoked? I just tried it and I've absolutely no clue of where to look for the build directory

You will when the build fails, because Meson gives you the full path to the meson-log.txt file that may contain the clue to your build failure. And that's the point here - you just copy the path from Meson's terminal output, and the file will actually exist.

[dnicolodi]

Indeed, that's right. The output looks something like this with pip:

$ python -m pip wheel .
Processing /Users/daniele/src/meson-python/tests/packages/complex
  Installing build dependencies ... done
  Getting requirements to build wheel ... done
  Preparing metadata (pyproject.toml) ... error
  error: subprocess-exited-with-error

  × Preparing metadata (pyproject.toml) did not run successfully.
  │ exit code: 1
  ╰─> [17 lines of output]
      The Meson build system
      Version: 1.1.0
      Source dir: /Users/daniele/src/meson-python/tests/packages/complex
      Build dir: /Users/daniele/src/meson-python/tests/packages/complex/.mesonpy-4gnlztqx/build
      Build type: native build
      Project name: complex
      Project version: 1.0.0
      C compiler for the host machine: ccache cc (clang 14.0.0 "Apple clang version 14.0.0 (clang-1400.0.29.202)")
      C linker for the host machine: cc ld64 820.1
      Cython compiler for the host machine: cython (cython 0.29.34)
      Host machine cpu family: x86_64
      Host machine cpu: x86_64

      ../../meson.build:11:0: ERROR: Problem encountered: error

      A full log can be found at /Users/daniele/src/meson-python/tests/packages/complex/.mesonpy-4gnlztqx/build/meson-logs/meson-log.txt
      + meson setup /Users/daniele/src/meson-python/tests/packages/complex /Users/daniele/src/meson-python/tests/packages/complex/.mesonpy-4gnlztqx/build -Dbuildtype=release -Db_ndebug=if-release -Db_vscrt=md --native-file=/Users/daniele/src/meson-python/tests/packages/complex/.mesonpy-4gnlztqx/build/meson-python-native-file.ini
      [end of output]

  note: This error originates from a subprocess, and is likely not a problem with pip.
error: metadata-generation-failed

× Encountered error while generating package metadata.
╰─> See above for output.

note: This is an issue with the package mentioned above, not pip.
hint: See above for details.

I don't know why the line indicating the command that is being executed comes after the output of the command. I think having it before the output makes the log easier to understand. Adding flush=True to the print() call achieves just that. I'll prepare a PR.

I like the fact that meson-python does not leave behind a build directory. However, I appreciate that being able to get to the build log is important. However, to be able to get to the Meson log file when not installing a package from local sources, the --no-clean flag needs to be passed to pip. If a flag needs to be passed, is having to pass the build directory explicitly a worst solution?

I'm ok with using a build/$abi/ directory but this makes the issue of what to do if the directory already exist much more important: before this could only happen if the user specified a build directory, after this change it would be a much more common occurrence. Another issue is whether we need to detect when meson-python is trying to use a build directory that was not created by meson-python itself.

What do other build backend do? I wish the PEPs provided some guidelines for this.

[rgommers]

However, to be able to get to the Meson log file when not installing a package from local sources, the --no-clean flag needs to be passed to pip. If a flag needs to be passed, is having to pass the build directory explicitly a worst solution?

Maybe not all that different indeed. It's better if both worked, because I suspect quite a few people will retry with --no-clean rather than read our docs. The "from local sources case has a bigger difference though: there pip does not clean up, so the link to the log file would be there if we'd also avoid cleaning up.

I'm ok with using a build/$abi/ directory but this makes the issue of what to do if the directory already exist much more important:

Yes, that is true. It may actually be a good thing? Say you do local development first, and then a pip install .. That'd work well with caching and avoid rebuilding from scratch.

What do other build backend do?

setuptools writes to build/. not sure what other build backends do.

[dnicolodi]

If we use a stable build directory, I am not sure about what should happen when a package is build twice with different configurations (either meson arguments passed via the command line or via pyproject.toml). Currently, if we detect that the build directory is a valid build directory, we just issue a meson setup --reconfigure and apply the settings. This is done on the assumption that this happens only when the user explicitly specifies a build directory, thus they most likely know what they are doing. However, if a stable build directory is used, also unaware users may be surprised by the behavior. For example:

python -m build -w . -Csetup-args=-Ddebug=true

would generate a wheel with debug symbols. Then the user changes his mind and wants a regular wheel. Executing

python -m build -w .

would still generate a wheel with debug symbols, because the -Ddebug=true is already set in the build directory and meson setup --reconfigure changes only the options that are explicitly set. At least build shows the compilation log, thus there is a small chance that the user notices this. However, pip does not show the compilation log, unless the build fails, thus this is hard to notice.

[bmerry]

For CI purposes (and particularly cibuildwheel, which doesn't really provide options to control what happens after a failed build) it would be useful to have an option (maybe passable via config-settings) to print out the meson log on failure. That'll be much easier to use than having to write a wrapper script that parses the error message to figure out where the build log got written (or whether it got written) and dumping it.

[dnicolodi]

Given a build directory, the location of the meson logs is know, thus there is no need to parse the build output to get it. If a build directory is not specified, meson-python uses a temporary build directory that is cleaned up as soon as the build finishes, thus the hypothetical script would not be able to retrieve the meson log anyway. Part of the discussion here is about making the build directory not to be a temporary directory by default, thus allow to easily extract the meson log.

A config settings option to dump the meson log could be an idea. How should such an option be named? Anything that contains the word debug is somehow ambiguous because it may be confused for an option that enabled debug options for the project being build.

[bmerry]

A config settings option to dump the meson log could be an idea. How should such an option be named

How about 'print-log', with options 'none' (default), 'on-error' and 'always'? One downside is that it might not be clear that this isn't logs from the actual compilations; so maybe 'print-configure-log'.

That could be a useful addition to mesonbuild itself rather than just for meson-py, in which case it would be passed as -Csetup-args=--print-log=on-error.

[dnicolodi]

One issue is that the detailed setup log can be many thousands of line long and is most often not necessary to debug meson setup failures. On the contrary, showing the detailed log, would most likely make the reason for the failure much more difficult to spot, unless the user scrolls back to the regular meson output. In a regular meson build, the detailed log location is output on failure and it is trivial to examine the log. The problem arises in CI environment where having access to anything else than the commands output is more complex.

However, if you want to debug a meson setup failure in CI, it is already straightforward to get the log:

python -m build -w . -Cbuilddir=build || cat build/meson-logs/meson-log.txt

cibuildwheel AFAIK does not allow to customize the command used to build the package, or to execute a command on failure. Maybe a CIBW_ON_FAILURE_COMMAND configuration entry could be added? @henryiii

[dnicolodi]

Another aspect to consider is that having a print-log option requires running the setup stage one more time to get the log after the user encounters a failure. While having the log available on the filesystem for inspection does not require running the build again, or knowing about the setting.

[rgommers]

However, if you want to debug a meson setup failure in CI, it is already straightforward to get the log:

This is useful I think, we should probably add that to the docs. In GitHub Actions jobs, having this log as a separate job step so it doesn't interfere with reading the regular output that came before is useful:

    - name: Show meson-log.txt
      if: always()
      run: cat build/meson-logs/meson-log.txt

[dnicolodi]

In Github Actions, there is also a way to tag output in a way that it is hidden by default, and you need to click on the small arrow to display it https://docs.github.com/en/actions/using-workflows/workflow-commands-for-github-actions#grouping-log-lines

[rgommers]

Good point, I like how cibuildwheel uses that feature. It may be tricky to echo the log file after the build step though - it may not be run if the step has "halt on failure" behavior, or if it does get run it may change the exit status back to 0.

Once we figure out a nice way of showing the log here, it's something we may want to add to the docs.

[rgommers]

In Github Actions, there is also a way to tag output in a way that it is hidden by default, and you need to click on the small arrow to display it

Update: we've got this implemented in NumPy now (example log). While it's potentially helpful, the meson-log.txt output is ~10,000 lines long and even when it's hidden it causes the pytest output in the next foldout to become really slow to scroll. So I'm not 100% happy with that solution yet. We'll probably move it back to its own job step.

[rgommers]

Suggestion by @oscarbenjamin in https://github.com/mesonbuild/meson-python/discussions/602#discussioncomment-8870523:

[what] would be very helpful in this situation is an easy way to get it to show the full logs like a MESON_PYTHON_SHOW_LOGS environment variable

[oddbookworm]

This is even more annoying if you're using something else that directly invokes pip internally and you don't even have the option to specify a build-dir

[rgommers]

@oddbookworm note that every pip option can be specified as an environment variable for exactly this reason: https://pip.pypa.io/en/stable/topics/configuration/#environment-variables. So for a --config-settings flag, you can set PIP_CONFIG_SETTINGS instead (documented at https://pip.pypa.io/en/stable/cli/pip_install/#cmdoption-C).