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

[Amador Pahim]

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

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

Same here. But even more likely to happen, as one exception either
pre_launch() or launch() can trigger this message without an output.
But if that's your preference, I don't really mind having:
INFO:qemu:Error launching VM. Command: ''. Output: ''.


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

Hard to say what's a sane limit. I'd prefer to log it all and let the
scripts tweak that using the logging.Formatter, if they want to.

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