[PATCH 0/4] iotests: add detailed tracebacks to qemu_img() failures

[John Snow]

It came to my attention via th_huth that iotest 065 would crash in a way
that was largely silent, except for the async QMP traces. The real cause
turns out to be that iotest 065 does not support ztsd being compiled out
of the build, so the qemu-img command fails ... silently.
(And then everything after it explodes nastily.)

Almost every user of iotests.qemu_img() does not check the return code,
a few assert it to be zero, and exactly one user asserts it to be
non-zero. qemu_img() is already throwing away process output, too, so no
callers are using that information, either.

Therefore: add an Exception to qemu_img(), with some zazz.

RFC: I didn't attempt to clean up the other dozen function helpers we
have. It's possible we can unify and consolidate cases a bit, but I
wanted to test the waters with a smaller...ish incision first. qemu_io
and qemu_nbd are candidates for this treatment, and using the same
terminal decorations for the VMLaunchError in machine.py is also worth
looking into.

To see this in action, you could configure your QEMU to omit zstd
support and then run ./check -qcow2 065. It'd look something like below:

After:

065   fail       [16:26:17] [16:26:18]   0.3s   (last: 0.4s)  failed, exit 
status 1
--- /home/jsnow/src/qemu/tests/qemu-iotests/065.out
+++ 065.out.bad
@@ -1,5 +1,64 @@
-........
+....EEE.
+======================================================================
+ERROR: test_qmp (__main__.TestQCow3LazyQMP)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 74, in setUp
+    self.TestImageInfoSpecific.setUp(self)
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 38, in setUp
+    qemu_img('create', '-f', iotests.imgfmt, '-o', self.img_options,
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/iotests.py", line 289, in 
qemu_img
+    raise VerboseProcessError(
+iotests.VerboseProcessError: Command 
'['/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/../../qemu-img', 'create', 
'-f', 'qcow2', '-o', 'compat=1.1,lazy_refcounts=on,compression_type=zstd', 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img', '128K']' 
returned non-zero exit status 1.
+  ┏━ output 
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
+  ┃ Formatting                                                                 
┃
+  ┃ '/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img',        
┃
+  ┃ fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zstd         
┃
+  ┃ size=131072 compat=1.1 lazy_refcounts=on refcount_bits=16                  
┃
+  ┃ qemu-img:                                                                  
┃
+  ┃ /home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img:          
┃
+  ┃ Parameter 'compression-type' does not accept value 'zstd'                  
┃
+  
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛
+
+======================================================================
+ERROR: test_human (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 38, in setUp
+    qemu_img('create', '-f', iotests.imgfmt, '-o', self.img_options,
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/iotests.py", line 289, in 
qemu_img
+    raise VerboseProcessError(
+iotests.VerboseProcessError: Command 
'['/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/../../qemu-img', 'create', 
'-f', 'qcow2', '-o', 'compat=1.1,lazy_refcounts=off,compression_type=zstd', 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img', '128K']' 
returned non-zero exit status 1.
+  ┏━ output 
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
+  ┃ Formatting                                                                 
┃
+  ┃ '/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img',        
┃
+  ┃ fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zstd         
┃
+  ┃ size=131072 compat=1.1 lazy_refcounts=off refcount_bits=16                 
┃
+  ┃ qemu-img:                                                                  
┃
+  ┃ /home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img:          
┃
+  ┃ Parameter 'compression-type' does not accept value 'zstd'                  
┃
+  
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛
+
+======================================================================
+ERROR: test_json (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 38, in setUp
+    qemu_img('create', '-f', iotests.imgfmt, '-o', self.img_options,
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/iotests.py", line 289, in 
qemu_img
+    raise VerboseProcessError(
+iotests.VerboseProcessError: Command 
'['/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/../../qemu-img', 'create', 
'-f', 'qcow2', '-o', 'compat=1.1,lazy_refcounts=off,compression_type=zstd', 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img', '128K']' 
returned non-zero exit status 1.
+  ┏━ output 
━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
+  ┃ Formatting                                                                 
┃
+  ┃ '/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img',        
┃
+  ┃ fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zstd         
┃
+  ┃ size=131072 compat=1.1 lazy_refcounts=off refcount_bits=16                 
┃
+  ┃ qemu-img:                                                                  
┃
+  ┃ /home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img:          
┃
+  ┃ Parameter 'compression-type' does not accept value 'zstd'                  
┃
+  
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛
+
 ----------------------------------------------------------------------
 Ran 8 tests

-OK
+FAILED (errors=3)
Failures: 065
Failed 1 of 1 iotests

Before:

065   fail       [16:24:37] [16:24:37]   0.3s   (last: 0.4s)  failed, exit 
status 1
--- /home/jsnow/src/qemu/tests/qemu-iotests/065.out
+++ 065.out.bad
@@ -1,5 +1,102 @@
-........
+....ERROR:qemu.aqmp.qmp_client.qemu-4002852:Failed to receive Greeting: 
EOFError
+ERROR:qemu.aqmp.qmp_client.qemu-4002852:Failed to establish session: EOFError
+EEEEE.
+======================================================================
+ERROR: test_qmp (__main__.TestQCow3LazyQMP)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/protocol.py", line 379, in 
_new_session
+    await self._establish_session()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/qmp_client.py", line 250, in 
_establish_session
+    self._greeting = await self._get_greeting()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/qmp_client.py", line 270, in 
_get_greeting
+    msg = await self._recv()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/protocol.py", line 909, in _recv
+    message = await self._do_recv()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/qmp_client.py", line 402, in 
_do_recv
+    msg_bytes = await self._readline()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/protocol.py", line 877, in 
_readline
+    raise EOFError
+EOFError
+
+The above exception was the direct cause of the following exception:
+
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/python/qemu/machine/machine.py", line 428, in 
launch
+    self._launch()
+  File "/home/jsnow/src/qemu/python/qemu/machine/machine.py", line 467, in 
_launch
+    self._post_launch()
+  File "/home/jsnow/src/qemu/python/qemu/machine/qtest.py", line 147, in 
_post_launch
+    super()._post_launch()
+  File "/home/jsnow/src/qemu/python/qemu/machine/machine.py", line 369, in 
_post_launch
+    self._qmp.accept(self._qmp_timer)
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/legacy.py", line 93, in accept
+    self._sync(
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/legacy.py", line 67, in _sync
+    return self._aloop.run_until_complete(
+  File "/usr/lib64/python3.9/asyncio/base_events.py", line 642, in 
run_until_complete
+    return future.result()
+  File "/usr/lib64/python3.9/asyncio/tasks.py", line 479, in wait_for
+    return fut.result()
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/protocol.py", line 282, in accept
+    await self._new_session(address, ssl, accept=True)
+  File "/home/jsnow/src/qemu/python/qemu/aqmp/protocol.py", line 398, in 
_new_session
+    raise ConnectError(emsg, err) from err
+qemu.aqmp.protocol.ConnectError: Failed to establish session: EOFError
+
+The above exception was the direct cause of the following exception:
+
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 76, in setUp
+    self.vm.launch()
+  File "/home/jsnow/src/qemu/python/qemu/machine/machine.py", line 441, in 
launch
+    raise VMLaunchFailure(
+qemu.machine.machine.VMLaunchFailure: ConnectError: Failed to establish 
session: EOFError
+       Exit code: 1
+       Command: 
/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/../../qemu-system-x86_64 
-display none -vga none -chardev 
socket,id=mon,path=/tmp/tmp96jl1ds7/qemu-4002852-monitor.sock -mon 
chardev=mon,mode=control -qtest 
unix:path=/tmp/tmp96jl1ds7/qemu-4002852-qtest.sock -accel qtest -nodefaults 
-display none -accel qtest -drive 
if=virtio,id=drive0,file=/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img,format=qcow2,cache=writeback,aio=threads,lazy-refcounts=off
+       Output: qemu-system-x86_64: -drive 
if=virtio,id=drive0,file=/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img,format=qcow2,cache=writeback,aio=threads,lazy-refcounts=off:
 Could not open 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img': No such 
file or directory
+
+
+
+======================================================================
+ERROR: test_human (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 59, in test_human
+    data = data[(data.index('Format specific information:') + 1)
+ValueError: 'Format specific information:' is not in list
+
+======================================================================
+ERROR: test_human (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 42, in tearDown
+    os.remove(test_img)
+FileNotFoundError: [Errno 2] No such file or directory: 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img'
+
+======================================================================
+ERROR: test_json (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 52, in test_json
+    data = json.loads(qemu_img_pipe('info', '--output=json', test_img))
+  File "/usr/lib64/python3.9/json/__init__.py", line 346, in loads
+    return _default_decoder.decode(s)
+  File "/usr/lib64/python3.9/json/decoder.py", line 337, in decode
+    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
+  File "/usr/lib64/python3.9/json/decoder.py", line 355, in raw_decode
+    raise JSONDecodeError("Expecting value", s, err.value) from None
+json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
+
+======================================================================
+ERROR: test_json (__main__.TestQCow3NotLazy)
+----------------------------------------------------------------------
+Traceback (most recent call last):
+  File "/home/jsnow/src/qemu/tests/qemu-iotests/065", line 42, in tearDown
+    os.remove(test_img)
+FileNotFoundError: [Errno 2] No such file or directory: 
'/home/jsnow/src/qemu/bin/git/tests/qemu-iotests/scratch/test.img'
+
 ----------------------------------------------------------------------
 Ran 8 tests

-OK
+FAILED (errors=5)
Failures: 065
Failed 1 of 1 iotests

John Snow (4):
  python/utils: add enboxify() text decoration utility
  iotests: add VerboseProcessError
  iotests: Remove explicit checks for qemu_img() == 0
  iotests: make qemu_img raise on non-zero rc by default

 python/qemu/utils/__init__.py                 | 58 +++++++++++++
 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                 | 87 +++++++++++++++++--
 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, 185 insertions(+), 57 deletions(-)

-- 
2.34.1