curtin-dev team mailing list archive

[Olivier Gayot <mp+462051@xxxxxxxxxxxxxxxxxx>]

Olivier Gayot has proposed merging ~ogayot/curtin:system-install-log-stderr into curtin:master.

Commit message:
system-install: log output of commands if they fail

Signed-off-by: Olivier Gayot <olivier.gayot@xxxxxxxxxxxxx>


Requested reviews:
  curtin developers (curtin-dev)

For more details, see:
https://code.launchpad.net/~ogayot/curtin/+git/curtin/+merge/462051

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 13:39:08 ubuntu-server subiquity_log.1547[11562]: Running command ['mount', '--make-private', '/target/dev'] with allowed return cod>
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Running command ['umount', '/target/dev'] with allowed return codes [0] (capture=F>
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: system install failed for ['openssh-server']: Unexpected error while running comma>
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Command: ['unshare', '--fork', '--pid', '--mount-proc=/target/proc', '--', 'chroot>
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Exit code: 100
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Reason: -
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Stdout: ''
Mar 08 13:39:08 ubuntu-server subiquity_log.1547[11562]: Stderr: ''


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)
        

-- 
Your team curtin developers is requested to review the proposed merge of ~ogayot/curtin:system-install-log-stderr into curtin:master.

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)]