--toolchain_resolution_debug output not ordered

[attilaolah]

Description of the problem / feature request:

When running a build with --toolchain_resolution_debug, the output lines seem to come in random order, each time different, making it really hard to debug the underlying issue.

Bugs: what's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

$ bazel build //any/target --toolchain_resolution_debug
$ bazel clean
$ bazel build //any/target --toolchain_resolution_debug
$ bazel clean
…
``

### What operating system are you running Bazel on?

Linux (Debian).

### What's the output of `bazel info release`?

release 3.5.0

###  Have you found anything relevant by searching the web?

Nope.

### Any other information, logs, or outputs that you want to share?

A possibly separate issue is that the flag itself doesn't always seem to work. If I invoke the same command several times, sometimes there is no debug output at all. But usually changing the flags or running `bazel clean` fixes the issue for the next run.

[katre]

This makes sense, but I'm not sure if I'll have time to tackle it.

The relevant code is in SingleToolchainResolutionFunction.resolveConstraints. I think the right approach is to sort the loop values (i.e., toolchains, availableExecutionPlatformKeys), and to do the same in checkConstraints for mismatchSettings.

The one trick is that we'd want to only sort when outputting debug information, because otherwise we're slowing down all toolchain resolution.

If you want to take a crack at it, I'd be happy to review a PR, otherwise it'd be nice to do but isn't a priority.

[dmitrig01]

Just ran into this. It makes this flag useless, as far as I can tell.

[nfelt]

I would like to +1 that with the current output this flag honestly provides net negative value in debugging because the output is so confusing. Here's a completely bare-bones example of the output I get on my gLinux workstation with Bazel 3.7.0 (which I realize is not latest, but it doesn't seem like much has changed other than converting the flag to take a regex filter).

Command:

cd $(mktemp -d) && touch WORKSPACE && printf 'genrule(name = "gen_foo", outs = ["foo.py"], cmd = "touch $@")\npy_binary(name = "foo", srcs = ["foo.py"])\n' > BUILD && bazel build --toolchain_resolution_debug=true :foo

Output:

Starting local Bazel server and connecting to it...
INFO: ToolchainResolution:   Type @bazel_tools//tools/python:toolchain_type: target platform @local_config_platform//:host: execution @local_config_platform//:host: Selected toolchain @bazel_tools//tools/python:_autodetecting_py_runtime_pair
INFO: ToolchainResolution:     Type @bazel_tools//tools/cpp:toolchain_type: target @local_config_platform//:host: Rejected toolchain @local_config_cc//:cc-compiler-armeabi-v7a; mismatching values: arm, android
INFO: ToolchainResolution:   Type @bazel_tools//tools/cpp:toolchain_type: target platform @local_config_platform//:host: execution @local_config_platform//:host: Selected toolchain @local_config_cc//:cc-compiler-k8
INFO: ToolchainResolution: Target platform @local_config_platform//:host: Selected execution platform @local_config_platform//:host, type @bazel_tools//tools/python:toolchain_type -> toolchain @bazel_tools//tools/python:_autodetecting_py_runtime_pair, type @bazel_tools//tools/cpp:toolchain_type -> toolchain @local_config_cc//:cc-compiler-k8
INFO: ToolchainResolution: Target platform @local_config_platform//:host: Selected execution platform @local_config_platform//:host,
INFO: ToolchainResolution: Target platform @local_config_platform//:host: Selected execution platform @local_config_platform//:host,
INFO: ToolchainResolution:     Type @bazel_tools//tools/cpp:toolchain_type: target @local_config_platform//:host: Rejected toolchain @local_config_cc//:cc-compiler-armeabi-v7a; mismatching values: arm, android
INFO: ToolchainResolution:   Type @bazel_tools//tools/cpp:toolchain_type: target platform @local_config_platform//:host: execution @local_config_platform//:host: Selected toolchain @local_config_cc//:cc-compiler-k8
INFO: ToolchainResolution: Target platform @local_config_platform//:host: Selected execution platform @local_config_platform//:host, type @bazel_tools//tools/cpp:toolchain_type -> toolchain @local_config_cc//:cc-compiler-k8
INFO: Analyzed target //:foo (19 packages loaded, 86 targets configured).
INFO: Found 1 target...
Target //:foo up-to-date:
  bazel-bin/foo.py
  bazel-bin/foo
