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

[Markus Armbruster <armbru@redhat.com>]

Amador Pahim <apahim@redhat.com> writes:

> On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <armbru@redhat.com> wrote:
>> 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 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 <apahim@redhat.com>
>>> ---
>>>  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.

No output would be bad news.  Making that explicit in the logs feels
right to me.

>> Why %r and not %s?
>
> It's a matter of preference. I tend to avoid allowing messages to
> break the log line. Anyway, I'm improving this.

That's a really good point.  I'd go as far and call %s wrong now :)

Output could be arbitrarily long, though.

>> Are you sure '\n' is appropriate in the argument of LOG.debug()?
>>
>> Why cram everything into a single LOG.debug()?
>>
>>                LOG.debug('Error launching VM')
>>                LOG.debug('Command: %s' % (' '.join(self._qemu_full_args)
>>                                           if self._qemu_full_args else ''))
>>                LOG.debug('Output: %s' % self._iolog if self._iolog else ''))
>
> Sure, I'm ok with both ways.
>
>>
>>>              raise
>>>
>>>      def _launch(self):
>>> +        '''Launch the VM and establish a QMP connection.'''
>>>          self._pre_launch()
>>>          devnull = open(os.path.devnull, 'rb')
>>>          self._popen = subprocess.Popen(self._qemu_full_args,