qemu-devel.nongnu.org archive mirror
 help / color / mirror / Atom feed
* [PATCH v5 0/8] Switch iotests to using Async QMP
@ 2021-10-26 17:56 John Snow
  2021-10-26 17:56 ` [PATCH v5 1/8] python/machine: remove has_quit argument John Snow
                   ` (8 more replies)
  0 siblings, 9 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

GitLab: https://gitlab.com/jsnow/qemu/-/commits/python-aqmp-iotest-wrapper
CI: https://gitlab.com/jsnow/qemu/-/pipelines/395925703

Hiya,

This series continues where the last two AQMP series left off and adds a
synchronous 'legacy' wrapper around the new AQMP interface, then drops
it straight into iotests to prove that AQMP is functional and totally
cool and fine. The disruption and churn to iotests is pretty minimal.

In the event that a regression happens and I am not physically proximate
to inflict damage upon, one may set the QEMU_PYTHON_LEGACY_QMP variable
to any non-empty string as it pleases you to engage the QMP machinery
you are used to.

V5:

006: Fixed a typing error. (Hanna)

V4:

006: Added to address a race condition in iotest 300.
     (Thanks for the repro, Hanna)

V3: Near as we can tell, our immediate ancestral forebear.
V2: A distant dream, half-remembered.
V1: Apocrypha.

John Snow (8):
  python/machine: remove has_quit argument
  python/machine: Handle QMP errors on close more meticulously
  python/aqmp: Remove scary message
  iotests: Accommodate async QMP Exception classes
  iotests: Conditionally silence certain AQMP errors
  iotests/300: avoid abnormal shutdown race condition
  python/aqmp: Create sync QMP wrapper for iotests
  python, iotests: replace qmp with aqmp

 python/qemu/aqmp/__init__.py              |  12 --
 python/qemu/aqmp/legacy.py                | 138 ++++++++++++++++++++++
 python/qemu/machine/machine.py            |  85 +++++++++----
 scripts/simplebench/bench_block_job.py    |   3 +-
 tests/qemu-iotests/040                    |   7 +-
 tests/qemu-iotests/218                    |   2 +-
 tests/qemu-iotests/255                    |   2 +-
 tests/qemu-iotests/300                    |  13 +-
 tests/qemu-iotests/iotests.py             |  20 +++-
 tests/qemu-iotests/tests/mirror-top-perms |  17 ++-
 10 files changed, 243 insertions(+), 56 deletions(-)
 create mode 100644 python/qemu/aqmp/legacy.py

-- 
2.31.1




^ permalink raw reply	[flat|nested] 17+ messages in thread

* [PATCH v5 1/8] python/machine: remove has_quit argument
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-26 17:56 ` [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously John Snow
                   ` (7 subsequent siblings)
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

If we spy on the QMP commands instead, we don't need callers to remember
to pass it. Seems like a fair trade-off.

The one slightly weird bit is overloading this instance variable for
wait(), where we use it to mean "don't issue the qmp 'quit'
command". This means that wait() will "fail" if the QEMU process does
not terminate of its own accord.

In most cases, we probably did already actually issue quit -- some
iotests do this -- but in some others, we may be waiting for QEMU to
terminate for some other reason, such as a test wherein we tell the
guest (directly) to shut down.

Signed-off-by: John Snow <jsnow@redhat.com>
Reviewed-by: Hanna Reitz <hreitz@redhat.com>
---
 python/qemu/machine/machine.py | 34 +++++++++++++++++++---------------
 tests/qemu-iotests/040         |  7 +------
 tests/qemu-iotests/218         |  2 +-
 tests/qemu-iotests/255         |  2 +-
 4 files changed, 22 insertions(+), 23 deletions(-)

diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
index 056d340e355..0bd40bc2f76 100644
--- a/python/qemu/machine/machine.py
+++ b/python/qemu/machine/machine.py
@@ -170,6 +170,7 @@ def __init__(self,
         self._console_socket: Optional[socket.socket] = None
         self._remove_files: List[str] = []
         self._user_killed = False
+        self._quit_issued = False
 
     def __enter__(self: _T) -> _T:
         return self
@@ -368,6 +369,7 @@ def _post_shutdown(self) -> None:
                 command = ''
             LOG.warning(msg, -int(exitcode), command)
 
+        self._quit_issued = False
         self._user_killed = False
         self._launched = False
 
@@ -443,15 +445,13 @@ def _hard_shutdown(self) -> None:
         self._subp.kill()
         self._subp.wait(timeout=60)
 
-    def _soft_shutdown(self, timeout: Optional[int],
-                       has_quit: bool = False) -> None:
+    def _soft_shutdown(self, timeout: Optional[int]) -> None:
         """
         Perform early cleanup, attempt to gracefully shut down the VM, and wait
         for it to terminate.
 
         :param timeout: Timeout in seconds for graceful shutdown.
                         A value of None is an infinite wait.
-        :param has_quit: When True, don't attempt to issue 'quit' QMP command
 
         :raise ConnectionReset: On QMP communication errors
         :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for
@@ -460,21 +460,19 @@ def _soft_shutdown(self, timeout: Optional[int],
         self._early_cleanup()
 
         if self._qmp_connection:
-            if not has_quit:
+            if not self._quit_issued:
                 # Might raise ConnectionReset
-                self._qmp.cmd('quit')
+                self.qmp('quit')
 
         # May raise subprocess.TimeoutExpired
         self._subp.wait(timeout=timeout)
 
-    def _do_shutdown(self, timeout: Optional[int],
-                     has_quit: bool = False) -> None:
+    def _do_shutdown(self, timeout: Optional[int]) -> None:
         """
         Attempt to shutdown the VM gracefully; fallback to a hard shutdown.
 
         :param timeout: Timeout in seconds for graceful shutdown.
                         A value of None is an infinite wait.
-        :param has_quit: When True, don't attempt to issue 'quit' QMP command
 
         :raise AbnormalShutdown: When the VM could not be shut down gracefully.
             The inner exception will likely be ConnectionReset or
@@ -482,13 +480,13 @@ def _do_shutdown(self, timeout: Optional[int],
             may result in its own exceptions, likely subprocess.TimeoutExpired.
         """
         try:
-            self._soft_shutdown(timeout, has_quit)
+            self._soft_shutdown(timeout)
         except Exception as exc:
             self._hard_shutdown()
             raise AbnormalShutdown("Could not perform graceful shutdown") \
                 from exc
 
-    def shutdown(self, has_quit: bool = False,
+    def shutdown(self,
                  hard: bool = False,
                  timeout: Optional[int] = 30) -> None:
         """
@@ -498,7 +496,6 @@ def shutdown(self, has_quit: bool = False,
         If the VM has not yet been launched, or shutdown(), wait(), or kill()
         have already been called, this method does nothing.
 
-        :param has_quit: When true, do not attempt to issue 'quit' QMP command.
         :param hard: When true, do not attempt graceful shutdown, and
                      suppress the SIGKILL warning log message.
         :param timeout: Optional timeout in seconds for graceful shutdown.
@@ -512,7 +509,7 @@ def shutdown(self, has_quit: bool = False,
                 self._user_killed = True
                 self._hard_shutdown()
             else:
-                self._do_shutdown(timeout, has_quit)
+                self._do_shutdown(timeout)
         finally:
             self._post_shutdown()
 
@@ -529,7 +526,8 @@ def wait(self, timeout: Optional[int] = 30) -> None:
         :param timeout: Optional timeout in seconds. Default 30 seconds.
                         A value of `None` is an infinite wait.
         """
-        self.shutdown(has_quit=True, timeout=timeout)
+        self._quit_issued = True
+        self.shutdown(timeout=timeout)
 
     def set_qmp_monitor(self, enabled: bool = True) -> None:
         """
@@ -574,7 +572,10 @@ def qmp(self, cmd: str,
             conv_keys = True
 
         qmp_args = self._qmp_args(conv_keys, args)
-        return self._qmp.cmd(cmd, args=qmp_args)
+        ret = self._qmp.cmd(cmd, args=qmp_args)
+        if cmd == 'quit' and 'error' not in ret and 'return' in ret:
+            self._quit_issued = True
+        return ret
 
     def command(self, cmd: str,
                 conv_keys: bool = True,
@@ -585,7 +586,10 @@ def command(self, cmd: str,
         On failure raise an exception.
         """
         qmp_args = self._qmp_args(conv_keys, args)
-        return self._qmp.command(cmd, **qmp_args)
+        ret = self._qmp.command(cmd, **qmp_args)
+        if cmd == 'quit':
+            self._quit_issued = True
+        return ret
 
     def get_qmp_event(self, wait: bool = False) -> Optional[QMPMessage]:
         """
diff --git a/tests/qemu-iotests/040 b/tests/qemu-iotests/040
index f3677de9dfd..6af5ab9e764 100755
--- a/tests/qemu-iotests/040
+++ b/tests/qemu-iotests/040
@@ -92,10 +92,9 @@ class TestSingleDrive(ImageCommitTestCase):
         self.vm.add_device('virtio-scsi')
         self.vm.add_device("scsi-hd,id=scsi0,drive=drive0")
         self.vm.launch()
-        self.has_quit = False
 
     def tearDown(self):
-        self.vm.shutdown(has_quit=self.has_quit)
+        self.vm.shutdown()
         os.remove(test_img)
         os.remove(mid_img)
         os.remove(backing_img)
@@ -127,8 +126,6 @@ class TestSingleDrive(ImageCommitTestCase):
         result = self.vm.qmp('quit')
         self.assert_qmp(result, 'return', {})
 
-        self.has_quit = True
-
     # Same as above, but this time we add the filter after starting the job
     @iotests.skip_if_unsupported(['throttle'])
     def test_commit_plus_filter_and_quit(self):
@@ -147,8 +144,6 @@ class TestSingleDrive(ImageCommitTestCase):
         result = self.vm.qmp('quit')
         self.assert_qmp(result, 'return', {})
 
-        self.has_quit = True
-
     def test_device_not_found(self):
         result = self.vm.qmp('block-commit', device='nonexistent', top='%s' % mid_img)
         self.assert_qmp(result, 'error/class', 'DeviceNotFound')
diff --git a/tests/qemu-iotests/218 b/tests/qemu-iotests/218
index 325d8244fb9..4922b4d3b6f 100755
--- a/tests/qemu-iotests/218
+++ b/tests/qemu-iotests/218
@@ -187,4 +187,4 @@ with iotests.VM() as vm, \
     log(vm.qmp('quit'))
 
     with iotests.Timeout(5, 'Timeout waiting for VM to quit'):
-        vm.shutdown(has_quit=True)
+        vm.shutdown()
diff --git a/tests/qemu-iotests/255 b/tests/qemu-iotests/255
index c43aa9c67ac..3d6d0e80cb5 100755
--- a/tests/qemu-iotests/255
+++ b/tests/qemu-iotests/255
@@ -123,4 +123,4 @@ with iotests.FilePath('src.qcow2') as src_path, \
     vm.qmp_log('block-job-cancel', device='job0')
     vm.qmp_log('quit')
 
-    vm.shutdown(has_quit=True)
+    vm.shutdown()
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
  2021-10-26 17:56 ` [PATCH v5 1/8] python/machine: remove has_quit argument John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-27 11:19   ` Kevin Wolf
  2021-10-26 17:56 ` [PATCH v5 3/8] python/aqmp: Remove scary message John Snow
                   ` (6 subsequent siblings)
  8 siblings, 1 reply; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

To use the AQMP backend, Machine just needs to be a little more diligent
about what happens when closing a QMP connection. The operation is no
longer a freebie in the async world; it may return errors encountered in
the async bottom half on incoming message receipt, etc.

(AQMP's disconnect, ultimately, serves as the quiescence point where all
async contexts are gathered together, and any final errors reported at
that point.)

Because async QMP continues to check for messages asynchronously, it's
almost certainly likely that the loop will have exited due to EOF after
issuing the last 'quit' command. That error will ultimately be bubbled
up when attempting to close the QMP connection. The manager class here
then is free to discard it -- if it was expected.

Signed-off-by: John Snow <jsnow@redhat.com>
Reviewed-by: Hanna Reitz <hreitz@redhat.com>
---
 python/qemu/machine/machine.py | 48 +++++++++++++++++++++++++++++-----
 1 file changed, 42 insertions(+), 6 deletions(-)

diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
index 0bd40bc2f76..a0cf69786b4 100644
--- a/python/qemu/machine/machine.py
+++ b/python/qemu/machine/machine.py
@@ -342,9 +342,15 @@ def _post_shutdown(self) -> None:
         # Comprehensive reset for the failed launch case:
         self._early_cleanup()
 
-        if self._qmp_connection:
-            self._qmp.close()
-            self._qmp_connection = None
+        try:
+            self._close_qmp_connection()
+        except Exception as err:  # pylint: disable=broad-except
+            LOG.warning(
+                "Exception closing QMP connection: %s",
+                str(err) if str(err) else type(err).__name__
+            )
+        finally:
+            assert self._qmp_connection is None
 
         self._close_qemu_log_file()
 
@@ -420,6 +426,31 @@ def _launch(self) -> None:
                                        close_fds=False)
         self._post_launch()
 
+    def _close_qmp_connection(self) -> None:
+        """
+        Close the underlying QMP connection, if any.
+
+        Dutifully report errors that occurred while closing, but assume
+        that any error encountered indicates an abnormal termination
+        process and not a failure to close.
+        """
+        if self._qmp_connection is None:
+            return
+
+        try:
+            self._qmp.close()
+        except EOFError:
+            # EOF can occur as an Exception here when using the Async
+            # QMP backend. It indicates that the server closed the
+            # stream. If we successfully issued 'quit' at any point,
+            # then this was expected. If the remote went away without
+            # our permission, it's worth reporting that as an abnormal
+            # shutdown case.
+            if not (self._user_killed or self._quit_issued):
+                raise
+        finally:
+            self._qmp_connection = None
+
     def _early_cleanup(self) -> None:
         """
         Perform any cleanup that needs to happen before the VM exits.
@@ -460,9 +491,14 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
         self._early_cleanup()
 
         if self._qmp_connection:
-            if not self._quit_issued:
-                # Might raise ConnectionReset
-                self.qmp('quit')
+            try:
+                if not self._quit_issued:
+                    # May raise ExecInterruptedError or StateError if the
+                    # connection dies or has *already* died.
+                    self.qmp('quit')
+            finally:
+                # Regardless, we want to quiesce the connection.
+                self._close_qmp_connection()
 
         # May raise subprocess.TimeoutExpired
         self._subp.wait(timeout=timeout)
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 3/8] python/aqmp: Remove scary message
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
  2021-10-26 17:56 ` [PATCH v5 1/8] python/machine: remove has_quit argument John Snow
  2021-10-26 17:56 ` [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-26 17:56 ` [PATCH v5 4/8] iotests: Accommodate async QMP Exception classes John Snow
                   ` (5 subsequent siblings)
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

The scary message interferes with the iotests output. Coincidentally, if
iotests works by removing this, then it's good evidence that we don't
really need to scare people away from using it.

Signed-off-by: John Snow <jsnow@redhat.com>
Acked-by: Hanna Reitz <hreitz@redhat.com>
---
 python/qemu/aqmp/__init__.py | 12 ------------
 1 file changed, 12 deletions(-)

diff --git a/python/qemu/aqmp/__init__.py b/python/qemu/aqmp/__init__.py
index d1b0e4dc3d3..880d5b6fa7f 100644
--- a/python/qemu/aqmp/__init__.py
+++ b/python/qemu/aqmp/__init__.py
@@ -22,7 +22,6 @@
 # the COPYING file in the top-level directory.
 
 import logging
-import warnings
 
 from .error import AQMPError
 from .events import EventListener
@@ -31,17 +30,6 @@
 from .qmp_client import ExecInterruptedError, ExecuteError, QMPClient
 
 
-_WMSG = """
-
-The Asynchronous QMP library is currently in development and its API
-should be considered highly fluid and subject to change. It should
-not be used by any other scripts checked into the QEMU tree.
-
-Proceed with caution!
-"""
-
-warnings.warn(_WMSG, FutureWarning)
-
 # Suppress logging unless an application engages it.
 logging.getLogger('qemu.aqmp').addHandler(logging.NullHandler())
 
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 4/8] iotests: Accommodate async QMP Exception classes
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (2 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 3/8] python/aqmp: Remove scary message John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-26 17:56 ` [PATCH v5 5/8] iotests: Conditionally silence certain AQMP errors John Snow
                   ` (4 subsequent siblings)
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

(But continue to support the old ones for now, too.)

There are very few cases of any user of QEMUMachine or a subclass
thereof relying on a QMP Exception type. If you'd like to check for
yourself, you want to grep for all of the derivatives of QMPError,
excluding 'AQMPError' and its derivatives. That'd be these:

- QMPError
- QMPConnectError
- QMPCapabilitiesError
- QMPTimeoutError
- QMPProtocolError
- QMPResponseError
- QMPBadPortError


Signed-off-by: John Snow <jsnow@redhat.com>
Reviewed-by: Hanna Reitz <hreitz@redhat.com>
---
 scripts/simplebench/bench_block_job.py    | 3 ++-
 tests/qemu-iotests/tests/mirror-top-perms | 5 +++--
 2 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/scripts/simplebench/bench_block_job.py b/scripts/simplebench/bench_block_job.py
index 4f03c121697..a403c35b08f 100755
--- a/scripts/simplebench/bench_block_job.py
+++ b/scripts/simplebench/bench_block_job.py
@@ -28,6 +28,7 @@
 sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'python'))
 from qemu.machine import QEMUMachine
 from qemu.qmp import QMPConnectError
+from qemu.aqmp import ConnectError
 
 
 def bench_block_job(cmd, cmd_args, qemu_args):
@@ -49,7 +50,7 @@ def bench_block_job(cmd, cmd_args, qemu_args):
         vm.launch()
     except OSError as e:
         return {'error': 'popen failed: ' + str(e)}
-    except (QMPConnectError, socket.timeout):
+    except (QMPConnectError, ConnectError, socket.timeout):
         return {'error': 'qemu failed: ' + str(vm.get_log())}
 
     try:
diff --git a/tests/qemu-iotests/tests/mirror-top-perms b/tests/qemu-iotests/tests/mirror-top-perms
index 3d475aa3a54..a2d5c269d7a 100755
--- a/tests/qemu-iotests/tests/mirror-top-perms
+++ b/tests/qemu-iotests/tests/mirror-top-perms
@@ -21,8 +21,9 @@
 
 import os
 
-from qemu import qmp
+from qemu.aqmp import ConnectError
 from qemu.machine import machine
+from qemu.qmp import QMPConnectError
 
 import iotests
 from iotests import qemu_img
@@ -102,7 +103,7 @@ class TestMirrorTopPerms(iotests.QMPTestCase):
             self.vm_b.launch()
             print('ERROR: VM B launched successfully, this should not have '
                   'happened')
-        except qmp.QMPConnectError:
+        except (QMPConnectError, ConnectError):
             assert 'Is another process using the image' in self.vm_b.get_log()
 
         result = self.vm.qmp('block-job-cancel',
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 5/8] iotests: Conditionally silence certain AQMP errors
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (3 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 4/8] iotests: Accommodate async QMP Exception classes John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-26 17:56 ` [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition John Snow
                   ` (3 subsequent siblings)
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

AQMP likes to be very chatty about errors it encounters. In general,
this is good because it allows us to get good diagnostic information for
otherwise complex async failures.

For example, during a failed QMP connection attempt, we might see:

+ERROR:qemu.aqmp.qmp_client.qemub-2536319:Negotiation failed: EOFError
+ERROR:qemu.aqmp.qmp_client.qemub-2536319:Failed to establish session: EOFError

This might be nice in iotests output, because failure scenarios
involving the new QMP library will be spelled out plainly in the output
diffs.

For tests that are intentionally causing this scenario though, filtering
that log output could be a hassle. For now, add a context manager that
simply lets us toggle this output off during a critical region.

(Additionally, a forthcoming patch allows the use of either legacy or
async QMP to be toggled with an environment variable. In this
circumstance, we can't amend the iotest output to just always expect the
error message, either. Just suppress it for now. More rigorous log
filtering can be investigated later if/when it is deemed safe to
permanently replace the legacy QMP library.)

Signed-off-by: John Snow <jsnow@redhat.com>
Reviewed-by: Hanna Reitz <hreitz@redhat.com>
---
 tests/qemu-iotests/iotests.py             | 20 +++++++++++++++++++-
 tests/qemu-iotests/tests/mirror-top-perms | 12 ++++++++----
 2 files changed, 27 insertions(+), 5 deletions(-)

diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index e5fff6ddcfc..e2f9d873ada 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -30,7 +30,7 @@
 import subprocess
 import sys
 import time
-from typing import (Any, Callable, Dict, Iterable,
+from typing import (Any, Callable, Dict, Iterable, Iterator,
                     List, Optional, Sequence, TextIO, Tuple, Type, TypeVar)
 import unittest
 
@@ -114,6 +114,24 @@
 sample_img_dir = os.environ['SAMPLE_IMG_DIR']
 
 
+@contextmanager
+def change_log_level(
+        logger_name: str, level: int = logging.CRITICAL) -> Iterator[None]:
+    """
+    Utility function for temporarily changing the log level of a logger.
+
+    This can be used to silence errors that are expected or uninteresting.
+    """
+    _logger = logging.getLogger(logger_name)
+    current_level = _logger.level
+    _logger.setLevel(level)
+
+    try:
+        yield
+    finally:
+        _logger.setLevel(current_level)
+
+
 def unarchive_sample_image(sample, fname):
     sample_fname = os.path.join(sample_img_dir, sample + '.bz2')
     with bz2.open(sample_fname) as f_in, open(fname, 'wb') as f_out:
diff --git a/tests/qemu-iotests/tests/mirror-top-perms b/tests/qemu-iotests/tests/mirror-top-perms
index a2d5c269d7a..0a51a613f39 100755
--- a/tests/qemu-iotests/tests/mirror-top-perms
+++ b/tests/qemu-iotests/tests/mirror-top-perms
@@ -26,7 +26,7 @@ from qemu.machine import machine
 from qemu.qmp import QMPConnectError
 
 import iotests
-from iotests import qemu_img
+from iotests import change_log_level, qemu_img
 
 
 image_size = 1 * 1024 * 1024
@@ -100,9 +100,13 @@ class TestMirrorTopPerms(iotests.QMPTestCase):
         self.vm_b.add_blockdev(f'file,node-name=drive0,filename={source}')
         self.vm_b.add_device('virtio-blk,drive=drive0,share-rw=on')
         try:
-            self.vm_b.launch()
-            print('ERROR: VM B launched successfully, this should not have '
-                  'happened')
+            # Silence AQMP errors temporarily.
+            # TODO: Remove this and just allow the errors to be logged when
+            # AQMP fully replaces QMP.
+            with change_log_level('qemu.aqmp'):
+                self.vm_b.launch()
+                print('ERROR: VM B launched successfully, '
+                      'this should not have happened')
         except (QMPConnectError, ConnectError):
             assert 'Is another process using the image' in self.vm_b.get_log()
 
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (4 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 5/8] iotests: Conditionally silence certain AQMP errors John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-27 12:56   ` Kevin Wolf
  2021-10-26 17:56 ` [PATCH v5 7/8] python/aqmp: Create sync QMP wrapper for iotests John Snow
                   ` (2 subsequent siblings)
  8 siblings, 1 reply; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

Wait for the destination VM to close itself instead of racing to shut it
down first, which produces different error log messages from AQMP
depending on precisely when we tried to shut it down.

(For example: We may try to issue 'quit' immediately prior to the target
VM closing its QMP socket, which will cause an ECONNRESET error to be
logged. Waiting for the VM to exit itself avoids the race on shutdown
behavior.)

Reported-by: Hanna Reitz <hreitz@redhat.com>
Signed-off-by: John Snow <jsnow@redhat.com>
---
 tests/qemu-iotests/300 | 13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)

diff --git a/tests/qemu-iotests/300 b/tests/qemu-iotests/300
index 10f9f2a8da6..dbd28384ec3 100755
--- a/tests/qemu-iotests/300
+++ b/tests/qemu-iotests/300
@@ -24,8 +24,6 @@ import random
 import re
 from typing import Dict, List, Optional
 
-from qemu.machine import machine
-
 import iotests
 
 
@@ -461,12 +459,11 @@ class TestBlockBitmapMappingErrors(TestDirtyBitmapMigration):
                       f"'{self.src_node_name}': Name is longer than 255 bytes",
                       log)
 
-        # Expect abnormal shutdown of the destination VM because of
-        # the failed migration
-        try:
-            self.vm_b.shutdown()
-        except machine.AbnormalShutdown:
-            pass
+        # Destination VM will terminate w/ error of its own accord
+        # due to the failed migration.
+        self.vm_b.wait()
+        rc = self.vm_b.exitcode()
+        assert rc is not None and rc > 0
 
     def test_aliased_bitmap_name_too_long(self) -> None:
         # Longer than the maximum for bitmap names
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 7/8] python/aqmp: Create sync QMP wrapper for iotests
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (5 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-26 17:56 ` [PATCH v5 8/8] python, iotests: replace qmp with aqmp John Snow
  2021-10-28 10:37 ` [PATCH v5 0/8] Switch iotests to using Async QMP Kevin Wolf
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

This is a wrapper around the async QMPClient that mimics the old,
synchronous QEMUMonitorProtocol class. It is designed to be
interchangeable with the old implementation.

It does not, however, attempt to mimic Exception compatibility.

Signed-off-by: John Snow <jsnow@redhat.com>
Acked-by: Hanna Reitz <hreitz@redhat.com>
---
 python/qemu/aqmp/legacy.py | 138 +++++++++++++++++++++++++++++++++++++
 1 file changed, 138 insertions(+)
 create mode 100644 python/qemu/aqmp/legacy.py

diff --git a/python/qemu/aqmp/legacy.py b/python/qemu/aqmp/legacy.py
new file mode 100644
index 00000000000..9e7b9fb80b9
--- /dev/null
+++ b/python/qemu/aqmp/legacy.py
@@ -0,0 +1,138 @@
+"""
+Sync QMP Wrapper
+
+This class pretends to be qemu.qmp.QEMUMonitorProtocol.
+"""
+
+import asyncio
+from typing import (
+    Awaitable,
+    List,
+    Optional,
+    TypeVar,
+    Union,
+)
+
+import qemu.qmp
+from qemu.qmp import QMPMessage, QMPReturnValue, SocketAddrT
+
+from .qmp_client import QMPClient
+
+
+# pylint: disable=missing-docstring
+
+
+class QEMUMonitorProtocol(qemu.qmp.QEMUMonitorProtocol):
+    def __init__(self, address: SocketAddrT,
+                 server: bool = False,
+                 nickname: Optional[str] = None):
+
+        # pylint: disable=super-init-not-called
+        self._aqmp = QMPClient(nickname)
+        self._aloop = asyncio.get_event_loop()
+        self._address = address
+        self._timeout: Optional[float] = None
+
+    _T = TypeVar('_T')
+
+    def _sync(
+            self, future: Awaitable[_T], timeout: Optional[float] = None
+    ) -> _T:
+        return self._aloop.run_until_complete(
+            asyncio.wait_for(future, timeout=timeout)
+        )
+
+    def _get_greeting(self) -> Optional[QMPMessage]:
+        if self._aqmp.greeting is not None:
+            # pylint: disable=protected-access
+            return self._aqmp.greeting._asdict()
+        return None
+
+    # __enter__ and __exit__ need no changes
+    # parse_address needs no changes
+
+    def connect(self, negotiate: bool = True) -> Optional[QMPMessage]:
+        self._aqmp.await_greeting = negotiate
+        self._aqmp.negotiate = negotiate
+
+        self._sync(
+            self._aqmp.connect(self._address)
+        )
+        return self._get_greeting()
+
+    def accept(self, timeout: Optional[float] = 15.0) -> QMPMessage:
+        self._aqmp.await_greeting = True
+        self._aqmp.negotiate = True
+
+        self._sync(
+            self._aqmp.accept(self._address),
+            timeout
+        )
+
+        ret = self._get_greeting()
+        assert ret is not None
+        return ret
+
+    def cmd_obj(self, qmp_cmd: QMPMessage) -> QMPMessage:
+        return dict(
+            self._sync(
+                # pylint: disable=protected-access
+
+                # _raw() isn't a public API, because turning off
+                # automatic ID assignment is discouraged. For
+                # compatibility with iotests *only*, do it anyway.
+                self._aqmp._raw(qmp_cmd, assign_id=False),
+                self._timeout
+            )
+        )
+
+    # Default impl of cmd() delegates to cmd_obj
+
+    def command(self, cmd: str, **kwds: object) -> QMPReturnValue:
+        return self._sync(
+            self._aqmp.execute(cmd, kwds),
+            self._timeout
+        )
+
+    def pull_event(self,
+                   wait: Union[bool, float] = False) -> Optional[QMPMessage]:
+        if not wait:
+            # wait is False/0: "do not wait, do not except."
+            if self._aqmp.events.empty():
+                return None
+
+        # If wait is 'True', wait forever. If wait is False/0, the events
+        # queue must not be empty; but it still needs some real amount
+        # of time to complete.
+        timeout = None
+        if wait and isinstance(wait, float):
+            timeout = wait
+
+        return dict(
+            self._sync(
+                self._aqmp.events.get(),
+                timeout
+            )
+        )
+
+    def get_events(self, wait: Union[bool, float] = False) -> List[QMPMessage]:
+        events = [dict(x) for x in self._aqmp.events.clear()]
+        if events:
+            return events
+
+        event = self.pull_event(wait)
+        return [event] if event is not None else []
+
+    def clear_events(self) -> None:
+        self._aqmp.events.clear()
+
+    def close(self) -> None:
+        self._sync(
+            self._aqmp.disconnect()
+        )
+
+    def settimeout(self, timeout: Optional[float]) -> None:
+        self._timeout = timeout
+
+    def send_fd_scm(self, fd: int) -> None:
+        self._aqmp.send_fd_scm(fd)
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v5 8/8] python, iotests: replace qmp with aqmp
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (6 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 7/8] python/aqmp: Create sync QMP wrapper for iotests John Snow
@ 2021-10-26 17:56 ` John Snow
  2021-10-28 10:37 ` [PATCH v5 0/8] Switch iotests to using Async QMP Kevin Wolf
  8 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-26 17:56 UTC (permalink / raw)
  To: qemu-devel
  Cc: Kevin Wolf, Vladimir Sementsov-Ogievskiy, Eduardo Habkost,
	qemu-block, Hanna Reitz, Cleber Rosa, John Snow

Swap out the synchronous QEMUMonitorProtocol from qemu.qmp with the sync
wrapper from qemu.aqmp instead.

Add an escape hatch in the form of the environment variable
QEMU_PYTHON_LEGACY_QMP which allows you to cajole QEMUMachine into using
the old implementation, proving that both implementations work
concurrently.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 python/qemu/machine/machine.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
index a0cf69786b4..a487c397459 100644
--- a/python/qemu/machine/machine.py
+++ b/python/qemu/machine/machine.py
@@ -41,7 +41,6 @@
 )
 
 from qemu.qmp import (  # pylint: disable=import-error
-    QEMUMonitorProtocol,
     QMPMessage,
     QMPReturnValue,
     SocketAddrT,
@@ -50,6 +49,12 @@
 from . import console_socket
 
 
+if os.environ.get('QEMU_PYTHON_LEGACY_QMP'):
+    from qemu.qmp import QEMUMonitorProtocol
+else:
+    from qemu.aqmp.legacy import QEMUMonitorProtocol
+
+
 LOG = logging.getLogger(__name__)
 
 
-- 
2.31.1



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously
  2021-10-26 17:56 ` [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously John Snow
@ 2021-10-27 11:19   ` Kevin Wolf
  2021-10-27 17:49     ` John Snow
  0 siblings, 1 reply; 17+ messages in thread
From: Kevin Wolf @ 2021-10-27 11:19 UTC (permalink / raw)
  To: John Snow
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> To use the AQMP backend, Machine just needs to be a little more diligent
> about what happens when closing a QMP connection. The operation is no
> longer a freebie in the async world; it may return errors encountered in
> the async bottom half on incoming message receipt, etc.
> 
> (AQMP's disconnect, ultimately, serves as the quiescence point where all
> async contexts are gathered together, and any final errors reported at
> that point.)
> 
> Because async QMP continues to check for messages asynchronously, it's
> almost certainly likely that the loop will have exited due to EOF after
> issuing the last 'quit' command. That error will ultimately be bubbled
> up when attempting to close the QMP connection. The manager class here
> then is free to discard it -- if it was expected.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> Reviewed-by: Hanna Reitz <hreitz@redhat.com>
> ---
>  python/qemu/machine/machine.py | 48 +++++++++++++++++++++++++++++-----
>  1 file changed, 42 insertions(+), 6 deletions(-)
> 
> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
> index 0bd40bc2f76..a0cf69786b4 100644
> --- a/python/qemu/machine/machine.py
> +++ b/python/qemu/machine/machine.py
> @@ -342,9 +342,15 @@ def _post_shutdown(self) -> None:
>          # Comprehensive reset for the failed launch case:
>          self._early_cleanup()
>  
> -        if self._qmp_connection:
> -            self._qmp.close()
> -            self._qmp_connection = None
> +        try:
> +            self._close_qmp_connection()
> +        except Exception as err:  # pylint: disable=broad-except
> +            LOG.warning(
> +                "Exception closing QMP connection: %s",
> +                str(err) if str(err) else type(err).__name__
> +            )
> +        finally:
> +            assert self._qmp_connection is None
>  
>          self._close_qemu_log_file()
>  
> @@ -420,6 +426,31 @@ def _launch(self) -> None:
>                                         close_fds=False)
>          self._post_launch()
>  
> +    def _close_qmp_connection(self) -> None:
> +        """
> +        Close the underlying QMP connection, if any.
> +
> +        Dutifully report errors that occurred while closing, but assume
> +        that any error encountered indicates an abnormal termination
> +        process and not a failure to close.
> +        """
> +        if self._qmp_connection is None:
> +            return
> +
> +        try:
> +            self._qmp.close()
> +        except EOFError:
> +            # EOF can occur as an Exception here when using the Async
> +            # QMP backend. It indicates that the server closed the
> +            # stream. If we successfully issued 'quit' at any point,
> +            # then this was expected. If the remote went away without
> +            # our permission, it's worth reporting that as an abnormal
> +            # shutdown case.
> +            if not (self._user_killed or self._quit_issued):
> +                raise

Isn't this racy for those tests that expect QEMU to quit by itself and
then later call wait()? self._quit_issued is only set to True in wait(),
but whatever will cause QEMU to quit happens earlier and it might
actually quit before wait() is called.

It would make sense to me that such tests need to declare that they
expect QEMU to quit before actually performing the action. And then
wait() becomes less weird in patch 1, too, because it can just assert
self._quit_issued instead of unconditionally setting it.


The other point I'm unsure is whether you can actually kill QEMU without
getting either self._user_killed or self._quit_issued set. The
potentially problematic case I see is shutdown(hard = False) where soft
shutdown fails. Then a hard shutdown will be performed without setting
self._user_killed (is this a bug?).

Of course, sending the 'quit' command in _soft_shutdown() will set
self._quit_issued at least, but are we absolutely sure that it can never
raise an exception before getting to qmp()? I guess in theory, closing
the console socket in _early_cleanup() could raise one? (But either way,
not relying on such subtleties would make the code easier to
understand.)

Kevin



^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition
  2021-10-26 17:56 ` [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition John Snow
@ 2021-10-27 12:56   ` Kevin Wolf
  2021-10-27 17:55     ` John Snow
  0 siblings, 1 reply; 17+ messages in thread
From: Kevin Wolf @ 2021-10-27 12:56 UTC (permalink / raw)
  To: John Snow
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> Wait for the destination VM to close itself instead of racing to shut it
> down first, which produces different error log messages from AQMP
> depending on precisely when we tried to shut it down.
> 
> (For example: We may try to issue 'quit' immediately prior to the target
> VM closing its QMP socket, which will cause an ECONNRESET error to be
> logged. Waiting for the VM to exit itself avoids the race on shutdown
> behavior.)
> 
> Reported-by: Hanna Reitz <hreitz@redhat.com>
> Signed-off-by: John Snow <jsnow@redhat.com>

I think this will still expose the race I described in my comment on
patch 2.

Kevin



^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously
  2021-10-27 11:19   ` Kevin Wolf
@ 2021-10-27 17:49     ` John Snow
  2021-10-28 10:01       ` Kevin Wolf
  0 siblings, 1 reply; 17+ messages in thread
From: John Snow @ 2021-10-27 17:49 UTC (permalink / raw)
  To: Kevin Wolf
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

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

This reply is long, sorry.

On Wed, Oct 27, 2021 at 7:19 AM Kevin Wolf <kwolf@redhat.com> wrote:

> Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> > To use the AQMP backend, Machine just needs to be a little more diligent
> > about what happens when closing a QMP connection. The operation is no
> > longer a freebie in the async world; it may return errors encountered in
> > the async bottom half on incoming message receipt, etc.
> >
> > (AQMP's disconnect, ultimately, serves as the quiescence point where all
> > async contexts are gathered together, and any final errors reported at
> > that point.)
> >
> > Because async QMP continues to check for messages asynchronously, it's
> > almost certainly likely that the loop will have exited due to EOF after
> > issuing the last 'quit' command. That error will ultimately be bubbled
> > up when attempting to close the QMP connection. The manager class here
> > then is free to discard it -- if it was expected.
> >
> > Signed-off-by: John Snow <jsnow@redhat.com>
> > Reviewed-by: Hanna Reitz <hreitz@redhat.com>
> > ---
> >  python/qemu/machine/machine.py | 48 +++++++++++++++++++++++++++++-----
> >  1 file changed, 42 insertions(+), 6 deletions(-)
> >
> > diff --git a/python/qemu/machine/machine.py
> b/python/qemu/machine/machine.py
> > index 0bd40bc2f76..a0cf69786b4 100644
> > --- a/python/qemu/machine/machine.py
> > +++ b/python/qemu/machine/machine.py
> > @@ -342,9 +342,15 @@ def _post_shutdown(self) -> None:
> >          # Comprehensive reset for the failed launch case:
> >          self._early_cleanup()
> >
> > -        if self._qmp_connection:
> > -            self._qmp.close()
> > -            self._qmp_connection = None
> > +        try:
> > +            self._close_qmp_connection()
> > +        except Exception as err:  # pylint: disable=broad-except
> > +            LOG.warning(
> > +                "Exception closing QMP connection: %s",
> > +                str(err) if str(err) else type(err).__name__
> > +            )
> > +        finally:
> > +            assert self._qmp_connection is None
> >
> >          self._close_qemu_log_file()
> >
> > @@ -420,6 +426,31 @@ def _launch(self) -> None:
> >                                         close_fds=False)
> >          self._post_launch()
> >
> > +    def _close_qmp_connection(self) -> None:
> > +        """
> > +        Close the underlying QMP connection, if any.
> > +
> > +        Dutifully report errors that occurred while closing, but assume
> > +        that any error encountered indicates an abnormal termination
> > +        process and not a failure to close.
> > +        """
> > +        if self._qmp_connection is None:
> > +            return
> > +
> > +        try:
> > +            self._qmp.close()
> > +        except EOFError:
> > +            # EOF can occur as an Exception here when using the Async
> > +            # QMP backend. It indicates that the server closed the
> > +            # stream. If we successfully issued 'quit' at any point,
> > +            # then this was expected. If the remote went away without
> > +            # our permission, it's worth reporting that as an abnormal
> > +            # shutdown case.
> > +            if not (self._user_killed or self._quit_issued):
> > +                raise
>
> Isn't this racy for those tests that expect QEMU to quit by itself and
> then later call wait()? self._quit_issued is only set to True in wait(),
> but whatever will cause QEMU to quit happens earlier and it might
> actually quit before wait() is called.
>

_quit_issued is also set to True via qmp() and command(), but I think
you're referring to cases where QEMU terminates for other reasons than an
explicit command. So, yes, QEMU might indeed terminate/abort/quit before
machine.py has recorded that fact somewhere. I wasn't aware of that being a
problem. I suppose it'd be racy if, say, you orchestrated a "side-channel
quit" and then didn't call wait() and instead called shutdown(). I think
that's the case you're worried about? But, this code should ultimately be
called in only four cases:

(1) Connection failure
(2) shutdown()
(3) shutdown(), via wait()
(4) shutdown(), via kill()

I had considered it a matter of calling the correct exit path from the test
code. If shutdown() does what the label on the tin says (it shuts down the
VM), I actually would expect it to be racy if QEMU was in the middle of
deconstructing itself. That's the belief behind changing around iotest 300
the way I did.


> It would make sense to me that such tests need to declare that they
> expect QEMU to quit before actually performing the action. And then
> wait() becomes less weird in patch 1, too, because it can just assert
> self._quit_issued instead of unconditionally setting it.
>

That's a thought. I was working on the model that calling wait() implies
the fact that the writer is expecting it to terminate through some
mechanism otherwise invisible to machine.py (HMP perhaps, a QGA action,
migration failure, etc.) It's one less call vs. saying "expect_shutdown();
wait_shutdown()". I wasn't aware of a circumstance where you'd want to
separate these two semantic bits of info ("I expect QEMU will shut down" /
"I am waiting for QEMU to shut down") and since the latter implied the
former, I rolled 'em up into one.

I suppose in your case, you're wondering what happens if we decide to call
shutdown() instead of wait() after orchestrating a "side-channel quit"? I
*would* have considered that a semantic error in the author's code, but I
suppose it's reasonable to expect that "shutdown() should DTRT". Though, in
order for it to DTRT, you have to inform machine that you're expecting that
side-channel termination, and if you already forgot to use wait() instead
of shutdown(), I'm not sure I can help the author remember that they should
have issued a "expect_shutdown()" or similar.

The other point I'm unsure is whether you can actually kill QEMU without
> getting either self._user_killed or self._quit_issued set. The
> potentially problematic case I see is shutdown(hard = False) where soft
> shutdown fails. Then a hard shutdown will be performed without setting
> self._user_killed (is this a bug?).
>

The original intent of _user_killed was specifically to record cases where
the test-writer *intentionally* killed the VM process. We then used that
flag to change the error reporting on cleanup in _post_shutdown. The idea
was that if the QEMU process terminated due to signal and we didn't
explicitly intentionally cause it, that we should loudly report that
occurrence. We added this specifically to catch problems on the exit path
in various iotests. So, the fact that soft shutdown fails over to a hard
shutdown but doesn't set that intent flag is the intended behavior.

So, what about _close_qmp_connection()? I figured that if any of the
following were true:

1) quit was explicitly issued via qmp() or command()
2) wait() was called instead of shutdown, implying an anticipated
side-channel termination
3) kill() or shutdown(hard=True) was called

... then we were expecting the remote to hang up on us, and we didn't need
to report that error.

What about when the VM is killed but it wasn't explicitly intentional by
the test-writer? As far as machine.py knows, it was unintentional and so it
will allow that error to trickle up when _close_qmp_connection() is called.
The server hung up on us and we have no idea why. The error will be
reported upwards. From the context of just this one function, that seems
like the correct behavior.

Of course, sending the 'quit' command in _soft_shutdown() will set
> self._quit_issued at least, but are we absolutely sure that it can never
> raise an exception before getting to qmp()? I guess in theory, closing
> the console socket in _early_cleanup() could raise one? (But either way,
> not relying on such subtleties would make the code easier to
> understand.)
>

If it does raise an exception before getting to qmp(), we'll fail over to
the hard shutdown path.

shutdown()
  _do_shutdown()
    _soft_shutdown()
      _early_cleanup() -- Let's say this one chokes.

So we'll likely have _quit_issued = False and _user_killed = False.

We fail over:

shutdown()
  _do_shutdown()
    _hard_shutdown()
      _early_cleanup() -- Uh oh, if it failed once, it might fail again.
      self._subp.kill()
      self._subp.wait(timeout=60)

I'm going to ignore the _early_cleanup() problem here for a moment, as it's
a pre-existing problem and I'll fix it separately. Let's just continue the
hypothetical.

shutdown()
  _post_shutdown()
    _early_cleanup()  -- Uh oh for a third time.
    _close_qmp_connection()
    ...

At this point, we're finally going to try to close this connection.

        try:
            self._close_qmp_connection()
        except Exception as err:  # pylint: disable=broad-except

            LOG.warning(
                "Exception closing QMP connection: %s",
                str(err) if str(err) else type(err).__name__
            )
        finally:
            assert self._qmp_connection is None

And the grand result is that it's very likely just going to log a warning
to the error stream saying that the QMP connection closed in a weird way --
possibly EOFError, possibly ECONNABORTED, ECONNRESET, EPIPE.The rest of
cleanup will continue, and the exception that was stored prior to executing
the "finally:" phase of shutdown() will now be raised, which would be:

raise AbnormalShutdown("Could not perform graceful shutdown") from exc

where 'exc' is the theoretical exception from _soft_shutdown >
_early_cleanup.

Ultimately, we'll see an error log for the QMP connection terminating in a
strange way, followed by a stack trace for our failure to gracefully shut
down the VM (because the early cleanup code failed.) I think this is
probably a reasonable way to report this circumstance -- the machine.py
code has no idea what's going on, so it (as best as it can) just reports
the errors it sees. This makes the cleanup code a little "eager to fail",
but for a testing suite I thought that was actually appropriate behavior.

I think this is at least functional as written, ultimately? The trick is
remembering to call wait() instead of shutdown() when you need it, but I
don't see a way to predict or track the intent of the test-writer any
better than that, so I don't know how to improve the usability of the
library around that case, exactly.

--js


>
> Kevin
>
>

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

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition
  2021-10-27 12:56   ` Kevin Wolf
@ 2021-10-27 17:55     ` John Snow
  0 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-27 17:55 UTC (permalink / raw)
  To: Kevin Wolf
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

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

On Wed, Oct 27, 2021 at 8:56 AM Kevin Wolf <kwolf@redhat.com> wrote:

> Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> > Wait for the destination VM to close itself instead of racing to shut it
> > down first, which produces different error log messages from AQMP
> > depending on precisely when we tried to shut it down.
> >
> > (For example: We may try to issue 'quit' immediately prior to the target
> > VM closing its QMP socket, which will cause an ECONNRESET error to be
> > logged. Waiting for the VM to exit itself avoids the race on shutdown
> > behavior.)
> >
> > Reported-by: Hanna Reitz <hreitz@redhat.com>
> > Signed-off-by: John Snow <jsnow@redhat.com>
>
> I think this will still expose the race I described in my comment on
> patch 2.
>
> Kevin
>
>
I wrote a long, meandering explanation of how I think things work in reply
to that comment. TLDR: I didn't see the problem.

Here in reply to this comment I'll just ask: what exactly *is* the race you
see happening here even with this patch? I'm not sure I see it.

--js

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

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously
  2021-10-27 17:49     ` John Snow
@ 2021-10-28 10:01       ` Kevin Wolf
  2021-10-28 15:35         ` John Snow
  0 siblings, 1 reply; 17+ messages in thread
From: Kevin Wolf @ 2021-10-28 10:01 UTC (permalink / raw)
  To: John Snow
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

Am 27.10.2021 um 19:49 hat John Snow geschrieben:
> This reply is long, sorry.

And after writing half of a very long reply myself, I noticed that I was
just very confused, so sorry for making you write a long text for no
real reason (well, at least for my first point - for the second one,
your explanation was very helpful, so thanks for that).

Somehow I ended up completely ignoring the context of the code (it's run
as part of shutdown functions) and instead thought of the general
condition of QMP connections going away anywhere in the code.

I suppose this could be a relevant concern in an actually asynchronous
client that may read from the socket (and encounter an error if the QEMU
process has already gone away and closed the connection) at any time,
but that's not what machine.py is meant for, at least not for now.

So I'll just delete what I already wrote. This patch should be fine.

Kevin



^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 0/8] Switch iotests to using Async QMP
  2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
                   ` (7 preceding siblings ...)
  2021-10-26 17:56 ` [PATCH v5 8/8] python, iotests: replace qmp with aqmp John Snow
@ 2021-10-28 10:37 ` Kevin Wolf
  2021-10-28 14:48   ` John Snow
  8 siblings, 1 reply; 17+ messages in thread
From: Kevin Wolf @ 2021-10-28 10:37 UTC (permalink / raw)
  To: John Snow
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> GitLab: https://gitlab.com/jsnow/qemu/-/commits/python-aqmp-iotest-wrapper
> CI: https://gitlab.com/jsnow/qemu/-/pipelines/395925703
> 
> Hiya,
> 
> This series continues where the last two AQMP series left off and adds a
> synchronous 'legacy' wrapper around the new AQMP interface, then drops
> it straight into iotests to prove that AQMP is functional and totally
> cool and fine. The disruption and churn to iotests is pretty minimal.
> 
> In the event that a regression happens and I am not physically proximate
> to inflict damage upon, one may set the QEMU_PYTHON_LEGACY_QMP variable
> to any non-empty string as it pleases you to engage the QMP machinery
> you are used to.

I obviously haven't reviewed systematically that AQMP is actually
correctly implemented and does what this series expects it to do, but
treating it as a black box should be good enough for this series:

Reviewed-by: Kevin Wolf <kwolf@redhat.com>



^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 0/8] Switch iotests to using Async QMP
  2021-10-28 10:37 ` [PATCH v5 0/8] Switch iotests to using Async QMP Kevin Wolf
@ 2021-10-28 14:48   ` John Snow
  0 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-28 14:48 UTC (permalink / raw)
  To: Kevin Wolf
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

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

On Thu, Oct 28, 2021 at 6:37 AM Kevin Wolf <kwolf@redhat.com> wrote:

> Am 26.10.2021 um 19:56 hat John Snow geschrieben:
> > GitLab:
> https://gitlab.com/jsnow/qemu/-/commits/python-aqmp-iotest-wrapper
> > CI: https://gitlab.com/jsnow/qemu/-/pipelines/395925703
> >
> > Hiya,
> >
> > This series continues where the last two AQMP series left off and adds a
> > synchronous 'legacy' wrapper around the new AQMP interface, then drops
> > it straight into iotests to prove that AQMP is functional and totally
> > cool and fine. The disruption and churn to iotests is pretty minimal.
> >
> > In the event that a regression happens and I am not physically proximate
> > to inflict damage upon, one may set the QEMU_PYTHON_LEGACY_QMP variable
> > to any non-empty string as it pleases you to engage the QMP machinery
> > you are used to.
>
> I obviously haven't reviewed systematically that AQMP is actually
> correctly implemented and does what this series expects it to do, but
> treating it as a black box should be good enough for this series:
>
> Reviewed-by: Kevin Wolf <kwolf@redhat.com>
>

Yeah. I've tested it "a lot" and I think it should work fine, it seems to
work fine in practice, there's lots of unit tests for the core
transport/async bits. And worst case, we can switch it back with a single
line change.

Thanks!

--js

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

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously
  2021-10-28 10:01       ` Kevin Wolf
@ 2021-10-28 15:35         ` John Snow
  0 siblings, 0 replies; 17+ messages in thread
From: John Snow @ 2021-10-28 15:35 UTC (permalink / raw)
  To: Kevin Wolf
  Cc: Vladimir Sementsov-Ogievskiy, Eduardo Habkost, qemu-block,
	qemu-devel, Hanna Reitz, Cleber Rosa

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

On Thu, Oct 28, 2021, 6:01 AM Kevin Wolf <kwolf@redhat.com> wrote:

> Am 27.10.2021 um 19:49 hat John Snow geschrieben:
> > This reply is long, sorry.
>
> And after writing half of a very long reply myself, I noticed that I was
> just very confused, so sorry for making you write a long text for no
> real reason (well, at least for my first point - for the second one,
> your explanation was very helpful, so thanks for that).
>
> Somehow I ended up completely ignoring the context of the code (it's run
> as part of shutdown functions) and instead thought of the general
> condition of QMP connections going away anywhere in the code.
>
> I suppose this could be a relevant concern in an actually asynchronous
> client that may read from the socket (and encounter an error if the QEMU
> process has already gone away and closed the connection) at any time,
> but that's not what machine.py is meant for, at least not for now.
>
> So I'll just delete what I already wrote. This patch should be fine.
>
> Kevin
>

No problem. The cleanup path here is quite complex, so it wasn't clear that
there *wasn't* a problem.

I'd like to upgrade machine.py to use asyncio more natively for the console
socket and qmp layers in the future and help break it apart into smaller
pieces that are easier to reason about.

You're right, though, if/when this part becomes async then needing more
precision on when we mark a vm as defunct will become important.

Thanks for looking at it!

--js

>

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

^ permalink raw reply	[flat|nested] 17+ messages in thread

end of thread, other threads:[~2021-10-28 15:37 UTC | newest]

Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-10-26 17:56 [PATCH v5 0/8] Switch iotests to using Async QMP John Snow
2021-10-26 17:56 ` [PATCH v5 1/8] python/machine: remove has_quit argument John Snow
2021-10-26 17:56 ` [PATCH v5 2/8] python/machine: Handle QMP errors on close more meticulously John Snow
2021-10-27 11:19   ` Kevin Wolf
2021-10-27 17:49     ` John Snow
2021-10-28 10:01       ` Kevin Wolf
2021-10-28 15:35         ` John Snow
2021-10-26 17:56 ` [PATCH v5 3/8] python/aqmp: Remove scary message John Snow
2021-10-26 17:56 ` [PATCH v5 4/8] iotests: Accommodate async QMP Exception classes John Snow
2021-10-26 17:56 ` [PATCH v5 5/8] iotests: Conditionally silence certain AQMP errors John Snow
2021-10-26 17:56 ` [PATCH v5 6/8] iotests/300: avoid abnormal shutdown race condition John Snow
2021-10-27 12:56   ` Kevin Wolf
2021-10-27 17:55     ` John Snow
2021-10-26 17:56 ` [PATCH v5 7/8] python/aqmp: Create sync QMP wrapper for iotests John Snow
2021-10-26 17:56 ` [PATCH v5 8/8] python, iotests: replace qmp with aqmp John Snow
2021-10-28 10:37 ` [PATCH v5 0/8] Switch iotests to using Async QMP Kevin Wolf
2021-10-28 14:48   ` John Snow

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).