INFO: Elapsed time: 2.905s, Critical Path: 0.06s
INFO: 6 processes: 5 internal, 1 linux-sandbox.
INFO: Build completed successfully, 6 total actions

Frankly, this only further confuses me. I have no idea what's actually happening in what order; python resolution steps are interspersed with C++ ones and any hierarchical relationship is lost. Some of the lines end in commas, but they don't seem related to the subsequent lines - I can't tell if this was a multi-line statement that was broken up by ordering or if the comma is just spurious. The indentation also doesn't make any sense (hopefully as a result of the lack of ordering, rather than a separate issue?). I see that #8502 raised this, but it was deduped to #7713 even though that doesn't really capture that aspect, and that issue was closed by #13207 which addresses only the "minimize output" aspect but IMO doesn't address any of the other various concerns about actually interpreting the output that is given.

[katre]

@nfelt: Have you tried with a Bazel that includes fbf9f9d?I find that filtering the toolchain types I want reported makes the output much more useful. If that's not the case, I'd be curious to know more about why.

[nfelt]

Thanks for the response. I haven't tried Bazel with the new flag (since it's not in 4.0.0 and I'm not aware of a particularly straightforward way to get a nightly build). But is it functionally any different from just grepping the output?

For my actual problem, even grepping the toolchain resolution output for lines containing py, I still get something takes a lot of scrutinizing for it to make any sense to me:

INFO: ToolchainResolution:   Type @bazel_tools//tools/python:toolchain_type: target platform @local_execution_config_platform//:platform: execution @local_execution_config_platform//:platform: Selected toolchain @local_execution_config_python//:py_runtime_pair
INFO: ToolchainResolution:     Type @bazel_tools//tools/python:toolchain_type: execution platform @local_config_platform//:host: Rejected toolchain @local_execution_config_python//:py_runtime_pair; mismatching values: platform_constraint
INFO: ToolchainResolution:   Type @bazel_tools//tools/python:toolchain_type: target platform @local_execution_config_platform//:platform: execution @local_config_platform//:host: Selected toolchain @bazel_tools//tools/python:_autodetecting_py_runtime_pair
INFO: ToolchainResolution: Target platform @local_execution_config_platform//:platform: Selected execution platform @local_execution_config_platform//:platform, type @bazel_tools//tools/python:toolchain_type -> toolchain @local_execution_config_python//:py_runtime_pair, type @bazel_tools//tools/cpp:toolchain_type -> toolchain @local_config_cc//:cc-compiler-k8

As mentioned above, the indentation in particular really throws me off. My best guess after having spent quite a bit of time attempting to understand what this means is that it's sort in reverse order and that the greater indented lines are logically "children" of lines that come somewhere later in the output, but this is pretty counterintuitive IMO. If that's the case it would really help to have an opening line as well as a closing line to make it obvious that we're entering and exiting some new "scope" of resolution.

Also, I don't know what to make of the one Rejected line - it's for the platform @local_config_platform//:host but it's sandwiched in between two lines for the platform @local_execution_config_platform//:platform and only the latter seems to have a conclusive Target platform line.

And then there's the things I mentioned that don't show up in the filtered output but are still confusing, like the trailing commas. For cases like this where the full output is only ~10 lines, it's not necessarily going to occur to a user that they need to filter it to see a consistent sub-sequence (if it even is consistent) and it's easy to get confused by red herrings.

Overall, I imagine that this debug output might be useful to someone who's a Bazel toolchain and configuration expert. But to someone who's not, it's just cryptic. Maybe this flag is only meant for expert users but then it would be nice if it indicated in the help that this is the case.

[katre]

That makes sense, I'll update the flag's documentation.

[github-actions]

Thank you for contributing to the Bazel repository! This issue has been marked as stale since it has not had any activity in the last 1+ years. It will be closed in the next 14 days unless any other activity occurs or one of the following labels is added: "not stale", "awaiting-bazeler". Please reach out to the triage team (@bazelbuild/triage) if you think this issue is still relevant or you are interested in getting the issue resolved.

[katre]

I am keeping #17814 as the canonical issue for "improve toolchain resolution debugging", so closing this but will keep the suggestions in mind.