[PATCH 0/5] iotests: add enhanced debugging info to qemu-img failures

[PATCH 0/5] iotests: add enhanced debugging info to qemu-img failures

[John Snow]

This is kinda-sorta V3-ish of a series I started in response to Thomas
Huth's encountering a failure in qemu-img because of missing zstd
support. This series changes the qemu_img() function in iotests.py to
one that raises an Exception on non-zero return code by default.

Alongside this, the Exception object itself is also augmented so that it
prints the stdout/stderr logs to screen if the exception goes unhandled
so that failure cases are very obvious and easy to spot in the middle of
python tracebacks.

(Test this out yourself: Disable zstd support and then run qcow2 iotest
065 before and after this patchset. It makes a real difference!)

NOTE: I have another 13-ish patches that go the rest of the way and
ensure that *every* call to qemu-img goes through this new qemu_img()
function, but for the sake of doing the most good in the shortest amount
of time, I am sending just the first 5 patches, and the rest will be
sent later. I think this is a very good series to get in before freeze
so that we have it during the heavy testing season.

John Snow (5):
  python/utils: add add_visual_margin() text decoration utility
  python/utils: add VerboseProcessError
  iotests: Remove explicit checks for qemu_img() == 0
  iotests: make qemu_img raise on non-zero rc by default
  iotests: fortify compare_images() against crashes

 python/qemu/utils/__init__.py                 | 114 ++++++++++++++++++
 tests/qemu-iotests/163                        |   9 +-
 tests/qemu-iotests/216                        |   6 +-
 tests/qemu-iotests/218                        |   2 +-
 tests/qemu-iotests/224                        |  11 +-
 tests/qemu-iotests/228                        |  12 +-
 tests/qemu-iotests/257                        |  11 +-
 tests/qemu-iotests/258                        |   4 +-
 tests/qemu-iotests/310                        |  14 +--
 tests/qemu-iotests/iotests.py                 |  69 +++++++++--
 tests/qemu-iotests/tests/block-status-cache   |   3 +-
 tests/qemu-iotests/tests/image-fleecing       |   4 +-
 .../tests/mirror-ready-cancel-error           |   6 +-
 tests/qemu-iotests/tests/mirror-top-perms     |   3 +-
 .../tests/remove-bitmap-from-backing          |   8 +-
 .../qemu-iotests/tests/stream-error-on-reset  |   4 +-
 16 files changed, 220 insertions(+), 60 deletions(-)

-- 
2.34.1

[PATCH 1/5] python/utils: add add_visual_margin() text decoration utility

[John Snow]

>>> print(add_visual_margin(msg, width=72, name="Commit Message"))
┏━ Commit Message ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
┃ add_visual_margin() takes a chunk of text and wraps it in a visual
┃ container that force-wraps to a specified width. An optional title
┃ label may be given, and any of the individual glyphs used to draw the
┃ box may be replaced or specified as well.
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

Signed-off-by: John Snow <jsnow@redhat.com>
---
 python/qemu/utils/__init__.py | 78 +++++++++++++++++++++++++++++++++++
 1 file changed, 78 insertions(+)

diff --git a/python/qemu/utils/__init__.py b/python/qemu/utils/__init__.py
index 7f1a5138c4..5babf40df2 100644
--- a/python/qemu/utils/__init__.py
+++ b/python/qemu/utils/__init__.py
@@ -15,7 +15,10 @@
 # the COPYING file in the top-level directory.
 #
 
+import os
 import re
+import shutil
+import textwrap
 from typing import Optional
 
 # pylint: disable=import-error
