If a subprocess fails for an unknown reason, display its output in the console

[mhsmith]

In #1362, Briefcase failed to install an Android app, but all it displayed this in the console was this:

Installing new app version...

Unable to install APK

If we'd displayed the output of the failing command, the cause would have been obvious:

INSTALL_FAILED_UPDATE_INCOMPATIBLE: Package com.example.helloworld signatures do not match previously installed version

Even if the user doesn't understand what this message means, at least they would be able to find a solution by searching for its text. As it is, there isn't much they can do except come and ask us for help, which wastes both their time and ours.

Yes, they can find the output in the log file, but apparently many users don't even think to look there. And if they do, the adb output is buried in the middle of the file between all the successful steps and the extra-verbose stack trace, so its relevance is not obvious from a user's point of view.

In general, I think that if a Briefcase command fails because of a subprocess, its output should always be shown to the user unless we can be certain that Briefcase has a more useful message to display instead.

[mhsmith]

Originally posted by @freakboy3742 in #1362 (comment)

---

Generally speaking, I agree - however, I think I'd qualify this by saying that the bar for "more useful" should be very low, and skewed in the favor of novice developers. Many of the developer tools we're wrapping leave a lot to be desired in terms of readability; if we're in a position to improve the end-user experience, we should do so.

[mhsmith]

Here's another example from Discord, where a git command failed because the the Git version was too old:
briefcase.2024_07_09-16_47_44.new.log

Briefcase displays a misleading message:

This may be because your computer is offline, or because the repository URL is incorrect.

The actual error is buried in the middle of the log:

error: unknown option `filter=blob:none

I still argue that we should show a failing command's output to the user unless we can be certain that Briefcase has a more useful message to display instead, either by examining the command's output or its return code.

I don't think this could ever be the case with git clone, because there are too many ways in which it can fail:

• Incompatible version of Git
• Various network problems on both client and server side
• Git protocol errors
• Errors from the local filesystem

The same is true of most other failed subprocesses. We should certainly display some advice about what the most likely causes are, but we should display the original message as well. That combination would make it much easier for the user to solve the problem without asking for help.

[rmartin16]

Pip may serve as reasonable prior art to support the case to always show the details of a failed subprocess.

For instance:

> python3 -m pip install pycairo
Collecting pycairo
  Downloading pycairo-1.26.1.tar.gz (346 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 346.9/346.9 kB 2.4 MB/s eta 0:00:00
  Installing build dependencies ... done
  Getting requirements to build wheel ... done
  Preparing metadata (pyproject.toml) ... done
Building wheels for collected packages: pycairo
  Building wheel for pycairo (pyproject.toml) ... error
  error: subprocess-exited-with-error
  
  × Building wheel for pycairo (pyproject.toml) did not run successfully.
  │ exit code: 1
  ╰─> [12 lines of output]
      running bdist_wheel
      running build
      running build_py
      creating build
      creating build/lib.linux-x86_64-cpython-312
      creating build/lib.linux-x86_64-cpython-312/cairo
      copying cairo/__init__.py -> build/lib.linux-x86_64-cpython-312/cairo
      copying cairo/__init__.pyi -> build/lib.linux-x86_64-cpython-312/cairo
      copying cairo/py.typed -> build/lib.linux-x86_64-cpython-312/cairo
      running build_ext
      'pkg-config' not found.
      Command ['pkg-config', '--print-errors', '--exists', 'cairo >= 1.15.10']
      [end of output]
  
  note: This error originates from a subprocess, and is likely not a problem with pip.
  ERROR: Failed building wheel for pycairo
Failed to build pycairo
ERROR: Could not build wheels for pycairo, which is required to install pyproject.toml-based projects

FWIW, the Git example is a bit of an outlier (insofar as capturing details of a subprocess call) since Briefcase doesn't, itself, shell out to run Git. Instead, this is deferred to the GitPython package. Therefore, all relevant details about the outcome of running git must be extracted from the exception raised from GitPython. The only reason even the log file contains details is because we're including the stringified version of the exception.

[freakboy3742]

I agree it is undesirable to provide inaccurate error messages. However, in this case, I'd argue the error isn't inaccurate. The provided quote is misleading - the full error message says:

Unable to clone repository 'https://github.com/beeware/briefcase-template'.

This may be because your computer is offline, or because the repository URL is incorrect.

This is exactly what has happened in the filter=blob:none case - Briefcase was unable to clone the repository. Prior to the introduction of filtering, virtually all failures at this point were due to connectivity. The most recent Briefcase release has added a new failure mode, so the explanation for the underlying cause is isn't correct in this case - but that part of the sentence also says "may be because".

In this case, if git's error was included in the log , I'd argue the 1 piece of useful information in the output would be lost in the noise. git clone --adsf outputs a one line message "unknown option --asdf", followed by the full usage for git - over 50 lines of output that doesn't really add anything to the debugging experience in this context. I'd need to check to be sure, but I don't think pip displays the entirety of log output - it gives a tail of the output up to a limit. So, in this case "pip-comparable" output wouldn't show anything useful; and including the full output would then require the user to read and interpret 50+ lines of output to identify a specific problem... which they then aren't really in a position to action, because they didn't opt into the usage of --filter. Even if they do find the one useful line in the output, the connection between "error: unknown option filter=blob:none" and "Your git version is too old" requires background knowledge that many users won't have.

In this specific case, I'd argue the problem here is that the helper message should include "or your git version is too old" as part of the helper text. Better still, we'd add an explicit check for the git version as part of git verification.

This less of a problem with the original ADB failure - mostly because Briefcase doesn't provide any real feedback. It just says "it didn't work". In that case, I agree surfacing the ADB output is a lot more helpful.

To that end, I'd suggest the following "style guide":

1. Briefcase should always have the final word, and should provide as much guidance and context for the failure as it can. i.e., the last thing on the screen should be Briefcase's summary of the problem. This won't always be 100% accurate in diagnosing what an error means, but it will always be able to provide better context for a failure than expecting a user to know what "gradle" or "dmgbuild" is.
2. If shown, the literal error message should be de-emphasized/formatted in any output to make it clear that it is "raw" output, from an underlying command. pip does this of a fashion (with indentation), but I'd argue it doesn't do it as well as it could, as pip installation failures often appear like a wall of noise, rather than something actionable (as evidenced by the number of support queries we field that amount to "this package couldn't be installed because the build failed"). There's a lot that could be done with Rich colors to draw attention away from raw output to de-emphasize and contextualise the raw output from Briefcase output.
3. The log output should make it easier to find the stderr output of a failed command if a command is the direct cause of a crash. The log associated with the git failure, is almost 500 lines long; the "useful" line is L321, with 321-363 being the full stdout log. The "annotated stack frame" format might be helpful for us, but in its current form, it really isn't helpful for end users. I'd argue that in the case of a failed subprocess, the command line, environment and stdout/err content should be either the first or last thing in the file.

[mhsmith]

I agree with the "style guide", but I would argue that it still makes sense to display the Git output in this case, unless we can determine a specific cause like the Git version:

if git's error was included in the log , I'd argue the 1 piece of useful information in the output would be lost in the noise. git clone --adsf outputs a one line message "unknown option --asdf", followed by the full usage for git - over 50 lines of output

As I mentioned above, there are many other reasons why Git could fail, and most of them would give a shorter and clearer error message.

Even if they do find the one useful line in the output, the connection between "error: unknown option filter=blob:none" and "Your git version is too old" requires background knowledge that many users won't have.

Like I said above, even if the user doesn't understand what an error message means, at least they would be able to find a solution by searching for its text.

[mhsmith]

Another example:

Submitting app for notariztion... errored

Unable to submit build/helloworld/macos/app/Hello World.app for notarization.

Log saved to /Users/msmith/git/beeware/apps/helloworld/logs/briefcase.2025_01_15-22_02_57.package.log

Error in log (1250 lines from the top, and 350 lines from the bottom):

           >>>     Error: HTTP status code: 403. A required agreement is missing or has expired. This request requires an in-effect agreement that has not been    subprocess.py:827
           signed or has expired. Ensure your team has signed the necessary legal agreements and that they are not expired.                                                         
           >>> Return code: 1                                                                                                                                      subprocess.py:827
           Submitting app for notariztion... errored                                                                                                                 __init__.py:974
                                                                                                                                                                      __main__.py:44
           Unable to submit build/helloworld/macos/app/Hello World.app for notarization.                                                                              __main__.py:45

[mhsmith]

I made a previous attempt at this in #764, but it got abandoned because of higher priority work.

[freakboy3742]

Here's a relatively non-invasive proposal for handling this consistently:

Calls to subprocess.run() aren't affected by this problem, as they display all stdout/stderr content as they run.

Calls to subprocess.Popen() aren't affected by this problem either, as it's up to the caller to read/stream content (and errors) from the process.

So - this only affects subprocess.check_output() (and, by extension, subprocess.parse_output(), which invokes check_output()). check_output() is only ever used for tools that are (relatively) short lived, and don't provide any useful context in the output while they run (if they produce output at all); it's only in the case of an error where the output might be helpful for diagnostic purposes.

check_output() already has handling to direct stdout/stderr content, plus the return code, into the log. What we need to add is additional handling to also surface stdout/stderr content to the console in the case of an error.

The complication is that for some uses of check_output, an "error" is expected. For example, in the Xcode integration, the invocation of xcode-select --install returns an error code of 1 if Xcode is already installed.

To allow for this, we should make 2 changes:

1. Add a raw_output() method to Subprocess. This method will take a CalledProcessError instance, and output stdout, stderr, and the return code to the console, with a "dim" style (so that it is de-emphasized, but still visible to the user).
2. Modify the quiet argument to check_output() to take an integer, rather than a boolean:

quiet=0:

• On success, stdout and return code is logged, nothing is printed to console
• On failure, stdout, stderr and return code is both logged and output to console with raw_output()

quiet=1:

• On success, stdout and return code is logged, nothing is printed to console
• On failure, stdout, stderr and return code is logged, but not displayed to console

quiet=2:

• On success, nothing is logged or printed to console
• On failure, nothing is logged or printed to console

The current default of False would become 0; this would result in all check_output() errors resulting in console output.

All existing uses of quiet=True would be converted to quiet=2.

The new value of quiet=1 would be used for the xcode-select --install-type cases - places where we are able to provide a meaningful interpretation of return values. If there is a "bucket case" for check_output() error handling (e.g., the "error code other that -1" case for xcode-select --install), raw_output() can be used to manually reproduce the quiet=0 behavior.

From a quick survey, there's a handful of uses - mostly related to tool verification - where an error is expected if the tool doesn't exist; these would become quiet=1. There's only 2 uses of quiet=True that will become quiet=2 - both of them in the Android backend, where pidof and pid_exists are used in a polling loop.

The remaining uses of check_output, and all the uses of parse_output would inherit the default behaviour, displaying the error output on failure. This means with no changes to the notarization code, the console output of a notarization attempt with a failure would look something like:

[myapp] Notarizing app using team ID CAFEBEEF...

Archiving My App.app for notarization... done

[notarytool] HTTP status code: 403. A required agreement is missing or has expired. This request requires an in-effect agreement that has not been
[notarytool] signed or has expired. Ensure your team has signed the necessary legal agreements and that they are not expired.     
                                                    
Return code: 1

Submitting app for notarization... errored                                                                                                                 

Unable to submit build/helloworld/macos/app/Hello World.app for notarization.                                                                              

The content prefixed by [notarytool] and the return code would be printed with "dim" style (so it would be in grey on a color console). "Unable to submit" is the Briefcase error, printed in red.

Thoughts?

[mhsmith]

That all sounds reasonable to me.