Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Markus Armbruster]

Amador Pahim <address@hidden> writes:

> On Fri, Aug 18, 2017 at 4:01 PM, Markus Armbruster <address@hidden> wrote:
>> Amador Pahim <address@hidden> writes:
>>
>>> On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <address@hidden> wrote:
>>>> Amador Pahim <address@hidden> 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 this patch:
>>>>>
>>>>>     >>> import qemu
>>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>>     >>> vm.launch()
>>>>>     Traceback (most recent call last):
>>>>>       File "<stdin>", line 1, in <module>
>>>>>       File "qemu.py", line 175, in launch
>>>>>         self._launch()
>>>>>       File "qemu.py", line 189, in _launch
>>>>>         self._post_launch()
>>>>>       File "qemu.py", line 154, 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 this patch:
>>>>>
>>>>>     >>> import qemu
>>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>>     >>> vm.launch()
>>>>>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>>>>>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>>>>>     -mon chardev=mon,mode=control -display none -vga none'.
>>>>>     Output: 'qemu-system-aarch64: No machine specified, and there
>>>>>     is no default\nUse -machine help to list supported machines\n'.
>>>>>     Traceback (most recent call last):
>>>>>       File "<stdin>", line 1, in <module>
>>>>>       File "qemu.py", line 175, in launch
>>>>>         self._launch()
>>>>>       File "qemu.py", line 189, in _launch
>>>>>         self._post_launch()
>>>>>       File "qemu.py", line 154, 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
>>>>>     >>>
>>>>>
>>>>> Signed-off-by: Amador Pahim <address@hidden>
>>>>> ---
>>>>>  scripts/qemu.py | 12 +++++++++++-
>>>>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>>>>
>>>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>>>> index e9a3a96d13..43fd0b072c 100644
>>>>> --- a/scripts/qemu.py
>>>>> +++ b/scripts/qemu.py
>>>>> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>>>>>              self._remove_if_exists(self._created_files.pop())
>>>>>
>>>>>      def launch(self):
>>>>> -        '''Launch the VM and establish a QMP connection'''
>>>>> +        '''
>>>>> +        Try to launch the VM and make sure we cleanup and expose the
>>>>> +        command line/output in case of exception.
>>>>> +        '''
>>>>>
>>>>>          if self.is_running():
>>>>>              raise QEMULaunchError('VM already running.')
>>>>> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>>>>>                                    'before launching again.')
>>>>>
>>>>>          try:
>>>>> +            self._iolog = None
>>>>>              self._qemu_full_args = None
>>>>>              self._qemu_full_args = (self._wrapper + [self._binary] +
>>>>>                                      self._base_args() + self._args)
>>>>> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>>>>>              self._pending_shutdown = True
>>>>>          except:
>>>>>              self.shutdown()
>>>>> +            LOG.debug('Error launching VM.%s%s',
>>>>> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
>>>>> +                      if self._qemu_full_args else '',
>>>>> +                      ' Output: %r.' % self._iolog
>>>>> +                      if self._iolog else '')
>>>>
>>>> This nested interpolation is too ugly to live :)
>>>
>>> I find it beautiful :)
>>> Killing it anyway.
>>>
>>>>
>>>> Nesting is easy to avoid:
>>>>
>>>>                LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
>>>>                          % (' '.join(self._qemu_full_args)
>>>>                             if self._qemu_full_args else '',
>>>>                             self._iolog
>>>>                             if self._iolog else ''))
>>>
>>> In this case we will have the strings "Command: " and "Output:" even
>>> with no content to expose.
>>
>> No command should not happen.
>
> It can happen, if we fail before the self._qemu_full_args become ready
> (i.e. if self._base_args() fails).

If we fail before we even have a command line, it's not really an "Error
launching VM", it's more like "can't figure out how to launch the VM".

I suspect the root of the problem is an overly large try block.  Which
also has a catch-all except to further enhance that delicious code
smell.

I fear we have bigger fish to fry than careless error reporting.
Debating it to the n-th degree is no use; do what you think is best.

[...]