@@ -23,6 +26,7 @@
 
 
 __all__ = (
+    'add_visual_margin',
     'get_info_usernet_hostfwd_port',
     'kvm_available',
     'list_accel',
@@ -43,3 +47,77 @@ def get_info_usernet_hostfwd_port(info_usernet_output: str) -> Optional[int]:
         if match is not None:
             return int(match[1])
     return None
+
+
+# pylint: disable=too-many-arguments
+def add_visual_margin(
+        content: str = '',
+        width: Optional[int] = None,
+        name: Optional[str] = None,
+        padding: int = 1,
+        upper_left: str = '┏',
+        lower_left: str = '┗',
+        horizontal: str = '━',
+        vertical: str = '┃',
+) -> str:
+    """
+    Decorate and wrap some text with a visual decoration around it.
+
+    This function assumes that the text decoration characters are single
+    characters that display using a single monospace column.
+
+    ┏━ Example ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
+    ┃ This is what this function looks like with text content that's
+    ┃ wrapped to 72 characters. The right-hand margin is left open to
+    ┃ acommodate the occasional unicode character that might make
+    ┃ predicting the total "visual" width of a line difficult. This
+    ┃ provides a visual distinction that's good-enough, though.
+    ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
+
+    :param content: The text to wrap and decorate.
+    :param width:
+        The number of columns to use, including for the decoration
+        itself. The default (None) uses the the available width of the
+        current terminal, or a fallback of 72 lines. A negative number
+        subtracts a fixed-width from the default size. The default obeys
+        the COLUMNS environment variable, if set.
+    :param name: A label to apply to the upper-left of the box.
+    :param padding: How many columns of padding to apply inside.
+    :param upper_left: Upper-left single-width text decoration character.
+    :param lower_left: Lower-left single-width text decoration character.
+    :param horizontal: Horizontal single-width text decoration character.
+    :param vertical: Vertical single-width text decoration character.
+    """
+    if width is None or width < 0:
+        avail = shutil.get_terminal_size(fallback=(72, 24))[0]
+        if width is None:
+            _width = avail
+        else:
+            _width = avail + width
+    else:
+        _width = width
+
+    prefix = vertical + (' ' * padding)
+
+    def _bar(name: Optional[str], top: bool = True) -> str:
+        ret = upper_left if top else lower_left
+        if name is not None:
+            ret += f"{horizontal} {name} "
+
+        filler_len = _width - len(ret)
+        ret += f"{horizontal * filler_len}"
+        return ret
+
+    def _wrap(line: str) -> str:
+        return os.linesep.join(
+            textwrap.wrap(
+                line, width=_width - padding, initial_indent=prefix,
+                subsequent_indent=prefix, replace_whitespace=False,
+                drop_whitespace=True, break_on_hyphens=False)
+        )
+
+    return os.linesep.join((
+        _bar(name, top=True),
+        os.linesep.join(_wrap(line) for line in content.splitlines()),
+        _bar(None, top=False),
+    ))
-- 
2.34.1

[PATCH 2/5] python/utils: add VerboseProcessError

[John Snow]

This adds an Exception that extends the Python stdlib
subprocess.CalledProcessError.

The difference is that the str() method of this exception also adds the
stdout/stderr logs. In effect, if this exception goes unhandled, Python
will print the output in a visually distinct wrapper to the terminal so
that it's easy to spot in a sea of traceback information.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 python/qemu/utils/__init__.py | 36 +++++++++++++++++++++++++++++++++++
 1 file changed, 36 insertions(+)

diff --git a/python/qemu/utils/__init__.py b/python/qemu/utils/__init__.py
index 5babf40df2..355ac550bc 100644
--- a/python/qemu/utils/__init__.py
+++ b/python/qemu/utils/__init__.py
@@ -18,6 +18,7 @@
 import os
 import re
 import shutil
+from subprocess import CalledProcessError
 import textwrap
 from typing import Optional
 
@@ -26,6 +27,7 @@
 
 
 __all__ = (
+    'VerboseProcessError',
     'add_visual_margin',
     'get_info_usernet_hostfwd_port',
     'kvm_available',
@@ -121,3 +123,37 @@ def _wrap(line: str) -> str:
         os.linesep.join(_wrap(line) for line in content.splitlines()),
         _bar(None, top=False),
     ))
+
+
+class VerboseProcessError(CalledProcessError):
+    """
+    The same as CalledProcessError, but more verbose.
+
+    This is useful for debugging failed calls during test executions.
+    The return code, signal (if any), and terminal output will be displayed
+    on unhandled exceptions.
+    """
+    def summary(self) -> str:
+        """Return the normal CalledProcessError str() output."""
+        return super().__str__()
+
+    def __str__(self) -> str:
+        lmargin = '  '
+        width = -len(lmargin)
+        sections = []
+
+        name = 'output' if self.stderr is None else 'stdout'
+        if self.stdout:
+            sections.append(add_visual_margin(self.stdout, width, name))
+        else:
+            sections.append(f"{name}: N/A")
+
+        if self.stderr:
+            sections.append(add_visual_margin(self.stderr, width, 'stderr'))
+        elif self.stderr is not None:
+            sections.append("stderr: N/A")
+
+        return os.linesep.join((
+            self.summary(),
+            textwrap.indent(os.linesep.join(sections), prefix=lmargin),
+        ))
-- 
2.34.1

[PATCH 3/5] iotests: Remove explicit checks for qemu_img() == 0

[John Snow]

qemu_img() returning zero ought to be the rule, not the
exception. Remove all explicit checks against the condition in
preparation for making non-zero returns an Exception.

Signed-off-by: John Snow <jsnow@redhat.com>
Reviewed-by: Eric Blake <eblake@redhat.com>
---
 tests/qemu-iotests/163                             |  9 +++------
 tests/qemu-iotests/216                             |  6 +++---
 tests/qemu-iotests/218                             |  2 +-
 tests/qemu-iotests/224                             | 11 +++++------
 tests/qemu-iotests/228                             | 12 ++++++------
 tests/qemu-iotests/257                             |  3 +--
 tests/qemu-iotests/258                             |  4 ++--
 tests/qemu-iotests/310                             | 14 +++++++-------
 tests/qemu-iotests/tests/block-status-cache        |  3 +--
 tests/qemu-iotests/tests/image-fleecing            |  4 ++--
 tests/qemu-iotests/tests/mirror-ready-cancel-error |  6 ++----
 tests/qemu-iotests/tests/mirror-top-perms          |  3 +--
 .../qemu-iotests/tests/remove-bitmap-from-backing  |  8 ++++----
 tests/qemu-iotests/tests/stream-error-on-reset     |  4 ++--
 14 files changed, 40 insertions(+), 49 deletions(-)

diff --git a/tests/qemu-iotests/163 b/tests/qemu-iotests/163
index b8bfc95358..e4cd4b230f 100755
--- a/tests/qemu-iotests/163
+++ b/tests/qemu-iotests/163
@@ -107,8 +107,7 @@ class ShrinkBaseClass(iotests.QMPTestCase):
 
         if iotests.imgfmt == 'raw':
             return
-        self.assertEqual(qemu_img('check', test_img), 0,
-                         "Verifying image corruption")
+        qemu_img('check', test_img)
 
     def test_empty_image(self):
         qemu_img('resize',  '-f', iotests.imgfmt, '--shrink', test_img,
@@ -130,8 +129,7 @@ class ShrinkBaseClass(iotests.QMPTestCase):
         qemu_img('resize',  '-f', iotests.imgfmt, '--shrink', test_img,
                  self.shrink_size)
 
-        self.assertEqual(qemu_img("compare", test_img, check_img), 0,
-                         "Verifying image content")
+        qemu_img("compare", test_img, check_img)
 
         self.image_verify()
 
@@ -146,8 +144,7 @@ class ShrinkBaseClass(iotests.QMPTestCase):
         qemu_img('resize',  '-f', iotests.imgfmt, '--shrink', test_img,
                  self.shrink_size)
 
-        self.assertEqual(qemu_img("compare", test_img, check_img), 0,
-                         "Verifying image content")
+        qemu_img("compare", test_img, check_img)
 
         self.image_verify()
 
diff --git a/tests/qemu-iotests/216 b/tests/qemu-iotests/216
index c02f8d2880..88b385afa3 100755
--- a/tests/qemu-iotests/216
+++ b/tests/qemu-iotests/216
@@ -51,10 +51,10 @@ with iotests.FilePath('base.img') as base_img_path, \
     log('--- Setting up images ---')
     log('')
 
-    assert qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M') == 0
+    qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M')
     assert qemu_io_silent(base_img_path, '-c', 'write -P 1 0M 1M') == 0
-    assert qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
-                    '-F', iotests.imgfmt, top_img_path) == 0
+    qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
+             '-F', iotests.imgfmt, top_img_path)
     assert qemu_io_silent(top_img_path,  '-c', 'write -P 2 1M 1M') == 0
 
     log('Done')
diff --git a/tests/qemu-iotests/218 b/tests/qemu-iotests/218
index 4922b4d3b6..853ed52b34 100755
--- a/tests/qemu-iotests/218
+++ b/tests/qemu-iotests/218
@@ -145,7 +145,7 @@ log('')
 with iotests.VM() as vm, \
      iotests.FilePath('src.img') as src_img_path:
 
-    assert qemu_img('create', '-f', iotests.imgfmt, src_img_path, '64M') == 0
+    qemu_img('create', '-f', iotests.imgfmt, src_img_path, '64M')
     assert qemu_io_silent('-f', iotests.imgfmt, src_img_path,
                           '-c', 'write -P 42 0M 64M') == 0
 
diff --git a/tests/qemu-iotests/224 b/tests/qemu-iotests/224
index 38dd153625..c31c55b49d 100755
--- a/tests/qemu-iotests/224
+++ b/tests/qemu-iotests/224
@@ -47,12 +47,11 @@ for filter_node_name in False, True:
          iotests.FilePath('top.img') as top_img_path, \
          iotests.VM() as vm:
 
-        assert qemu_img('create', '-f', iotests.imgfmt,
-                        base_img_path, '64M') == 0
-        assert qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
-                        '-F', iotests.imgfmt, mid_img_path) == 0
-        assert qemu_img('create', '-f', iotests.imgfmt, '-b', mid_img_path,
-                        '-F', iotests.imgfmt, top_img_path) == 0
+        qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M')
+        qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
+                 '-F', iotests.imgfmt, mid_img_path)
+        qemu_img('create', '-f', iotests.imgfmt, '-b', mid_img_path,
+                 '-F', iotests.imgfmt, top_img_path)
 
         # Something to commit
         assert qemu_io_silent(mid_img_path, '-c', 'write -P 1 0 1M') == 0
diff --git a/tests/qemu-iotests/228 b/tests/qemu-iotests/228
index a5eda2e149..f79bae0267 100755
--- a/tests/qemu-iotests/228
+++ b/tests/qemu-iotests/228
@@ -54,11 +54,11 @@ with iotests.FilePath('base.img') as base_img_path, \
      iotests.FilePath('top.img') as top_img_path, \
      iotests.VM() as vm:
 
-    assert qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M') == 0
+    qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M')
     # Choose a funny way to describe the backing filename
-    assert qemu_img('create', '-f', iotests.imgfmt, '-b',
-                    'file:' + base_img_path, '-F', iotests.imgfmt,
-                    top_img_path) == 0
+    qemu_img('create', '-f', iotests.imgfmt, '-b',
+             'file:' + base_img_path, '-F', iotests.imgfmt,
+             top_img_path)
 
     vm.launch()
 
@@ -172,8 +172,8 @@ with iotests.FilePath('base.img') as base_img_path, \
     # (because qemu cannot "canonicalize"/"resolve" the backing
     # filename unless the backing file is opened implicitly with the
     # overlay)
-    assert qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
-                    '-F', iotests.imgfmt, top_img_path) == 0
+    qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
+             '-F', iotests.imgfmt, top_img_path)
 
     # You can only reliably override backing options by using a node
     # reference (or by specifying file.filename, but, well...)
diff --git a/tests/qemu-iotests/257 b/tests/qemu-iotests/257
index c72c82a171..fb5359c581 100755
--- a/tests/qemu-iotests/257
+++ b/tests/qemu-iotests/257
@@ -240,8 +240,7 @@ def compare_images(image, reference, baseimg=None, expected_match=True):
     """
     expected_ret = 0 if expected_match else 1
     if baseimg:
-        assert qemu_img("rebase", "-u", "-b", baseimg, '-F', iotests.imgfmt,
-                        image) == 0
+        qemu_img("rebase", "-u", "-b", baseimg, '-F', iotests.imgfmt, image)
     ret = qemu_img("compare", image, reference)
     log('qemu_img compare "{:s}" "{:s}" ==> {:s}, {:s}'.format(
         image, reference,
diff --git a/tests/qemu-iotests/258 b/tests/qemu-iotests/258
index a6618208a8..7798a04d7d 100755
--- a/tests/qemu-iotests/258
+++ b/tests/qemu-iotests/258
@@ -75,13 +75,13 @@ def test_concurrent_finish(write_to_stream_node):
 
         # It is important to use raw for the base layer (so that
         # permissions are just handed through to the protocol layer)
-        assert qemu_img('create', '-f', 'raw', node0_path, '64M') == 0
+        qemu_img('create', '-f', 'raw', node0_path, '64M')
 
         stream_throttle=None
         commit_throttle=None
 
         for path in [node1_path, node2_path, node3_path, node4_path]:
-            assert qemu_img('create', '-f', iotests.imgfmt, path, '64M') == 0
+            qemu_img('create', '-f', iotests.imgfmt, path, '64M')
 
         if write_to_stream_node:
             # This is what (most of the time) makes commit finish
diff --git a/tests/qemu-iotests/310 b/tests/qemu-iotests/310
index 33c3411869..4e6d70e5ac 100755
--- a/tests/qemu-iotests/310
+++ b/tests/qemu-iotests/310
@@ -43,15 +43,15 @@ with iotests.FilePath('base.img') as base_img_path, \
     log('--- Setting up images ---')
     log('')
 
-    assert qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M') == 0
+    qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M')
     assert qemu_io_silent(base_img_path, '-c', 'write -P 1 0M 1M') == 0
     assert qemu_io_silent(base_img_path, '-c', 'write -P 1 3M 1M') == 0
-    assert qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
-                    '-F', iotests.imgfmt, mid_img_path) == 0
+    qemu_img('create', '-f', iotests.imgfmt, '-b', base_img_path,
+             '-F', iotests.imgfmt, mid_img_path)
     assert qemu_io_silent(mid_img_path, '-c', 'write -P 3 2M 1M') == 0
     assert qemu_io_silent(mid_img_path, '-c', 'write -P 3 4M 1M') == 0
-    assert qemu_img('create', '-f', iotests.imgfmt, '-b', mid_img_path,
-                    '-F', iotests.imgfmt, top_img_path) == 0
+    qemu_img('create', '-f', iotests.imgfmt, '-b', mid_img_path,
+             '-F', iotests.imgfmt, top_img_path)
     assert qemu_io_silent(top_img_path, '-c', 'write -P 2 1M 1M') == 0
 
 #      0 1 2 3 4
@@ -105,8 +105,8 @@ with iotests.FilePath('base.img') as base_img_path, \
     log('')
 
     # Detach backing to check that we can read the data from the top level now
-    assert qemu_img('rebase', '-u', '-b', '', '-f', iotests.imgfmt,
-                    top_img_path) == 0
+    qemu_img('rebase', '-u', '-b', '', '-f', iotests.imgfmt,
+             top_img_path)
 
     assert qemu_io_silent(top_img_path, '-c', 'read -P 0 0 1M') == 0
     assert qemu_io_silent(top_img_path, '-c', 'read -P 2 1M 1M') == 0
diff --git a/tests/qemu-iotests/tests/block-status-cache b/tests/qemu-iotests/tests/block-status-cache
index 6fa10bb8f8..40e648e251 100755
--- a/tests/qemu-iotests/tests/block-status-cache
+++ b/tests/qemu-iotests/tests/block-status-cache
@@ -35,8 +35,7 @@ nbd_sock = os.path.join(iotests.sock_dir, 'nbd.sock')
 class TestBscWithNbd(iotests.QMPTestCase):
     def setUp(self) -> None:
         """Just create an empty image with a read-only NBD server on it"""
-        assert qemu_img_create('-f', iotests.imgfmt, test_img,
-                               str(image_size)) == 0
+        qemu_img_create('-f', iotests.imgfmt, test_img, str(image_size))
 
         # Pass --allocation-depth to enable the qemu:allocation-depth context,
         # which we are going to query to provoke a block-status inquiry with
diff --git a/tests/qemu-iotests/tests/image-fleecing b/tests/qemu-iotests/tests/image-fleecing
index a58b5a1781..ac8f19e506 100755
--- a/tests/qemu-iotests/tests/image-fleecing
+++ b/tests/qemu-iotests/tests/image-fleecing
@@ -53,8 +53,8 @@ def do_test(use_cbw, base_img_path, fleece_img_path, nbd_sock_path, vm):
     log('--- Setting up images ---')
     log('')
 
-    assert qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M') == 0
-    assert qemu_img('create', '-f', 'qcow2', fleece_img_path, '64M') == 0
+    qemu_img('create', '-f', iotests.imgfmt, base_img_path, '64M')
+    qemu_img('create', '-f', 'qcow2', fleece_img_path, '64M')
 
     for p in patterns:
         qemu_io('-f', iotests.imgfmt,
diff --git a/tests/qemu-iotests/tests/mirror-ready-cancel-error b/tests/qemu-iotests/tests/mirror-ready-cancel-error
index 770ffca379..1d0e333b5e 100755
--- a/tests/qemu-iotests/tests/mirror-ready-cancel-error
+++ b/tests/qemu-iotests/tests/mirror-ready-cancel-error
@@ -31,10 +31,8 @@ target = os.path.join(iotests.test_dir, 'target.img')
 
 class TestMirrorReadyCancelError(iotests.QMPTestCase):
     def setUp(self) -> None:
-        assert iotests.qemu_img_create('-f', iotests.imgfmt, source,
-                                       str(image_size)) == 0
-        assert iotests.qemu_img_create('-f', iotests.imgfmt, target,
-                                       str(image_size)) == 0
+        iotests.qemu_img_create('-f', iotests.imgfmt, source, str(image_size))
+        iotests.qemu_img_create('-f', iotests.imgfmt, target, str(image_size))
 
         # Ensure that mirror will copy something before READY so the
         # target format layer will forward the pre-READY flush to its
diff --git a/tests/qemu-iotests/tests/mirror-top-perms b/tests/qemu-iotests/tests/mirror-top-perms
index b5849978c4..6ac8d5efcc 100755
--- a/tests/qemu-iotests/tests/mirror-top-perms
+++ b/tests/qemu-iotests/tests/mirror-top-perms
@@ -34,8 +34,7 @@ source = os.path.join(iotests.test_dir, 'source.img')
 
 class TestMirrorTopPerms(iotests.QMPTestCase):
     def setUp(self):
-        assert qemu_img('create', '-f', iotests.imgfmt, source,
-                        str(image_size)) == 0
+        qemu_img('create', '-f', iotests.imgfmt, source, str(image_size))
         self.vm = iotests.VM()
         self.vm.add_drive(source)
         self.vm.add_blockdev(f'null-co,node-name=null,size={image_size}')
diff --git a/tests/qemu-iotests/tests/remove-bitmap-from-backing b/tests/qemu-iotests/tests/remove-bitmap-from-backing
index 3c397b08ea..fee3141340 100755
--- a/tests/qemu-iotests/tests/remove-bitmap-from-backing
+++ b/tests/qemu-iotests/tests/remove-bitmap-from-backing
@@ -27,11 +27,11 @@ iotests.script_initialize(supported_fmts=['qcow2'],
 top, base = iotests.file_path('top', 'base')
 size = '1M'
 
-assert qemu_img_create('-f', iotests.imgfmt, base, size) == 0
-assert qemu_img_create('-f', iotests.imgfmt, '-b', base,
-                       '-F', iotests.imgfmt, top, size) == 0
+qemu_img_create('-f', iotests.imgfmt, base, size)
+qemu_img_create('-f', iotests.imgfmt, '-b', base,
+                '-F', iotests.imgfmt, top, size)
 
-assert qemu_img('bitmap', '--add', base, 'bitmap0') == 0
+qemu_img('bitmap', '--add', base, 'bitmap0')
 # Just assert that our method of checking bitmaps in the image works.
 assert 'bitmaps' in qemu_img_pipe('info', base)
 
diff --git a/tests/qemu-iotests/tests/stream-error-on-reset b/tests/qemu-iotests/tests/stream-error-on-reset
index 7eaedb24d7..389ae822b8 100755
--- a/tests/qemu-iotests/tests/stream-error-on-reset
+++ b/tests/qemu-iotests/tests/stream-error-on-reset
@@ -54,9 +54,9 @@ class TestStreamErrorOnReset(QMPTestCase):
           to it will result in an error
         - top image is attached to a virtio-scsi device
         """
-        assert qemu_img_create('-f', imgfmt, base, str(image_size)) == 0
+        qemu_img_create('-f', imgfmt, base, str(image_size))
         assert qemu_io_silent('-c', f'write 0 {data_size}', base) == 0
-        assert qemu_img_create('-f', imgfmt, top, str(image_size)) == 0
+        qemu_img_create('-f', imgfmt, top, str(image_size))
 
         self.vm = iotests.VM()
         self.vm.add_args('-accel', 'tcg') # Make throttling work properly
-- 
2.34.1

[PATCH 4/5] iotests: make qemu_img raise on non-zero rc by default

[John Snow]

re-write qemu_img() as a function that will by default raise a
VerboseProcessException (extended from CalledProcessException) on
non-zero return codes. This will produce a stack trace that will show
the command line arguments and return code from the failed process run.

Users that want something more flexible (there appears to be only one)
can use check=False and manage the return themselves. However, when the
return code is negative, the Exception will be raised no matter what.
This is done under the belief that there's no legitimate reason, even in
negative tests, to see a crash from qemu-img.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 tests/qemu-iotests/257        |  8 ++++--
 tests/qemu-iotests/iotests.py | 54 +++++++++++++++++++++++++++++++----
 2 files changed, 53 insertions(+), 9 deletions(-)

diff --git a/tests/qemu-iotests/257 b/tests/qemu-iotests/257
index fb5359c581..e7e7a2317e 100755
--- a/tests/qemu-iotests/257
+++ b/tests/qemu-iotests/257
@@ -241,11 +241,13 @@ def compare_images(image, reference, baseimg=None, expected_match=True):
     expected_ret = 0 if expected_match else 1
     if baseimg:
         qemu_img("rebase", "-u", "-b", baseimg, '-F', iotests.imgfmt, image)
-    ret = qemu_img("compare", image, reference)
+
+    sub = qemu_img("compare", image, reference, check=False)
+
     log('qemu_img compare "{:s}" "{:s}" ==> {:s}, {:s}'.format(
         image, reference,
-        "Identical" if ret == 0 else "Mismatch",
-        "OK!" if ret == expected_ret else "ERROR!"),
+        "Identical" if sub.returncode == 0 else "Mismatch",
+        "OK!" if sub.returncode == expected_ret else "ERROR!"),
         filters=[iotests.filter_testfiles])
 
 def test_bitmap_sync(bsync_mode, msync_mode='bitmap', failure=None):
diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 6ba65eb1ff..f6c0f1b0a0 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -39,6 +39,7 @@
 
 from qemu.machine import qtest
 from qemu.qmp import QMPMessage
+from qemu.utils import VerboseProcessError
 
 # Use this logger for logging messages directly from the iotests module
 logger = logging.getLogger('qemu.iotests')
@@ -215,9 +216,49 @@ def qemu_img_pipe_and_status(*args: str) -> Tuple[str, int]:
     return qemu_tool_pipe_and_status('qemu-img', full_args,
                                      drop_successful_output=is_create)
 
-def qemu_img(*args: str) -> int:
-    '''Run qemu-img and return the exit code'''
-    return qemu_img_pipe_and_status(*args)[1]
+def qemu_img(*args: str, check: bool = True, combine_stdio: bool = True
+             ) -> subprocess.CompletedProcess[str]:
+    """
+    Run qemu_img and return the status code and console output.
+
+    This function always prepends QEMU_IMG_OPTIONS and may further alter
+    the args for 'create' commands.
+
+    :param args: command-line arguments to qemu-img.
+    :param check: Enforce a return code of zero.
+    :param combine_stdio: set to False to keep stdout/stderr separated.
+
+    :raise VerboseProcessError:
+        When the return code is negative, or on any non-zero exit code
+        when 'check=True' was provided (the default). This exception has
+        'stdout', 'stderr', and 'returncode' properties that may be
+        inspected to show greater detail. If this exception is not
+        handled, the command-line, return code, and all console output
+        will be included at the bottom of the stack trace.
+
+    :return: a CompletedProcess. This object has args, returncode, and
+        stdout properties. If streams are not combined, it will also
+        have a stderr property.
+    """
+    full_args = qemu_img_args + qemu_img_create_prepare_args(list(args))
+
+    subp = subprocess.run(
+        full_args,
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT if combine_stdio else subprocess.PIPE,
+        universal_newlines=True,
+        check=False
+    )
+
+    if check and subp.returncode or (subp.returncode < 0):
+        raise VerboseProcessError(
+            subp.returncode, full_args,
+            output=subp.stdout,
+            stderr=subp.stderr,
+        )
+
+    return subp
+
 
 def ordered_qmp(qmsg, conv_keys=True):
     # Dictionaries are not ordered prior to 3.6, therefore:
