Skip to content

Commit e3ec21c

Browse files
Surface raw errors when check_output fails (#2125)
* Output errors if check_output call fails. * Add quiet=1 to check_output usage. * Add changenote. * Remove a local path reference. * Refactor subprocess error handling to share more logic with logging. * Tweak the changenote. Co-authored-by: Malcolm Smith <smith@chaquo.com> * Fix a couple of missed quiet calls. --------- Co-authored-by: Malcolm Smith <smith@chaquo.com>
1 parent 6fb23c1 commit e3ec21c

25 files changed

Lines changed: 332 additions & 205 deletions

changes/1907.feature.rst

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
If Briefcase receives an error invoking a system tool, it will now surface the raw error message to the user in addition to logging the error.

src/briefcase/integrations/android_sdk.py

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1424,7 +1424,7 @@ def avd_name(self) -> str | None:
14241424
an emulator
14251425
"""
14261426
try:
1427-
output = self.run("emu", "avd", "name")
1427+
output = self.run("emu", "avd", "name", quiet=1)
14281428
return output.split("\n")[0]
14291429
except subprocess.CalledProcessError as e:
14301430
# Status code 1 is a normal "it's not an emulator" error response
@@ -1451,13 +1451,13 @@ def has_booted(self) -> bool:
14511451
f"Unable to determine if emulator {self.device} has booted."
14521452
) from e
14531453

1454-
def run(self, *arguments: SubprocessArgT, quiet: bool = False) -> str:
1454+
def run(self, *arguments: SubprocessArgT, quiet: int = 0) -> str:
14551455
"""Run a command on a device using Android debug bridge, `adb`. The device name
14561456
is mandatory to ensure clarity in the case of multiple attached devices.
14571457
14581458
:param arguments: List of strings to pass to `adb` as arguments.
14591459
:param quiet: Should the invocation of this command be silent, and
1460-
*not* appear in the logs? This should almost always be False;
1460+
*not* appear in the logs? This should almost always be 0;
14611461
however, for some calls (most notably, calls that are called
14621462
frequently to evaluate the status of another process), logging can
14631463
be turned off so that log output isn't corrupted by thousands of

src/briefcase/integrations/docker.py

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -207,6 +207,7 @@ def _user_access(cls, tools: ToolCache):
207207
tools.subprocess.check_output(
208208
["docker", "info"],
209209
env=cls.subprocess_env(),
210+
quiet=1,
210211
)
211212
except subprocess.CalledProcessError as e:
212213
failure_output = e.output
@@ -220,6 +221,7 @@ def _user_access(cls, tools: ToolCache):
220221
):
221222
raise BriefcaseCommandError(cls.DAEMON_NOT_RUNNING_ERROR) from e
222223
else:
224+
tools.subprocess.output_error(e)
223225
raise BriefcaseCommandError(cls.GENERIC_DOCKER_ERROR) from e
224226

225227
@classmethod

src/briefcase/integrations/java.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -214,6 +214,7 @@ def verify_install(cls, tools: ToolCache, install: bool = True, **kwargs) -> JDK
214214
# If no JRE/JDK is installed, /usr/libexec/java_home raises an error
215215
java_home = tools.subprocess.check_output(
216216
["/usr/libexec/java_home"],
217+
quiet=1,
217218
).strip("\n")
218219
except (OSError, subprocess.CalledProcessError):
219220
tools.console.debug("An existing JDK/JRE was not returned")

src/briefcase/integrations/subprocess.py

Lines changed: 63 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@
1919
import psutil
2020

2121
from briefcase.config import AppConfig
22-
from briefcase.console import Console
22+
from briefcase.console import Console, LogLevel
2323
from briefcase.exceptions import CommandOutputParseError, ParseError
2424
from briefcase.integrations.base import Tool, ToolCache
2525

