Amador Pahim <apa...@redhat.com> writes:
> On Thu, Jul 20, 2017 at 1:58 PM, Markus Armbruster <arm...@redhat.com> wrote:
>> Amador Pahim <apa...@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 <apa...@redhat.com>
>>> Reviewed-by: Fam Zheng <f...@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?
>
> The _pre_launch()/_post_launch() are probably the main source of
> exceptions here and I assume we want to handle the exceptions coming
> from them.
>
> The call to subprocess.Popen() is unlikely to raise exceptions. I
> mean, it's easy to trigger an 'OSError' exception providing a
> non-existent command to Popen, but once we provide something
> executable, we will not see an exception here if the command fails.
> The CalledProcessError is only raised by subprocess.check_call() or
> subprocess.check_output().
Okay.
Catching all exceptions is too sloppy for my taste. But it's not your
patch's fault.
>>> 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?
>
> subprocess.CalledProcessError will not happen with subprocess.Popen,
> even if the command fails. But if the virtual machine does not start,
> we will, for example, see a 'socket.timeout' exception coming from
> _post_launch() when it tries to connect to the qemu monitor.
A traceback is a inexcusably lazy way to report such errors. You're
putting lipstick on a pig.
When putting on lipstick is all we can do, it can be better than
nothing. Is it all we can do?