@@ -232,7 +273,7 @@ def ordered_qmp(qmsg, conv_keys=True):
         return od
     return qmsg
 
-def qemu_img_create(*args):
+def qemu_img_create(*args: str) -> subprocess.CompletedProcess[str]:
     return qemu_img('create', *args)
 
 def qemu_img_measure(*args):
@@ -435,8 +476,9 @@ def qemu_nbd_popen(*args):
 
 def compare_images(img1, img2, fmt1=imgfmt, fmt2=imgfmt):
     '''Return True if two image files are identical'''
-    return qemu_img('compare', '-f', fmt1,
-                    '-F', fmt2, img1, img2) == 0
+    res = qemu_img('compare', '-f', fmt1,
+                   '-F', fmt2, img1, img2, check=False)
+    return res.returncode == 0
 
 def create_image(name, size):
     '''Create a fully-allocated raw image with sector markers'''
-- 
2.34.1

[PATCH 5/5] iotests: fortify compare_images() against crashes

[John Snow]

Fority compare_images() to be more discerning about the status codes it
receives. If qemu_img() returns an exit code that implies it didn't
actually perform the comparison, treat that as an exceptional
circumstance and force the caller to be aware of the peril.

If a negative test is desired (Perhaps to test how qemu_img compare
behaves on malformed images, for instance), it is still possible to
catch the exception in the test and deal with that circumstance
manually.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 tests/qemu-iotests/iotests.py | 21 ++++++++++++++++-----
 1 file changed, 16 insertions(+), 5 deletions(-)

diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index f6c0f1b0a0..654ce834e6 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -474,11 +474,22 @@ def qemu_nbd_popen(*args):
             p.kill()
             p.wait()
 
-def compare_images(img1, img2, fmt1=imgfmt, fmt2=imgfmt):
-    '''Return True if two image files are identical'''
-    res = qemu_img('compare', '-f', fmt1,
-                   '-F', fmt2, img1, img2, check=False)
-    return res.returncode == 0
+def compare_images(img1: str, img2: str,
+                   fmt1: str = imgfmt, fmt2: str = imgfmt) -> bool:
+    """
+    Compare two images with QEMU_IMG; return True if they are identical.
+
+    :raise CalledProcessError:
+        when qemu-img crashes or returns a status code of anything other
+        than 0 (identical) or 1 (different).
+    """
+    try:
+        qemu_img('compare', '-f', fmt1, '-F', fmt2, img1, img2)
+        return True
+    except subprocess.CalledProcessError as exc:
+        if exc.returncode == 1:
+            return False
+        raise
 
 def create_image(name, size):
     '''Create a fully-allocated raw image with sector markers'''
-- 
2.34.1

Re: [PATCH 1/5] python/utils: add add_visual_margin() text decoration utility

[Eric Blake]

On Thu, Mar 03, 2022 at 03:58:58PM -0500, John Snow wrote:
> >>> print(add_visual_margin(msg, width=72, name="Commit Message"))
> ┏━ Commit Message ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
> ┃ add_visual_margin() takes a chunk of text and wraps it in a visual
> ┃ container that force-wraps to a specified width. An optional title
> ┃ label may be given, and any of the individual glyphs used to draw the
> ┃ box may be replaced or specified as well.
> ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

I see you dropped the right margin compared to earlier versions, but
agree that this is still a nice visual indicator, and probably easier
to maintain in this form.  And it got rid of the weird spacing on the
left when the wrap point hit at the wrong time.

> +    Decorate and wrap some text with a visual decoration around it.
> +
> +    This function assumes that the text decoration characters are single
> +    characters that display using a single monospace column.
> +
> +    ┏━ Example ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
> +    ┃ This is what this function looks like with text content that's
> +    ┃ wrapped to 72 characters. The right-hand margin is left open to
> +    ┃ acommodate the occasional unicode character that might make
> +    ┃ predicting the total "visual" width of a line difficult. This
> +    ┃ provides a visual distinction that's good-enough, though.
> +    ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

Yep - hand-waving away Unicode messiness is certainly easiest ;)

Reviewed-by: Eric Blake <eblake@redhat.com>

[take with a grain of salt - my python is weak. But as you said in the
cover letter, it's fairly straightforward to reproduce an environment
where you can see it in action for hands-on testing]

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [PATCH 2/5] python/utils: add VerboseProcessError

[Eric Blake]

