On Fri, Aug 18, 2017 at 4:01 PM, Markus Armbruster <arm...@redhat.com> wrote:
> Amador Pahim <apa...@redhat.com> writes:
>
>> On Tue, Aug 15, 2017 at 10:57 AM, 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 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 <apa...@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.
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,
