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

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

[John Snow]

V3:
 - Rebase on origin/master
 - Expand 3/5 to cover new uses upstream
 - Fix reflow nit by eblake on 3/5

V2:
 - Rebase on top of kwolf's latest PR.
 - Adjust tests/graph-changes-while-io in patch 3/5
 - Drop eblake's r-b on 3/5.

This is 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!)

NOTES:

(1) 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.

(2) ... And then another 10 or so to give the same treatment to all
qemu_io() calls.

(3) ... And I'm working on the same for qemu_nbd(). Ultimately I want to
make every last subprocess call one that's checked and can produce nice
diagnostic info to the terminal if it goes unhandled.

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                        |  13 +-
 tests/qemu-iotests/iotests.py                 |  71 +++++++++--
 tests/qemu-iotests/tests/block-status-cache   |   3 +-
 .../qemu-iotests/tests/graph-changes-while-io |   7 +-
 tests/qemu-iotests/tests/image-fleecing       |  10 +-
 .../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 +-
 17 files changed, 226 insertions(+), 68 deletions(-)

-- 
2.34.1

[PATCH v3 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>
Reviewed-by: Eric Blake <eblake@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 v3 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>
Reviewed-by: Eric Blake <eblake@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 v3 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>
---
 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                              | 13 ++++++-------
 tests/qemu-iotests/tests/block-status-cache         |  3 +--
 tests/qemu-iotests/tests/graph-changes-while-io     |  7 +++----
 tests/qemu-iotests/tests/image-fleecing             | 10 +++++-----
 tests/qemu-iotests/tests/mirror-ready-cancel-error  |  6 ++----
 tests/qemu-iotests/tests/mirror-top-perms           |  3 +--
 tests/qemu-iotests/tests/remove-bitmap-from-backing |  8 ++++----
 tests/qemu-iotests/tests/stream-error-on-reset      |  4 ++--
 15 files changed, 45 insertions(+), 56 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..e3bfedc7fd 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,7 @@ 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/graph-changes-while-io b/tests/qemu-iotests/tests/graph-changes-while-io
index 567e8cf21e..7664f33689 100755
--- a/tests/qemu-iotests/tests/graph-changes-while-io
+++ b/tests/qemu-iotests/tests/graph-changes-while-io
@@ -34,16 +34,15 @@ def do_qemu_img_bench() -> None:
     """
     Do some I/O requests on `nbd_sock`.
     """
-    assert qemu_img('bench', '-f', 'raw', '-c', '2000000',
-                    f'nbd+unix:///node0?socket={nbd_sock}') == 0
+    qemu_img('bench', '-f', 'raw', '-c', '2000000',
+             f'nbd+unix:///node0?socket={nbd_sock}')
 
 
 class TestGraphChangesWhileIO(QMPTestCase):
     def setUp(self) -> None:
         # Create an overlay that can be added at runtime on top of the
         # null-co block node that will receive I/O
-        assert qemu_img_create('-f', imgfmt, '-F', 'raw', '-b', 'null-co://',
-                               top) == 0
+        qemu_img_create('-f', imgfmt, '-F', 'raw', '-b', 'null-co://', top)
 
         # QSD instance with a null-co block node in an I/O thread,
         # exported over NBD (on `nbd_sock`, export name "node0")
diff --git a/tests/qemu-iotests/tests/image-fleecing b/tests/qemu-iotests/tests/image-fleecing
index c56278639c..b7e5076104 100755
--- a/tests/qemu-iotests/tests/image-fleecing
+++ b/tests/qemu-iotests/tests/image-fleecing
@@ -63,18 +63,18 @@ def do_test(vm, use_cbw, use_snapshot_access_filter, 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')
     if bitmap:
-        assert qemu_img('bitmap', '--add', base_img_path, 'bitmap0') == 0
+        qemu_img('bitmap', '--add', base_img_path, 'bitmap0')
 
     if use_snapshot_access_filter:
         assert use_cbw
-        assert qemu_img('create', '-f', 'raw', fleece_img_path, '64M') == 0
+        qemu_img('create', '-f', 'raw', fleece_img_path, '64M')
     else:
-        assert qemu_img('create', '-f', 'qcow2', fleece_img_path, '64M') == 0
+        qemu_img('create', '-f', 'qcow2', fleece_img_path, '64M')
 
     if push_backup:
-        assert qemu_img('create', '-f', 'qcow2', target_img_path, '64M') == 0
+        qemu_img('create', '-f', 'qcow2', target_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 v3 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>
Reviewed-by: Eric Blake <eblake@redhat.com>
---
 tests/qemu-iotests/257        |  8 +++--
 tests/qemu-iotests/iotests.py | 56 ++++++++++++++++++++++++++++++-----
 2 files changed, 54 insertions(+), 10 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 508adade9e..ec4568b24a 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -37,9 +37,10 @@
 
 from contextlib import contextmanager
 
+from qemu.aqmp.legacy import QEMUMonitorProtocol
 from qemu.machine import qtest
 from qemu.qmp import QMPMessage
-from qemu.aqmp.legacy import QEMUMonitorProtocol
+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):
@@ -467,8 +508,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 v3 5/5] iotests: fortify compare_images() against crashes

[John Snow]

Fortify 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>
Reviewed-by: Eric Blake <eblake@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 ec4568b24a..7057db0686 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -506,11 +506,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 v3 3/5] iotests: Remove explicit checks for qemu_img() == 0

