| Message ID | 20230518162034.1277885-8-alex.bennee@linaro.org |
|---|---|
| State | New |
| Headers | show |
| Series | testing/next: avocado logging, docs, gitlab | expand |
On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@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. Also, what about the QMP logging? I don't suppose this will trickle down to that level either. Worried this is kind of incomplete. --js > Signed-off-by: Alex Bennée <alex.bennee@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 >
John Snow <jsnow@redhat.com> writes: > On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@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. > 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 <alex.bennee@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 >>
On Fri, May 19, 2023 at 2:39 AM Alex Bennée <alex.bennee@linaro.org> wrote: > > > John Snow <jsnow@redhat.com> writes: > > > On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@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.bennee@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 > >> >
On Thu, May 18, 2023 at 04:15:03PM -0400, John Snow wrote: > On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@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. I'd consider this a regression in Avocado. Logging should log everything from any module by default. Avocado should not presume that users are only interested in Avocado's own namespace. The namespaces used by the individuals test are more interesting to users of Avocado IMHO. > Also, what about the QMP logging? I don't suppose this will trickle > down to that level either. > > Worried this is kind of incomplete. Agreed, I'd push this back onto Avocado to fix the regression. With regards, Daniel
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)
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. Signed-off-by: Alex Bennée <alex.bennee@linaro.org> --- python/qemu/machine/machine.py | 42 ++++++++++++++------------ tests/avocado/avocado_qemu/__init__.py | 3 +- 2 files changed, 24 insertions(+), 21 deletions(-)