Merge ~ogayot/curtin:system-install-log-stderr into curtin:master

[Olivier Gayot]

system-install: log output of commands if they fail

Signed-off-by: Olivier Gayot <email address hidden>

If a subcommand fails as part of a `curtin system-install` invocation, curtin tries to show its output. Sadly, the output of the subcommand is not captured, so there is nothing to show.

Example:

Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Running command ['umount', '/target/dev'] with allowed return codes [0] (capture=False)
Mar 08 14:23:46 ubuntu-server systemd[1]: target-proc.mount: Deactivated successfully.
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: system install failed for ['openssh-server']: Unexpected error while running command.
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Command: ['unshare', '--fork', '--pid', '--mount-proc=/target/proc', '--', 'chroot', '/target', 'apt-get', '--quiet', '--assume-yes', '--option=Dpkg::options::=--force-unsafe-io', '--option=Dpkg::Options::=--force-confold', 'install', 'openssh-server']
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Exit code: 100
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Reason: -
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Stdout: ''
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: Stderr: ''
Mar 08 14:23:46 ubuntu-server subiquity_log.1543[10940]: finish: cmd-system-install: FAIL: curtin command system-install
Mar 08 14:23:46 ubuntu-server curtin_event.1543.10[10940]: finish: cmd-system-install: FAIL: curtin command system-install

NOTE that in the example above, the output of curtin system-install was redirected to the journal.

This change captures the output of subcommands so that there is something to show if a subcommand fails:

system install failed for ['openssh-server']: Unexpected error while running command.
Command: ['unshare', '--fork', '--pid', '--mount-proc=/target/proc', '--', 'chroot', '/target', 'apt-get', '--quiet', '--assume-yes', '--option=Dpkg::options::=--force-unsafe-io', '--option=Dpkg::Options::=--force-confold', 'install', 'openssh-server']
Exit code: 100
Reason: -
Stdout: Reading package lists...
        Building dependency tree...
        Reading state information...
        openssh-server is already the newest version (1:9.6p1-3ubuntu2).
        0 upgraded, 0 newly installed, 0 to remove and 130 not upgraded.
        1 not fully installed or removed.
        After this operation, 0 B of additional disk space will be used.
        Setting up openssh-server (1:9.6p1-3ubuntu2) ...
        needrestart is being skipped since dpkg has failed

Stderr: E: Can not write log (Is /dev/pts mounted?) - posix_openpt (19: No such device)
        Failed to connect to bus: No data available
        dpkg: error processing package openssh-server (--configure):
         installed openssh-server package post-installation script subprocess returned error exit status 1
        Errors were encountered while processing:
         openssh-server
        E: Sub-process /usr/bin/dpkg returned an error code (1)

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:f322a9546024fb20acf029a0a72580d6c6ec6178
https://jenkins.canonical.com/server-team/job/curtin-ci/249/
Executed test runs:
    SUCCESS: https://jenkins.canonical.com/server-team/job/curtin-ci/nodes=metal-amd64/249/
    SUCCESS: https://jenkins.canonical.com/server-team/job/curtin-ci/nodes=metal-arm64/249/
    SUCCESS: https://jenkins.canonical.com/server-team/job/curtin-ci/nodes=metal-ppc64el/249/
    SUCCESS: https://jenkins.canonical.com/server-team/job/curtin-ci/nodes=metal-s390x/249/

Click here to trigger a rebuild:
https://jenkins.canonical.com/server-team/job/curtin-ci/249//rebuild

review: Approve (continuous-integration)

[Olivier Gayot (ogayot)]

I'm moving back this MP to "in progress". I think the change might hide existing logs when commands exit successfully. Would have to double check.

Unmerged commits

f322a95... by Olivier Gayot on 2024-03-08

system-install: log output of commands if they fail

Signed-off-by: Olivier Gayot <email address hidden>

diff --git a/curtin/distro.py b/curtin/distro.py
index 3284b69..5f9ad90 100644
--- a/curtin/distro.py
+++ b/curtin/distro.py
@@ -259,11 +259,11 @@ def run_apt_command(mode, args=None, opts=None, env=None, target=None,
         if clean and not download_only:
             with ChrootableTarget(
                     target, allow_daemons=allow_daemons) as inchroot:
-                inchroot.subp(['apt-get', 'clean'])
+                inchroot.subp(['apt-get', 'clean'], capture=True)
         return cmd_rv
 
     with ChrootableTarget(target, allow_daemons=allow_daemons) as inchroot:
-        return inchroot.subp(cmd, env=env)
+        return inchroot.subp(cmd, env=env, capture=True)
 
 
 def apt_install(mode, packages=None, opts=None, env=None, target=None,
@@ -300,9 +300,10 @@ def apt_install(mode, packages=None, opts=None, env=None, target=None,
     with ChrootableTarget(target, allow_daemons=allow_daemons) as inchroot:
         if not assume_downloaded:
             cmd_rv = inchroot.subp(cmd + dl_opts + packages, env=env,
-                                   retries=download_retries)
+                                   retries=download_retries, capture=True)
         if not download_only:
-            cmd_rv = inchroot.subp(cmd + inst_opts + packages, env=env)
+            cmd_rv = inchroot.subp(cmd + inst_opts + packages, env=env,
+                                   capture=True)
 
     return cmd_rv
 
diff --git a/tests/unittests/test_distro.py b/tests/unittests/test_distro.py
index a28a741..b226e35 100644
--- a/tests/unittests/test_distro.py
+++ b/tests/unittests/test_distro.py
@@ -313,7 +313,8 @@ class TestAptInstall(CiTestCase):
         distro.run_apt_command('install', ['foobar', 'wark'])
         m_apt_update.assert_called_once()
         m_apt_install.assert_has_calls(expected_calls)
-        m_subp.assert_called_once_with(['apt-get', 'clean'], target='/')
+        m_subp.assert_called_once_with(['apt-get', 'clean'], target='/',
+                                       capture=True)
 
         m_subp.reset_mock()
         m_apt_install.reset_mock()
@@ -336,10 +337,10 @@ class TestAptInstall(CiTestCase):
         expected_calls = [
             mock.call(cmd_prefix + ['install', '--download-only']
                                  + ['foobar', 'wark'],
-                      env=None, target='/', retries=None),
+                      env=None, target='/', retries=None, capture=True),
             mock.call(cmd_prefix + ['install']
                                  + ['foobar', 'wark'],
-                      env=None, target='/'),
+                      env=None, target='/', capture=True),
         ]
 
         distro.apt_install('install', packages=['foobar', 'wark'])
@@ -347,9 +348,9 @@ class TestAptInstall(CiTestCase):
 
         expected_calls = [
             mock.call(cmd_prefix + ['upgrade', '--download-only'],
-                      env=None, target='/', retries=None),
+                      env=None, target='/', retries=None, capture=True),
             mock.call(cmd_prefix + ['upgrade'],
-                      env=None, target='/'),
+                      env=None, target='/', capture=True),
         ]
 
         m_subp.reset_mock()
@@ -358,9 +359,9 @@ class TestAptInstall(CiTestCase):
 
         expected_calls = [
             mock.call(cmd_prefix + ['dist-upgrade', '--download-only'],
-                      env=None, target='/', retries=None),
+                      env=None, target='/', retries=None, capture=True),
             mock.call(cmd_prefix + ['dist-upgrade'],
-                      env=None, target='/'),
+                      env=None, target='/', capture=True),
         ]
 
         m_subp.reset_mock()
@@ -373,11 +374,12 @@ class TestAptInstall(CiTestCase):
         m_subp.reset_mock()
         distro.apt_install('install', ['git'], download_only=True)
         m_subp.assert_called_once_with(expected_dl_cmd, env=None, target='/',
-                                       retries=None)
+                                       retries=None, capture=True)
 
         m_subp.reset_mock()
         distro.apt_install('install', ['git'], assume_downloaded=True)
-        m_subp.assert_called_once_with(expected_inst_cmd, env=None, target='/')
+        m_subp.assert_called_once_with(expected_inst_cmd, env=None, target='/',
+                                       capture=True)
 
     @mock.patch.object(util.ChrootableTarget, "__enter__", new=lambda a: a)
     @mock.patch('curtin.util.subp')
@@ -588,10 +590,13 @@ class TestSystemUpgrade(CiTestCase):
         auto_remove = apt_base + ['autoremove']
         expected_calls = [
             mock.call(dl_apt_cmd, env=env, retries=None,
-                      target=paths.target_path(target)),
-            mock.call(inst_apt_cmd, env=env, target=paths.target_path(target)),
-            mock.call(['apt-get', 'clean'], target=paths.target_path(target)),
-            mock.call(auto_remove, env=env, target=paths.target_path(target)),
+                      target=paths.target_path(target), capture=True),
+            mock.call(inst_apt_cmd, env=env, target=paths.target_path(target),
+                      capture=True),
+            mock.call(['apt-get', 'clean'], target=paths.target_path(target),
+                      capture=True),
+            mock.call(auto_remove, env=env, target=paths.target_path(target),
+                      capture=True),
         ]
         which_calls = [mock.call('eatmydata', target=target)]
         apt_update_calls = [mock.call(target, env=env)]