[Eric Blake]

On Mon, Mar 07, 2022 at 08:57:26PM -0500, John Snow wrote:
> 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>

As this is a testsuite improvement rather than a new feature, I think
it's fine for the series to go in during soft freeze.

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

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

[John Snow]

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

On Tue, Mar 8, 2022, 10:16 AM Eric Blake <eblake@redhat.com> wrote:

> On Mon, Mar 07, 2022 at 08:57:26PM -0500, John Snow wrote:
> > 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>
>
> As this is a testsuite improvement rather than a new feature, I think
> it's fine for the series to go in during soft freeze.
>

Yup, I agree. I'd like to move this in sooner rather than later to guard
against rot, and to have the better failure messages during testing season.

I have followup patches that finish the audit of qemu-img calls. It's less
clear if those should also go in during soft freeze, but I suppose I can
send them and we can see how confident we feel about it.

(Also note, I am giving the same treatment to qemu-io in another branch,
too. That branch has revealed actual logical errors in our testing in
several places. That series isn't 100% ready yet, but it might also qualify
for freeze because it fixes real test defects.)


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

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

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

[Hanna Reitz]

On 08.03.22 02:57, 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>
> Reviewed-by: Eric Blake <eblake@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:

What exactly is this condition for?  I would’ve understood if it was 
`self.stdout` (because the stdout section then is called just “output”, 
so it would make sense to omit the stderr block), but this way it looks 
like we’ll only go here if `self.stderr` is an empty string (which 
doesn’t make much sense to me, and I don’t understand why we wouldn’t 
have the same in the `self.stdout` part above).

(tl;dr: should this be `self.stdout`?)

Hanna

> +            sections.append("stderr: N/A")
> +
> +        return os.linesep.join((
> +            self.summary(),
> +            textwrap.indent(os.linesep.join(sections), prefix=lmargin),
> +        ))

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

[Hanna Reitz]

On 08.03.22 02:57, 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.

Why not qemu_img_pipe_and_status() as the central function where all 
qemu-img calls go through?

It seems like this makes qemu_img() a second version of 
qemu_img_pipe_and_status(), which is a bit weird.

(Or perhaps it should actually be qemu_tool_pipe_and_status() that 
receives this treatment, with qemu-io functions just passing check=False 
by default.)