On Thu, Mar 03, 2022 at 03:58:59PM -0500, John Snow wrote:
> This adds an Exception that extends the Python stdlib
> subprocess.CalledProcessError.
> 
> The difference is that the str() method of this exception also adds the
> stdout/stderr logs. In effect, if this exception goes unhandled, Python
> will print the output in a visually distinct wrapper to the terminal so
> that it's easy to spot in a sea of traceback information.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  python/qemu/utils/__init__.py | 36 +++++++++++++++++++++++++++++++++++
>  1 file changed, 36 insertions(+)
>

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [PATCH 4/5] iotests: make qemu_img raise on non-zero rc by default

[Eric Blake]

On Thu, Mar 03, 2022 at 03:59:01PM -0500, John Snow wrote:
> re-write qemu_img() as a function that will by default raise a
> VerboseProcessException (extended from CalledProcessException) on
> non-zero return codes. This will produce a stack trace that will show
> the command line arguments and return code from the failed process run.
> 
> Users that want something more flexible (there appears to be only one)
> can use check=False and manage the return themselves. However, when the
> return code is negative, the Exception will be raised no matter what.
> This is done under the belief that there's no legitimate reason, even in
> negative tests, to see a crash from qemu-img.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  tests/qemu-iotests/257        |  8 ++++--
>  tests/qemu-iotests/iotests.py | 54 +++++++++++++++++++++++++++++++----
>  2 files changed, 53 insertions(+), 9 deletions(-)
>

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [PATCH 5/5] iotests: fortify compare_images() against crashes

[Eric Blake]

On Thu, Mar 03, 2022 at 03:59:02PM -0500, John Snow wrote:
> Fority compare_images() to be more discerning about the status codes it

Fortify

> receives. If qemu_img() returns an exit code that implies it didn't
> actually perform the comparison, treat that as an exceptional
> circumstance and force the caller to be aware of the peril.
> 
> If a negative test is desired (Perhaps to test how qemu_img compare

perhaps

> behaves on malformed images, for instance), it is still possible to
> catch the exception in the test and deal with that circumstance
> manually.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  tests/qemu-iotests/iotests.py | 21 ++++++++++++++++-----
>  1 file changed, 16 insertions(+), 5 deletions(-)

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [PATCH 1/5] python/utils: add add_visual_margin() text decoration utility

[John Snow]

[-- Attachment #1: Type: text/plain, Size: 3700 bytes --]

On Thu, Mar 3, 2022, 5:43 PM Eric Blake <eblake@redhat.com> wrote:

> On Thu, Mar 03, 2022 at 03:58:58PM -0500, John Snow wrote:
> > >>> print(add_visual_margin(msg, width=72, name="Commit Message"))
> > ┏━ Commit Message ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
> > ┃ add_visual_margin() takes a chunk of text and wraps it in a visual
> > ┃ container that force-wraps to a specified width. An optional title
> > ┃ label may be given, and any of the individual glyphs used to draw the
> > ┃ box may be replaced or specified as well.
> > ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
>
> I see you dropped the right margin compared to earlier versions, but
> agree that this is still a nice visual indicator, and probably easier
> to maintain in this form.  And it got rid of the weird spacing on the
> left when the wrap point hit at the wrong time.
>
> > +    Decorate and wrap some text with a visual decoration around it.
> > +
> > +    This function assumes that the text decoration characters are single
> > +    characters that display using a single monospace column.
> > +
> > +    ┏━ Example
> ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
> > +    ┃ This is what this function looks like with text content that's
> > +    ┃ wrapped to 72 characters. The right-hand margin is left open to
> > +    ┃ acommodate the occasional unicode character that might make
> > +    ┃ predicting the total "visual" width of a line difficult. This
> > +    ┃ provides a visual distinction that's good-enough, though.
> > +
> ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
>
> Yep - hand-waving away Unicode messiness is certainly easiest ;)
>

I started reading the unicode specification for determining the number of
"visual grapheme clusters" in a string, got a headache, and gave up.

(See also the PyPI package "grapheme", which was last updated for unicode
13.0 and appears unmaintained. It's no small amount of code!)

I could write a function that gives a *pretty good estimate*, but I don't
want to maintain something like that.

Urwid has functions that give *great* estimates, but I'd like to avoid
dependencies.

Leaving the right margin open was the quickest, cleanest hack :) I'm amazed
at how hard this is to accomplish.

(See https://hsivonen.fi/string-length/ which ought to be required reading
in all CS classes from now on.)

Ultimately I took both this decoration and the exception code into utils as
an admission of guilt and a pledge to maintain what I did write ;)


> Reviewed-by: Eric Blake <eblake@redhat.com>
>
> [take with a grain of salt - my python is weak. But as you said in the
> cover letter, it's fairly straightforward to reproduce an environment
> where you can see it in action for hands-on testing]
>

I've long since given up on anyone understanding the Python I write.
Eduardo did, so he quit. 😅

Thanks for the reviews.


>
> --
> Eric Blake, Principal Software Engineer
> Red Hat, Inc.           +1-919-301-3266
> Virtualization:  qemu.org | libvirt.org
>
>

[-- Attachment #2: Type: text/html, Size: 5334 bytes --]