Re: [Qemu-devel] [PATCH v3 2/3] qemu.py: include debug information on launch error

[Markus Armbruster <armbru@redhat.com>]

Amador Pahim <apahim@redhat.com> writes:

> When launching a VM, if an exception happens and the VM is not
> initiated, it is useful to see the qemu command line that was executed
> and the output of that command.
>
> Before the patch:
>
>     >>> VM = qemu.QEMUMachine('../aarch64-softmmu/qemu-system-aarch64')
>     >>> VM.launch()
>     Traceback (most recent call last):
>       File "<stdin>", line 1, in <module>
>       File "qemu.py", line 137, in launch
>         self._post_launch()
>       File "qemu.py", line 121, in _post_launch
>         self._qmp.accept()
>       File "qmp/qmp.py", line 145, in accept
>         self.__sock, _ = self.__sock.accept()
>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>         sock, addr = self._sock.accept()
>     socket.timeout: timed out
>
> After the patch:
>
>     >>> VM = qemu.QEMUMachine('../aarch64-softmmu/qemu-system-aarch64')
>     >>> VM.launch()
>     Traceback (most recent call last):
>       File "<stdin>", line 1, in <module>
>       File "qemu.py", line 156, in launch
>         raise RuntimeError(msg)
>     RuntimeError: Error launching VM.
>     Original Exception:
>     Traceback (most recent call last):
>       File "qemu.py", line 138, in launch
>         self._post_launch()
>       File "qemu.py", line 122, in _post_launch
>         self._qmp.accept()
>       File "qmp/qmp.py", line 145, in accept
>         self.__sock, _ = self.__sock.accept()
>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>         sock, addr = self._sock.accept()
>     timeout: timed out
>     Command:
>     /usr/bin/qemu-system-aarch64 -chardev socket,id=mon,
>     path=/var/tmp/qemu-23958-monitor.sock -mon chardev=mon,mode=control
>     -display none -vga none
>     Output:
>     qemu-system-aarch64: No machine specified, and there is no default
>     Use -machine help to list supported machines
>
> Also, if the launch() faces an exception, the 'except' now will use args
> to fill the debug information. So this patch assigns 'args' earlier,
> assuring it will be available for the 'except'.
>
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> Reviewed-by: Fam Zheng <famz@redhat.com>
> ---
>  scripts/qemu.py | 18 ++++++++++++++++--
>  1 file changed, 16 insertions(+), 2 deletions(-)
>
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index f0fade32bd..2707ae7f75 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -18,6 +18,7 @@ import os
>  import sys
>  import subprocess
>  import qmp.qmp
> +import traceback
>  
>  
>  class QEMUMachine(object):
> @@ -129,17 +130,30 @@ class QEMUMachine(object):
>          '''Launch the VM and establish a QMP connection'''
>          devnull = open('/dev/null', 'rb')
>          qemulog = open(self._qemu_log_path, 'wb')
> +        args = self._wrapper + [self._binary] + self._base_args() + self.args
>          try:
>              self._pre_launch()
> -            args = self._wrapper + [self._binary] + self._base_args() + self._args
>              self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
>                                             stderr=subprocess.STDOUT, shell=False)
>              self._post_launch()

Lifting the assignment out of the try makes sense, because exceptions
there are programming errors.

Why are ._pre_launch() and ._post_launch() inside the try?

>          except:

Why do we catch all exceptions, and not just
subprocess.CalledProcessError?

> +            self._load_io_log()
>              if self.is_running():

I suspect we can't get here only for "odd" exceptions, not for
subprocess.CalledProcessError.

>                  self._popen.kill()
>                  self._popen.wait()
> -            self._load_io_log()
> +            else:
> +                exc_type, exc_value, exc_traceback = sys.exc_info()
> +                msg = ('Error launching VM.\n'
> +                       'Original Exception: \n%s'
> +                       'Command:\n%s\n'
> +                       'Output:\n%s\n' %
> +                       (''.join(traceback.format_exception(exc_type,
> +                                                           exc_value,
> +                                                           exc_traceback)),
> +                        ' '.join(args),
> +                        self._iolog))
> +                self._post_shutdown()
> +                raise RuntimeError(msg)
>              self._post_shutdown()
>              raise

Why do we print a traceback when subprocess.CalledProcessError?