> 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>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> ---
>   tests/qemu-iotests/257        |  8 +++--
>   tests/qemu-iotests/iotests.py | 56 ++++++++++++++++++++++++++++++-----
>   2 files changed, 54 insertions(+), 10 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 508adade9e..ec4568b24a 100644
> --- a/tests/qemu-iotests/iotests.py
> +++ b/tests/qemu-iotests/iotests.py
> @@ -37,9 +37,10 @@
>   
>   from contextlib import contextmanager
>   
> +from qemu.aqmp.legacy import QEMUMonitorProtocol
>   from qemu.machine import qtest
>   from qemu.qmp import QMPMessage
> -from qemu.aqmp.legacy import QEMUMonitorProtocol
> +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):

I wouldn’t expect these parentheses here in any other language, are they 
required in Python?

> +        raise VerboseProcessError(
> +            subp.returncode, full_args,
> +            output=subp.stdout,
> +            stderr=subp.stderr,
> +        )

I trust these parameters are correct, because it really sometimes seems 
like Python doc doesn’t want to tell me about the arguments that 
constructors take.  (The only thing I found out is that `stdout` works 
as an alias for `output`, so passing `output` here and reading 
`self.stdout` in `VerboseProcesError` should(tm) be fine.)

Hanna

> +
> +    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):
> @@ -467,8 +508,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'''

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

[Hanna Reitz]

On 08.03.22 02:57, John Snow wrote:
> 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>
> ---
>   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                              | 13 ++++++-------
>   tests/qemu-iotests/tests/block-status-cache         |  3 +--
>   tests/qemu-iotests/tests/graph-changes-while-io     |  7 +++----
>   tests/qemu-iotests/tests/image-fleecing             | 10 +++++-----
>   tests/qemu-iotests/tests/mirror-ready-cancel-error  |  6 ++----
>   tests/qemu-iotests/tests/mirror-top-perms           |  3 +--
>   tests/qemu-iotests/tests/remove-bitmap-from-backing |  8 ++++----
>   tests/qemu-iotests/tests/stream-error-on-reset      |  4 ++--
>   15 files changed, 45 insertions(+), 56 deletions(-)

Reviewed-by: Hanna Reitz <hreitz@redhat.com>

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

[Hanna Reitz]

On 08.03.22 02:57, John Snow wrote:
> Fortify 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>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> ---
>   tests/qemu-iotests/iotests.py | 21 ++++++++++++++++-----
>   1 file changed, 16 insertions(+), 5 deletions(-)

Reviewed-by: Hanna Reitz <hreitz@redhat.com>

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

[Hanna Reitz]

On 08.03.22 02:57, 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.
> ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
>
> Signed-off-by: John Snow <jsnow@redhat.com>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> ---
>   python/qemu/utils/__init__.py | 78 +++++++++++++++++++++++++++++++++++
>   1 file changed, 78 insertions(+)

Acked-by: Hanna Reitz <hreitz@redhat.com>

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

[Hanna Reitz]

On 17.03.22 11:25, Hanna Reitz wrote:
> On 08.03.22 02:57, 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.
>
> Why not qemu_img_pipe_and_status() as the central function where all 
> qemu-img calls go through?

OK, I see that your follow-up series effectively does this.  Still 
wondering why this patch here doesn’t touch qemu_img_pipe_and_status() 
instead.

> It seems like this makes qemu_img() a second version of 
> qemu_img_pipe_and_status(), which is a bit weird.
>
> (Or perhaps it should actually be qemu_tool_pipe_and_status() that 
> receives this treatment, with qemu-io functions just passing 
> check=False by default.)

(And perhaps this, but I guess qemu-io is the only other real user of 
qemu_tool_pipe_and_status(), so if it doesn’t care, then there’s no real 
reason to change that function.)

Hanna

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

[John Snow]

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

On Thu, Mar 17, 2022, 6:41 AM Hanna Reitz <hreitz@redhat.com> wrote:

> On 17.03.22 11:25, Hanna Reitz wrote:
> > On 08.03.22 02:57, 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.
> >
> > Why not qemu_img_pipe_and_status() as the central function where all
> > qemu-img calls go through?
>
> OK, I see that your follow-up series effectively does this.  Still
> wondering why this patch here doesn’t touch qemu_img_pipe_and_status()
> instead.
>

Just a bad habit, I guess. It's the way I wrote this series: add a new
thing, then move the old things over to use it gradually.

This patchset (and the next) is pretty much the order I actually wrote it
in.

I do prefer the shorter name qemu_img() for this fn, tho.

(I struggle a lot with the order I write not being the order most people
prefer for reading. I feel like I've never quite gotten that correct. I
suppose I like to work backwards: start at the code I want and work
backwards until it works again.)


> > It seems like this makes qemu_img() a second version of
> > qemu_img_pipe_and_status(), which is a bit weird.
> >
> > (Or perhaps it should actually be qemu_tool_pipe_and_status() that
> > receives this treatment, with qemu-io functions just passing
> > check=False by default.)
>
> (And perhaps this, but I guess qemu-io is the only other real user of
> qemu_tool_pipe_and_status(), so if it doesn’t care, then there’s no real
> reason to change that function.)
>

Similar reasoning: I'm not actually sure I can justify the change
everywhere yet. I worked through all of qemu-io, but calls to qemu-nbd and
qemu itself are not yet audited.

In the end, that's the goal. Working my way backwards until replacing all
of these functions, yes.

Sorry for my backwards brain, maybe. I felt doing it this way got us the
most benefit the quickest.


> Hanna
>
>

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

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

[John Snow]

On Thu, Mar 17, 2022 at 5:23 AM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 08.03.22 02:57, 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>
> > Reviewed-by: Eric Blake <eblake@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:
>
> What exactly is this condition for?  I would’ve understood if it was
> `self.stdout` (because the stdout section then is called just “output”,
> so it would make sense to omit the stderr block), but this way it looks
> like we’ll only go here if `self.stderr` is an empty string (which
> doesn’t make much sense to me, and I don’t understand why we wouldn’t
> have the same in the `self.stdout` part above).
>
> (tl;dr: should this be `self.stdout`?)
>
> Hanna
>

if self.stderr is None, it means that the IO streams were combined. If
it is merely empty, it means there wasn't any stderr output.

so:

if self.stderr: There's content here, so put it in a lil' box
else: could be either None or the empty string. If it's None, we
didn't *have* a stderr, so don't print anything at all, let the
"output" section above handle it. If we did have stderr and it just
happened to be empty, write N/A.

I wanted that "N/A" to provide active feedback to show the human
operator that we're not just failing to show them what the stderr
output was: there genuinely wasn't any.

> > +            sections.append("stderr: N/A")
> > +
> > +        return os.linesep.join((
> > +            self.summary(),
> > +            textwrap.indent(os.linesep.join(sections), prefix=lmargin),
> > +        ))
>

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

[John Snow]

On Thu, Mar 17, 2022 at 6:25 AM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 08.03.22 02:57, John Snow wrote:

> > +    if check and subp.returncode or (subp.returncode < 0):
>
> I wouldn’t expect these parentheses here in any other language, are they
> required in Python?
>

It's not required, I just find it easier to read this way.

> > +        raise VerboseProcessError(
> > +            subp.returncode, full_args,
> > +            output=subp.stdout,
> > +            stderr=subp.stderr,
> > +        )
>
> I trust these parameters are correct, because it really sometimes seems
> like Python doc doesn’t want to tell me about the arguments that
> constructors take.  (The only thing I found out is that `stdout` works
> as an alias for `output`, so passing `output` here and reading
> `self.stdout` in `VerboseProcesError` should(tm) be fine.)
>

>>> import subprocess
>>> help(subprocess.CalledProcessError)

 |  __init__(self, returncode, cmd, output=None, stderr=None)
 |      Initialize self.  See help(type(self)) for accurate signature.

It should be fine :tm:

--js

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

[Hanna Reitz]

On 17.03.22 16:13, John Snow wrote:
> On Thu, Mar 17, 2022 at 5:23 AM Hanna Reitz <hreitz@redhat.com> wrote:
>> On 08.03.22 02:57, 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>
>>> Reviewed-by: Eric Blake <eblake@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:
>> What exactly is this condition for?  I would’ve understood if it was
>> `self.stdout` (because the stdout section then is called just “output”,
>> so it would make sense to omit the stderr block), but this way it looks
>> like we’ll only go here if `self.stderr` is an empty string (which
>> doesn’t make much sense to me, and I don’t understand why we wouldn’t
>> have the same in the `self.stdout` part above).
>>
>> (tl;dr: should this be `self.stdout`?)
>>
>> Hanna
>>
> if self.stderr is None, it means that the IO streams were combined. If
> it is merely empty, it means there wasn't any stderr output.

Might warrant a comment? :)

> so:
>
> if self.stderr: There's content here, so put it in a lil' box
> else: could be either None or the empty string. If it's None, we
> didn't *have* a stderr, so don't print anything at all, let the
> "output" section above handle it. If we did have stderr and it just
> happened to be empty, write N/A.
>
> I wanted that "N/A" to provide active feedback to show the human
> operator that we're not just failing to show them what the stderr
> output was: there genuinely wasn't any.

Thanks, that makes sense.

Reviewed-by: Hanna Reitz <hreitz@redhat.com>

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

[Hanna Reitz]

On 17.03.22 16:24, John Snow wrote:
> On Thu, Mar 17, 2022 at 6:25 AM Hanna Reitz <hreitz@redhat.com> wrote:
>> On 08.03.22 02:57, John Snow wrote:
>>> +    if check and subp.returncode or (subp.returncode < 0):
>> I wouldn’t expect these parentheses here in any other language, are they
>> required in Python?
>>
> It's not required, I just find it easier to read this way.

Oh well.

>>> +        raise VerboseProcessError(
>>> +            subp.returncode, full_args,
>>> +            output=subp.stdout,
>>> +            stderr=subp.stderr,
>>> +        )
>> I trust these parameters are correct, because it really sometimes seems
>> like Python doc doesn’t want to tell me about the arguments that
>> constructors take.  (The only thing I found out is that `stdout` works
>> as an alias for `output`, so passing `output` here and reading
>> `self.stdout` in `VerboseProcesError` should(tm) be fine.)
>>
>>>> import subprocess
>>>> help(subprocess.CalledProcessError)
>   |  __init__(self, returncode, cmd, output=None, stderr=None)
>   |      Initialize self.  See help(type(self)) for accurate signature.
>
> It should be fine :tm:

The things you learn...

Hanna

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

[Hanna Reitz]

On 08.03.22 02:57, 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>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> ---
>   tests/qemu-iotests/257        |  8 +++--
>   tests/qemu-iotests/iotests.py | 56 ++++++++++++++++++++++++++++++-----
>   2 files changed, 54 insertions(+), 10 deletions(-)

Reviewed-by: Hanna Reitz <hreitz@redhat.com>

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

[John Snow]

On Thu, Mar 17, 2022 at 11:56 AM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 17.03.22 16:13, John Snow wrote:
> > On Thu, Mar 17, 2022 at 5:23 AM Hanna Reitz <hreitz@redhat.com> wrote:
> >> On 08.03.22 02:57, 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>
> >>> Reviewed-by: Eric Blake <eblake@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:
> >> What exactly is this condition for?  I would’ve understood if it was
> >> `self.stdout` (because the stdout section then is called just “output”,
> >> so it would make sense to omit the stderr block), but this way it looks
> >> like we’ll only go here if `self.stderr` is an empty string (which
> >> doesn’t make much sense to me, and I don’t understand why we wouldn’t
> >> have the same in the `self.stdout` part above).
> >>
> >> (tl;dr: should this be `self.stdout`?)
> >>
> >> Hanna
> >>
> > if self.stderr is None, it means that the IO streams were combined. If
> > it is merely empty, it means there wasn't any stderr output.
>
> Might warrant a comment? :)

How 'bout:

has_combined_output = self.stderr is None

>
> > so:
> >
> > if self.stderr: There's content here, so put it in a lil' box
> > else: could be either None or the empty string. If it's None, we
> > didn't *have* a stderr, so don't print anything at all, let the
> > "output" section above handle it. If we did have stderr and it just
> > happened to be empty, write N/A.
> >
> > I wanted that "N/A" to provide active feedback to show the human
> > operator that we're not just failing to show them what the stderr
> > output was: there genuinely wasn't any.
>
> Thanks, that makes sense.
>
> Reviewed-by: Hanna Reitz <hreitz@redhat.com>
>

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

[Hanna Reitz]

On 17.03.22 17:31, John Snow wrote:
> On Thu, Mar 17, 2022 at 11:56 AM Hanna Reitz <hreitz@redhat.com> wrote:
>> On 17.03.22 16:13, John Snow wrote:
>>> On Thu, Mar 17, 2022 at 5:23 AM Hanna Reitz <hreitz@redhat.com> wrote:
>>>> On 08.03.22 02:57, 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>
>>>>> Reviewed-by: Eric Blake <eblake@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:
>>>> What exactly is this condition for?  I would’ve understood if it was
>>>> `self.stdout` (because the stdout section then is called just “output”,
>>>> so it would make sense to omit the stderr block), but this way it looks
>>>> like we’ll only go here if `self.stderr` is an empty string (which
>>>> doesn’t make much sense to me, and I don’t understand why we wouldn’t
>>>> have the same in the `self.stdout` part above).
>>>>
>>>> (tl;dr: should this be `self.stdout`?)
>>>>
>>>> Hanna
>>>>
>>> if self.stderr is None, it means that the IO streams were combined. If
>>> it is merely empty, it means there wasn't any stderr output.
>> Might warrant a comment? :)
> How 'bout:
>
> has_combined_output = self.stderr is None

That would be better, although I’m not quite sure I’d immediately know 
what this means.  Something like “Does self.stdout contain both stdout 
and stderr?” above it would clear my potential and/or assumed confusion, 
I believe.

Hanna

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

[John Snow]

On Thu, Mar 17, 2022 at 12:34 PM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 17.03.22 17:31, John Snow wrote:
> > On Thu, Mar 17, 2022 at 11:56 AM Hanna Reitz <hreitz@redhat.com> wrote:
> >> On 17.03.22 16:13, John Snow wrote:
> >>> On Thu, Mar 17, 2022 at 5:23 AM Hanna Reitz <hreitz@redhat.com> wrote:
> >>>> On 08.03.22 02:57, 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>
> >>>>> Reviewed-by: Eric Blake <eblake@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:
> >>>> What exactly is this condition for?  I would’ve understood if it was
> >>>> `self.stdout` (because the stdout section then is called just “output”,
> >>>> so it would make sense to omit the stderr block), but this way it looks
> >>>> like we’ll only go here if `self.stderr` is an empty string (which
> >>>> doesn’t make much sense to me, and I don’t understand why we wouldn’t
> >>>> have the same in the `self.stdout` part above).
> >>>>
> >>>> (tl;dr: should this be `self.stdout`?)
> >>>>
> >>>> Hanna
> >>>>
> >>> if self.stderr is None, it means that the IO streams were combined. If
> >>> it is merely empty, it means there wasn't any stderr output.
> >> Might warrant a comment? :)
> > How 'bout:
> >
> > has_combined_output = self.stderr is None
>
> That would be better, although I’m not quite sure I’d immediately know
> what this means.  Something like “Does self.stdout contain both stdout
> and stderr?” above it would clear my potential and/or assumed confusion,
> I believe.

Sure thing.

(Thanks!)