@@ -617,31 +617,33 @@ def _run_and_stream_output(
617617
return subprocess.CompletedProcess(args, return_code, stderr=stderr)
618618

619619
@ensure_console_is_safe
620-
def check_output(self, args: SubprocessArgsT, quiet: bool = False, **kwargs) -> str:
620+
def check_output(self, args: SubprocessArgsT, quiet: int = 0, **kwargs) -> str:
621621
"""A wrapper for subprocess.check_output()
622622
623-
The behavior of this method is identical to
624-
subprocess.check_output(), except for:
625-
- If the `env` is argument provided, the current system environment
626-
will be copied, and the contents of env overwritten into that
627-
environment.
628-
- The `text` argument is defaulted to True so all output
629-
is returned as strings instead of bytes.
630-
- The `stderr` argument is defaulted to `stdout` so _all_ output is
631-
returned and `stderr` isn't unexpectedly printed to the console.
623+
The behavior of this method is identical to subprocess.check_output(), except
624+
for:
625+
- If the `env` is argument provided, the current system environment will be
626+
copied, and the contents of env overwritten into that environment.
627+
- The `text` argument is defaulted to True so all output is returned as strings
628+
instead of bytes.
629+
- The `stderr` argument is defaulted to `stdout` so _all_ output is returned
630+
and `stderr` isn't unexpectedly printed to the console.
632631
633632
:param args: commands and its arguments to run via subprocess
634-
:param quiet: Should the invocation of this command be silent, and
635-
*not* appear in the logs? This should almost always be False;
636-
however, for some calls (most notably, calls that are called
637-
frequently to evaluate the status of another process), logging can
638-
be turned off so that log output isn't corrupted by thousands of
639-
polling calls.
633+
:param quiet: Should the invocation of this command be silent, and *not* appear
634+
in the logs? This should almost always be 0, indicating "not quiet"; any
635+
command output will be logged, and any errors will be logged *and* printed
636+
to the console. A value of 1 will log all command output, but errors will be
637+
logged, but *not* printed to the console. A value of 2 will *not* log any
638+
command output; errors will be logged, but *not* printed to the console. A
639+
value of 2 is mostly useful for calls that are called frequently to evaluate
640+
the status of another process (such as calls that poll an API) so that log
641+
output isn't corrupted by thousands of polling calls.
640642
"""
641643
# if stderr isn't explicitly redirected, then send it to stdout.
642644
kwargs.setdefault("stderr", subprocess.STDOUT)
643645

644-
if not quiet:
646+
if quiet < 2:
645647
self._log_command(args)
646648
self._log_cwd(kwargs.get("cwd"))
647649
self._log_environment(kwargs.get("env"))
@@ -651,12 +653,17 @@ def check_output(self, args: SubprocessArgsT, quiet: bool = False, **kwargs) ->
651653
[str(arg) for arg in args], **self.final_kwargs(**kwargs)
652654
)
653655
except subprocess.CalledProcessError as e:
654-
if not quiet:
656+
# Subprocess errors will be logged, and also printed to console if we're at
657+
# DEBUG+ log levels. However, if we're at quiet=0 *and* a non-debug log
658+
# level, we need to explicitly output to the console.
659+
if quiet == 0 and self.tools.console.verbosity < LogLevel.DEBUG:
660+
self.output_error(e)
661+
if quiet < 2:
655662
self._log_output(e.output, e.stderr)
656663
self._log_return_code(e.returncode)
657664
raise
658665

659-
if not quiet:
666+
if quiet < 2:
660667
self._log_output(cmd_output)
661668
self._log_return_code(0)
662669
return cmd_output
@@ -822,15 +829,22 @@ def cleanup(self, label: str, popen_process: subprocess.Popen):
822829
self.tools.console.warning(f"Forcibly killing {label}...")
823830
popen_process.kill()
824831

832+
def _console(self, msg: str = ""):
833+
"""Funnel for subprocess console-only logging."""
834+
self.tools.console.to_console(msg, style="dim")
835+
825836
def _log(self, msg: str = ""):
826837
"""Funnel for all subprocess details logging."""
827838
self.tools.console.debug(msg, preface=">>> " if msg else "")
828839

829-
def _log_command(self, args: SubprocessArgsT):
840+
def _log_command(self, args: SubprocessArgsT, handler=None):
830841
"""Log the entire console command being executed."""
831-
self._log()
832-
self._log("Running Command:")
833-
self._log(f" {' '.join(shlex.quote(str(arg)) for arg in args)}")
842+
if handler is None:
843+
handler = self._log
844+
845+
handler()
846+
handler("Running Command:")
847+
handler(f" {' '.join(shlex.quote(str(arg)) for arg in args)}")
834848

835849
def _log_cwd(self, cwd: str | Path | None):
836850
"""Log the working directory for the command being executed."""
@@ -849,18 +863,36 @@ def _log_environment(self, overrides: dict[str, str] | None):
849863
for env_var, value in overrides.items():
850864
self._log(f" {env_var}={value}")
851865

852-
def _log_output(self, output: str, stderr: str | None = None):
866+
def _log_output(self, output: str, stderr: str | None = None, handler=None):
853867
"""Log the output of the executed command."""
868+
if handler is None:
869+
handler = self._log
870+
854871
if output:
855-
self._log("Command Output:")
872+
handler("Command Output:")
856873
for line in ensure_str(output).splitlines():
857-
self._log(f" {line}")
874+
handler(f" {line}")
858875

859876
if stderr:
860-
self._log("Command Error Output (stderr):")
877+
handler("Command Error Output (stderr):")
861878
for line in ensure_str(stderr).splitlines():
862-
self._log(f" {line}")
879+
handler(f" {line}")
863880

864-
def _log_return_code(self, return_code: int | str):
881+
def _log_return_code(self, return_code: int | str, handler=None):
865882
"""Log the output value of the executed command."""
866-
self._log(f"Return code: {return_code}")
883+
if handler is None:
884+
handler = self._log
885+
handler(f"Return code: {return_code}")
886+
handler()
887+
888+
def output_error(self, exception: subprocess.CalledProcessException):
889+
"""Print error from a subprocess to the console.
890+
891+
This will output the command, output and return code to the console,
892+
but *not* to the log.
893+
894+
:param exception: The raw exception raised by a subprocess
895+
"""
896+
self._log_command(exception.cmd, handler=self._console)
897+
self._log_output(exception.output, exception.stderr, handler=self._console)
898+
self._log_return_code(exception.returncode, handler=self._console)

src/briefcase/integrations/xcode.py

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -104,7 +104,7 @@ def ensure_xcode_is_installed(
104104
# xcode-select: error: tool 'xcodebuild' requires Xcode, but active
105105
# developer directory '/Library/Developer/CommandLineTools' is a
106106
# command line tools instance
107-
output = tools.subprocess.check_output(["xcodebuild", "-version"])
107+
output = tools.subprocess.check_output(["xcodebuild", "-version"], quiet=1)
108108

109109
if min_version is not None:
110110
# Look for a line in the output that reads "Xcode X.Y.Z"
@@ -187,6 +187,7 @@ def ensure_xcode_is_installed(
187187
) from e
188188

189189
else:
190+
tools.subprocess.output_error(e)
190191
raise BriefcaseCommandError(
191192
"""\
192193
An Xcode install appears to exist, but Briefcase was unable to
@@ -250,7 +251,7 @@ def ensure_command_line_tools_are_installed(cls, tools: ToolCache):
250251
#
251252
# Any other status code is a problem.
252253
try:
253-
tools.subprocess.check_output(["xcode-select", "--install"])
254+
tools.subprocess.check_output(["xcode-select", "--install"], quiet=1)
254255
raise BriefcaseCommandError(
255256
"""\
256257
The command line developer tools are not installed.
@@ -294,7 +295,7 @@ def confirm_xcode_license_accepted(cls, tools: ToolCache):
294295
# tools return a status code of 69 (nice...) if the license has not been
295296
# accepted. In this case, we can prompt the user to accept the license.
296297
try:
297-
tools.subprocess.check_output(["/usr/bin/clang", "--version"])
298+
tools.subprocess.check_output(["/usr/bin/clang", "--version"], quiet=1)
298299
except subprocess.CalledProcessError as e:
299300
if e.returncode == 69:
300301
tools.console.info(
@@ -362,6 +363,7 @@ def confirm_xcode_license_accepted(cls, tools: ToolCache):
362363
"""
363364
)
364365
else:
366+
tools.subprocess.output_error(e)
365367
tools.console.warning(
366368
"""
367369
*************************************************************************

src/briefcase/platforms/android/gradle.py

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -440,7 +440,7 @@ def run_app(
440440
while not pid and datetime.datetime.now() < fail_time:
441441
# Try to get the PID; run in quiet mode because we may
442442
# need to do this a lot in the next 5 seconds.
443-
pid = adb.pidof(package, quiet=True)
443+
pid = adb.pidof(package, quiet=2)
444444
if not pid:
445445
time.sleep(0.01)
446446

@@ -460,7 +460,7 @@ def run_app(
460460
clean_filter=android_log_clean_filter,
461461
clean_output=False,
462462
# Check for the PID in quiet mode so logs aren't corrupted.
463-
stop_func=lambda: not adb.pid_exists(pid=pid, quiet=True),
463+
stop_func=lambda: not adb.pid_exists(pid=pid, quiet=2),
464464
log_stream=True,
465465
)
466466
else:

src/briefcase/platforms/linux/system.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -566,7 +566,7 @@ def verify_system_packages(self, app: AppConfig):
566566
installed = provided_by = package
567567

568568
try:
569-
self.tools.subprocess.check_output(system_verify + [installed])
569+
self.tools.subprocess.check_output(system_verify + [installed], quiet=1)
570570
except subprocess.CalledProcessError:
571571
missing.add(provided_by)
572572

src/briefcase/platforms/windows/app.py

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -76,11 +76,13 @@ def build_app(self, app: BaseConfig, **kwargs):
7676
self.binary_path(app).relative_to(self.bundle_path(app)),
7777
],
7878
cwd=self.bundle_path(app),
79+
quiet=1,
7980
)
8081
except subprocess.CalledProcessError as e:
8182
# Ignore this error from signtool since it is logged if the file
8283
# is not currently signed
8384
if "error: 0x00000057" not in e.stdout:
85+
self.tools.subprocess.output_error(e)
8486
raise BriefcaseCommandError(
8587
f"""\
8688
Failed to remove any existing digital signatures from the stub app.

tests/integrations/android_sdk/ADB/test_avd_name.py

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@ def test_emulator(adb, capsys):
1515
assert adb.avd_name() == "exampledevice"
1616

1717
# Validate call parameters.
18-
adb.run.assert_called_once_with("emu", "avd", "name")
18+
adb.run.assert_called_once_with("emu", "avd", "name", quiet=1)
1919

2020

2121
def test_device(adb, capsys):
@@ -29,7 +29,7 @@ def test_device(adb, capsys):
2929
assert adb.avd_name() is None
3030

3131
# Validate call parameters.
32-
adb.run.assert_called_once_with("emu", "avd", "name")
32+
adb.run.assert_called_once_with("emu", "avd", "name", quiet=1)
3333

3434

3535
def test_adb_failure(adb, capsys):
@@ -44,7 +44,7 @@ def test_adb_failure(adb, capsys):
4444
adb.avd_name()
4545

4646
# Validate call parameters.
47-
adb.run.assert_called_once_with("emu", "avd", "name")
47+
adb.run.assert_called_once_with("emu", "avd", "name", quiet=1)
4848

4949

5050
def test_invalid_device(adb, capsys):
@@ -57,4 +57,4 @@ def test_invalid_device(adb, capsys):
5757
adb.avd_name()
5858

5959
# Validate call parameters.
60-
adb.run.assert_called_once_with("emu", "avd", "name")
60+
adb.run.assert_called_once_with("emu", "avd", "name", quiet=1)

0 commit comments

Comments
 (0)