Re: [PATCH 7/8] python/qemu: allow avocado to set logging name space

["Alex Bennée" <alex.bennee@linaro.org>]

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
>>


-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro