exec_sudo: check cmd for str, log output and raise exception

To avoid any confusion, commands passed to exec_sudo() should be a
list of "str"s.  Log a message if we see unicode issues.

This also adds a debug trace of all output.  stderr is captured.

This is modified to raise CalledProcessError on failure, like
check_call().  Calls that are ok to fail will need to explicitly catch
and ignore this.

The two calls that we expect to fail are wrapped

We wish to try rolling back if one of these command raises an
exception.  Modify the create handler to initiate rollback on all
exceptions.

Change-Id: Iee4fa41ffaf243e4728bf3a5eeec5c8fa8d2dadc

diskimage_builder/block_device/blockdevice.py

@@ -274,8 +274,8 @@ class BlockDevice(object):
 
         try:
             self.create(self.state, rollback)
-        except BlockDeviceSetupException as bdse:
-            logger.error("exception [%s]" % bdse)
+        except Exception:
+            logger.exception("Create failed; rollback initiated")
             for rollback_cb in reversed(rollback):
                 rollback_cb()
             sys.exit(1)

diskimage_builder/block_device/level1/partitioning.py

@@ -23,7 +23,7 @@ from diskimage_builder.block_device.utils import parse_rel_size_spec
 from diskimage_builder.graph.digraph import Digraph
 import logging
 import os
-
+from subprocess import CalledProcessError
 
 logger = logging.getLogger(__name__)
 
@@ -238,8 +238,12 @@ class Partitioning(PluginBase):
         These calls are highly distribution and version specific. Here
         a couple of different methods are used to get the best result.
         """
-        exec_sudo(["partprobe", device_path])
-        exec_sudo(["udevadm", "settle"])
+        try:
+            exec_sudo(["partprobe", device_path])
+            exec_sudo(["udevadm", "settle"])
+        except CalledProcessError as e:
+            logger.info("Ignoring settling failure: %s" % e)
+            pass
 
         if self._all_part_devices_exist(partition_devices):
             return

diskimage_builder/block_device/utils.py

@@ -88,15 +88,41 @@ def parse_rel_size_spec(size_spec, abs_size):
 
 
 def exec_sudo(cmd):
+    """Run a command under sudo
+
+    Run command under sudo, with debug trace of output.  This is like
+    subprocess.check_call() but sudo wrapped and with output tracing
+    at debug levels.
+
+    Arguments:
+    :param cmd: str command list; for Popen()
+    :return: nothing
+    :raises: subprocess.CalledProcessError if return code != 0
+
+    """
+    assert isinstance(cmd, list)
     sudo_cmd = ["sudo"]
     sudo_cmd.extend(cmd)
-    logger.info("Calling [%s]" % " ".join(sudo_cmd))
-    subp = subprocess.Popen(sudo_cmd)
-    rval = subp.wait()
-    if rval != 0:
-        logger.error("Calling [%s] failed with [%s]" %
-                     (" ".join(sudo_cmd), rval))
-    return rval
+    try:
+        logger.info("Calling [%s]" % " ".join(sudo_cmd))
+    except TypeError:
+        # Popen actually doesn't care, but we've managed to get mixed
+        # str and bytes in argument lists which causes errors logging
+        # commands.  Give a clue as to what's going on.
+        logger.exception("Ensure all arguments are str type!")
+        raise
+
+    proc = subprocess.Popen(sudo_cmd,
+                            stdout=subprocess.PIPE,
+                            stderr=subprocess.STDOUT)
+
+    for line in iter(proc.stdout.readline, b""):
+        logger.debug("exec_sudo: %s" % line.rstrip())
+
+    proc.wait()
+    if proc.returncode != 0:
+        raise subprocess.CalledProcessError(proc.returncode,
+                                            ' '.join(sudo_cmd))
 
 
 def sort_mount_points(mount_points):