From 2ef884f943f43b0926eb5e8496aa82987c475a84 Mon Sep 17 00:00:00 2001 From: Alex Lowe Date: Wed, 22 Apr 2026 00:16:27 -0400 Subject: [PATCH 1/4] test: add failing reproducer for subprocess output not logged (issue #250) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds two tests for subprocess output visibility: 1. test_execute_run_logs_output_at_debug [FAILS] — _execute_run() captures stdout from every command via capture_output=True, but never logs it. Operators using debug/trace logging see nothing from in-container commands (apt-get, systemctl, etc.) even when they run successfully. 2. test_execute_run_output_included_in_error_details [PASSES] — verifies that the 'output shown on error' half of #250 already works: when a subprocess fails, its stdout is captured and included in the BaseConfigurationError details via details_from_called_process_error(). The fix for the failing test is to log proc.stdout at debug level inside _execute_run() after a successful run. Fixes: https://github.com/canonical/craft-providers/issues/250 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- tests/unit/bases/test_ubuntu_buildd.py | 61 ++++++++++++++++++++++++++ 1 file changed, 61 insertions(+) diff --git a/tests/unit/bases/test_ubuntu_buildd.py b/tests/unit/bases/test_ubuntu_buildd.py index c33273d0c..0633bcb90 100644 --- a/tests/unit/bases/test_ubuntu_buildd.py +++ b/tests/unit/bases/test_ubuntu_buildd.py @@ -1674,6 +1674,67 @@ def test_execute_run_bad_check_verifynetwork_combination(fake_executor): ) +def test_execute_run_logs_output_at_debug(fake_executor, fake_process, logs): + """_execute_run() should log command stdout at debug level. + + When craft-providers runs commands inside an instance (apt-get, systemctl, + etc.) the output is currently silently discarded on success. Operators + running with debug/trace logging expect to see that output so they can + diagnose problems without having to reproduce a full failure. + + Regression test for https://github.com/canonical/craft-providers/issues/250 + """ + base_config = ubuntu.BuilddBase(alias=ubuntu.BuilddBaseAlias.JAMMY) + command = ["the", "command"] + fake_process.register_subprocess( + [*DEFAULT_FAKE_CMD, *command], + returncode=0, + stdout=b"important command output", + ) + + base_config._execute_run(command, executor=fake_executor) + + assert "important command output" in logs.debug + + +def test_execute_run_output_included_in_error_details(fake_executor, fake_process): + """When a subprocess fails, its stdout must appear in the error details. + + For example, when `apt-get update` returns exit code 100, the apt output + contains the specific mirror/package that caused the failure. Without it + the user sees only "Failed to update apt cache" with no actionable detail. + + The test registers a subprocess that produces stdout and fails, then + checks that a higher-level caller wraps the error with those details + visible — using _pre_setup_packages (apt-get update) as a representative + caller. + + Regression test for https://github.com/canonical/craft-providers/issues/250 + """ + base_config = ubuntu.BuilddBase(alias=ubuntu.BuilddBaseAlias.JAMMY) + + fake_process.register_subprocess( + [*DEFAULT_FAKE_CMD, "cat", "/etc/os-release"], + stdout="UBUNTU_CODENAME=jammy", + ) + fake_process.register_subprocess( + [*DEFAULT_FAKE_CMD, "apt-get", "update"], + returncode=100, + stdout=b"Err:1 http://archive.ubuntu.com/ubuntu jammy InRelease\n Connection refused", + ) + fake_process.register_subprocess( + [*DEFAULT_FAKE_CMD, "bash", "-c", "exec 3<> /dev/tcp/snapcraft.io/443"], + ) + + with pytest.raises(BaseConfigurationError) as exc_info: + base_config._pre_setup_packages(executor=fake_executor) + + assert "Connection refused" in str(exc_info.value), ( + "stdout from the failed subprocess must appear in the error details " + "so the user knows why apt-get update failed" + ) + + @pytest.mark.usefixtures("stub_verify_network") def test_network_connectivity_yes(fake_executor, fake_process): """Connectivity is ok.""" From 9884fb19e01442894753e2c14d6076066cb4cdaa Mon Sep 17 00:00:00 2001 From: Alex Lowe Date: Wed, 22 Apr 2026 00:21:50 -0400 Subject: [PATCH 2/4] fix: log subprocess stdout/stderr at debug level after each command _execute_run() captures output via capture_output=True but previously discarded it on success. Now logs proc.stdout and proc.stderr at debug level so operators running with -v or debug logging can see what in- container commands (apt-get, systemctl, snap, etc.) printed without needing to reproduce a full failure. Fixes: https://github.com/canonical/craft-providers/issues/250 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- craft_providers/base.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/craft_providers/base.py b/craft_providers/base.py index d8b4477f3..4d398cdbf 100644 --- a/craft_providers/base.py +++ b/craft_providers/base.py @@ -1223,4 +1223,10 @@ def _execute_run( if verify_network and not cls._network_connected(executor=executor): raise NetworkError from exc raise + + if proc.stdout: + logger.debug("Command stdout: %s", proc.stdout) + if proc.stderr: + logger.debug("Command stderr: %s", proc.stderr) + return proc From 03ba6d982c50842943d79ce3dfdb1abccf48ba72 Mon Sep 17 00:00:00 2001 From: Alex Lowe Date: Mon, 4 May 2026 11:32:18 -0400 Subject: [PATCH 3/4] Update tests/unit/bases/test_ubuntu_buildd.py Co-authored-by: Callahan Kovacs Signed-off-by: Alex Lowe --- tests/unit/bases/test_ubuntu_buildd.py | 9 --------- 1 file changed, 9 deletions(-) diff --git a/tests/unit/bases/test_ubuntu_buildd.py b/tests/unit/bases/test_ubuntu_buildd.py index 0633bcb90..35dfa934a 100644 --- a/tests/unit/bases/test_ubuntu_buildd.py +++ b/tests/unit/bases/test_ubuntu_buildd.py @@ -1700,15 +1700,6 @@ def test_execute_run_logs_output_at_debug(fake_executor, fake_process, logs): def test_execute_run_output_included_in_error_details(fake_executor, fake_process): """When a subprocess fails, its stdout must appear in the error details. - For example, when `apt-get update` returns exit code 100, the apt output - contains the specific mirror/package that caused the failure. Without it - the user sees only "Failed to update apt cache" with no actionable detail. - - The test registers a subprocess that produces stdout and fails, then - checks that a higher-level caller wraps the error with those details - visible — using _pre_setup_packages (apt-get update) as a representative - caller. - Regression test for https://github.com/canonical/craft-providers/issues/250 """ base_config = ubuntu.BuilddBase(alias=ubuntu.BuilddBaseAlias.JAMMY) From 93599c3d228ccfc8df807c1d090a18fa54d6fdd2 Mon Sep 17 00:00:00 2001 From: Alex Lowe Date: Mon, 4 May 2026 11:32:28 -0400 Subject: [PATCH 4/4] Update tests/unit/bases/test_ubuntu_buildd.py Co-authored-by: Callahan Kovacs Signed-off-by: Alex Lowe --- tests/unit/bases/test_ubuntu_buildd.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/tests/unit/bases/test_ubuntu_buildd.py b/tests/unit/bases/test_ubuntu_buildd.py index 35dfa934a..bbe136fb6 100644 --- a/tests/unit/bases/test_ubuntu_buildd.py +++ b/tests/unit/bases/test_ubuntu_buildd.py @@ -1677,11 +1677,6 @@ def test_execute_run_bad_check_verifynetwork_combination(fake_executor): def test_execute_run_logs_output_at_debug(fake_executor, fake_process, logs): """_execute_run() should log command stdout at debug level. - When craft-providers runs commands inside an instance (apt-get, systemctl, - etc.) the output is currently silently discarded on success. Operators - running with debug/trace logging expect to see that output so they can - diagnose problems without having to reproduce a full failure. - Regression test for https://github.com/canonical/craft-providers/issues/250 """ base_config = ubuntu.BuilddBase(alias=ubuntu.BuilddBaseAlias.JAMMY)