On Fri, May 19, 2023 at 2:39 AM Alex Bennée <alex.ben...@linaro.org> wrote:
>
>
> John Snow <js...@redhat.com> writes:
>
> > On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.ben...@linaro.org> wrote:
> >>
> >> Since the update to the latest version Avocado only automatically
> >> collects logging under the avocado name space. Tweak the QEMUMachine
> >> class to allow avocado to bring logging under its name space. This
> >> also allows useful tricks like:
> >>
> >> ./avocado --show avocado.qemu.machine run path/to/test
> >>
> >> if you want to quickly get the machine invocation out of a test
> >> without searching deeply through the logs.
> >>
> >
> > Huh. That's kind of weird though, right? Each Python module is
> > intended to log to its own namespace by design; it feels like Avocado
> > really ought to have configuration options that allows it to collect
> > logging from other namespaces. I'm not against this patch, but if for
> > instance I wind up splitting qemu.machine out as a separate module
> > someday (like I did to qemu.qmp), then it feels weird to add options
> > specifically for fudging the logging hierarchy.
>
> According to the docs it does but I couldn't get it to work so this is a
> sticking plaster over that. If it gets fixed in later avocado's it is
> easy enough to remove.
>
Fair enough ...
Cleber, any input?
> > Also, what about the QMP logging? I don't suppose this will trickle
> > down to that level either.
>
> I can certainly add that - but it would need a similar hook.
Right... this is why I am wondering if it isn't just simpler to
configure Avocado to just relay everything from the qemu.* namespace,
which will be easier in the long run ... but hey, if it's broken, it's
broken :(
ACK to the bandaid.
--js
>
> >
> > Worried this is kind of incomplete.
> >
> > --js
> >
> >> Signed-off-by: Alex Bennée <alex.ben...@linaro.org>
> >> ---
> >> python/qemu/machine/machine.py | 42 ++++++++++++++------------
> >> tests/avocado/avocado_qemu/__init__.py | 3 +-
> >> 2 files changed, 24 insertions(+), 21 deletions(-)
> >>
> >> diff --git a/python/qemu/machine/machine.py
> >> b/python/qemu/machine/machine.py
> >> index e57c254484..402b9a0df9 100644
> >> --- a/python/qemu/machine/machine.py
> >> +++ b/python/qemu/machine/machine.py
> >> @@ -49,10 +49,6 @@
> >>
> >> from . import console_socket
> >>
> >> -
> >> -LOG = logging.getLogger(__name__)
> >> -
> >> -
> >> class QEMUMachineError(Exception):
> >> """
> >> Exception called when an error in QEMUMachine happens.
> >> @@ -131,6 +127,7 @@ def __init__(self,
> >> drain_console: bool = False,
> >> console_log: Optional[str] = None,
> >> log_dir: Optional[str] = None,
> >> + log_namespace: Optional[str] = None,
> >> qmp_timer: Optional[float] = 30):
> >> '''
> >> Initialize a QEMUMachine
> >> @@ -164,6 +161,11 @@ def __init__(self,
> >> self._sock_dir = sock_dir
> >> self._log_dir = log_dir
> >>
> >> + if log_namespace:
> >> + self.log = logging.getLogger(log_namespace)
> >> + else:
> >> + self.log = logging.getLogger(__name__)
> >> +
> >> self._monitor_address = monitor_address
> >>
> >> self._console_log_path = console_log
> >> @@ -382,11 +384,11 @@ def _post_shutdown(self) -> None:
> >> Called to cleanup the VM instance after the process has exited.
> >> May also be called after a failed launch.
> >> """
> >> - LOG.debug("Cleaning up after VM process")
> >> + self.log.debug("Cleaning up after VM process")
> >> try:
> >> self._close_qmp_connection()
> >> except Exception as err: # pylint: disable=broad-except
> >> - LOG.warning(
> >> + self.log.warning(
> >> "Exception closing QMP connection: %s",
> >> str(err) if str(err) else type(err).__name__
> >> )
> >> @@ -414,7 +416,7 @@ def _post_shutdown(self) -> None:
> >> command = ' '.join(self._qemu_full_args)
> >> else:
> >> command = ''
> >> - LOG.warning(msg, -int(exitcode), command)
> >> + self.log.warning(msg, -int(exitcode), command)
> >>
> >> self._quit_issued = False
> >> self._user_killed = False
> >> @@ -458,7 +460,7 @@ def _launch(self) -> None:
> >> Launch the VM and establish a QMP connection
> >> """
> >> self._pre_launch()
> >> - LOG.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
> >> + self.log.debug('VM launch command: %r', '
> >> '.join(self._qemu_full_args))
> >>
> >> # Cleaning up of this subprocess is guaranteed by _do_shutdown.
> >> # pylint: disable=consider-using-with
> >> @@ -507,7 +509,7 @@ def _early_cleanup(self) -> None:
> >> # for QEMU to exit, while QEMU is waiting for the socket to
> >> # become writable.
> >> if self._console_socket is not None:
> >> - LOG.debug("Closing console socket")
> >> + self.log.debug("Closing console socket")
> >> self._console_socket.close()
> >> self._console_socket = None
> >>
> >> @@ -518,7 +520,7 @@ def _hard_shutdown(self) -> None:
> >> :raise subprocess.Timeout: When timeout is exceeds 60 seconds
> >> waiting for the QEMU process to terminate.
> >> """
> >> - LOG.debug("Performing hard shutdown")
> >> + self.log.debug("Performing hard shutdown")
> >> self._early_cleanup()
> >> self._subp.kill()
> >> self._subp.wait(timeout=60)
> >> @@ -535,17 +537,17 @@ def _soft_shutdown(self, timeout: Optional[int]) ->
> >> None:
> >> :raise subprocess.TimeoutExpired: When timeout is exceeded
> >> waiting for
> >> the QEMU process to terminate.
> >> """
> >> - LOG.debug("Attempting graceful termination")
> >> + self.log.debug("Attempting graceful termination")
> >>
> >> self._early_cleanup()
> >>
> >> if self._quit_issued:
> >> - LOG.debug(
> >> + self.log.debug(
> >> "Anticipating QEMU termination due to prior 'quit'
> >> command, "
> >> "or explicit call to wait()"
> >> )
> >> else:
> >> - LOG.debug("Politely asking QEMU to terminate")
> >> + self.log.debug("Politely asking QEMU to terminate")
> >>
> >> if self._qmp_connection:
> >> try:
> >> @@ -557,14 +559,14 @@ def _soft_shutdown(self, timeout: Optional[int]) ->
> >> None:
> >> # Regardless, we want to quiesce the connection.
> >> self._close_qmp_connection()
> >> elif not self._quit_issued:
> >> - LOG.debug(
> >> + self.log.debug(
> >> "Not anticipating QEMU quit and no QMP connection
> >> present, "
> >> "issuing SIGTERM"
> >> )
> >> self._subp.terminate()
> >>
> >> # May raise subprocess.TimeoutExpired
> >> - LOG.debug(
> >> + self.log.debug(
> >> "Waiting (timeout=%s) for QEMU process (pid=%s) to terminate",
> >> timeout, self._subp.pid
> >> )
> >> @@ -586,9 +588,9 @@ def _do_shutdown(self, timeout: Optional[int]) -> None:
> >> self._soft_shutdown(timeout)
> >> except Exception as exc:
> >> if isinstance(exc, subprocess.TimeoutExpired):
> >> - LOG.debug("Timed out waiting for QEMU process to exit")
> >> - LOG.debug("Graceful shutdown failed", exc_info=True)
> >> - LOG.debug("Falling back to hard shutdown")
> >> + self.log.debug("Timed out waiting for QEMU process to
> >> exit")
> >> + self.log.debug("Graceful shutdown failed", exc_info=True)
> >> + self.log.debug("Falling back to hard shutdown")
> >> self._hard_shutdown()
> >> raise AbnormalShutdown("Could not perform graceful shutdown")
> >> \
> >> from exc
> >> @@ -611,9 +613,9 @@ def shutdown(self,
> >> if not self._launched:
> >> return
> >>
> >> - LOG.debug("Shutting down VM appliance; timeout=%s", timeout)
> >> + self.log.debug("Shutting down VM appliance; timeout=%s", timeout)
> >> if hard:
> >> - LOG.debug("Caller requests immediate termination of QEMU
> >> process.")
> >> + self.log.debug("Caller requests immediate termination of QEMU
> >> process.")
> >>
> >> try:
> >> if hard:
> >> diff --git a/tests/avocado/avocado_qemu/__init__.py
> >> b/tests/avocado/avocado_qemu/__init__.py
> >> index b19f797b7b..d925573299 100644
> >> --- a/tests/avocado/avocado_qemu/__init__.py
> >> +++ b/tests/avocado/avocado_qemu/__init__.py
> >> @@ -322,7 +322,8 @@ def require_multiprocess(self):
> >> def _new_vm(self, name, *args):
> >> self._sd = tempfile.TemporaryDirectory(prefix="qemu_")
> >> vm = QEMUMachine(self.qemu_bin, base_temp_dir=self.workdir,
> >> - sock_dir=self._sd.name, log_dir=self.logdir)
> >> + sock_dir=self._sd.name, log_dir=self.logdir,
> >> + log_namespace="avocado.qemu.machine")
> >> self.log.debug('QEMUMachine "%s" created', name)
> >> self.log.debug('QEMUMachine "%s" temp_dir: %s', name, vm.temp_dir)
> >> self.log.debug('QEMUMachine "%s" log_dir: %s', name, vm.log_dir)
> >> --
> >> 2.39.2
> >>
>
