John Snow <[email protected]> writes:
> On Thu, May 18, 2023 at 12:20 PM Alex Bennée <[email protected]> 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. > 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. > > Worried this is kind of incomplete. > > --js > >> Signed-off-by: Alex Bennée <[email protected]> >> --- >> 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 >> -- Alex Bennée Virtualisation Tech Lead @ Linaro
