Re: [Qemu-devel] [PATCH v5 18/21] iotests: add QMP event waiting queue

[Max Reitz <mreitz@redhat.com>]

On 17.04.2015 20:23, John Snow wrote:
>
>
> On 04/17/2015 09:33 AM, Max Reitz wrote:
>> On 09.04.2015 00:20, John Snow wrote:
>>> A filter is added to allow callers to request very specific
>>> events to be pulled from the event queue, while leaving undesired
>>> events still in the stream.
>>>
>>> This allows to poll for completion data for multiple asynchronous
>>> events in any arbitrary order.
>>>
>>> A new timeout context is added to the qmp pull_event method's
>>> wait parameter to allow tests to fail if they do not complete
>>> within some expected period of time.
>>>
>>> Signed-off-by: John Snow <jsnow@redhat.com>
>>> ---
>>>   scripts/qmp/qmp.py            |  6 +++++-
>>>   tests/qemu-iotests/iotests.py | 38
>>> ++++++++++++++++++++++++++++++++++++++
>>>   2 files changed, 43 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/scripts/qmp/qmp.py b/scripts/qmp/qmp.py
>>> index 20b6ec7..7f9ac1b 100644
>>> --- a/scripts/qmp/qmp.py
>>> +++ b/scripts/qmp/qmp.py
>>> @@ -140,7 +140,8 @@ class QEMUMonitorProtocol:
>>>           """
>>>           Get and delete the first available QMP event.
>>> -        @param wait: block until an event is available (bool)
>>> +        @param wait: block until an event is available. If a float is
>>> provided,
>>> +                     use this as a timeout value. (bool, float)
>>
>> Ouch... I guess it works, though...
>>
>
> It does read awkwardly in the declaration, but I also thought that:
>
> wait=False
> wait=True
> wait=60.0
> wait=0.0
>
> all read fairly clearly and had very clear implications, so from a 
> usage standpoint it seemed very nice and convenient.
>
> Making a second parameter gets strange:
>
> wait=False, timeout=50.0
>
> ^ What does this mean?
>
> wait=True, timeout=0.0
>
> ^ Does this mean to wait forever, or to not wait at all?
>
> So in this case I stand by what looks like hackishness as a nice, 
> semantically appropriate interface.

Yes, looks reasonable.

>>>           """
>>>           self.__sock.setblocking(0)
>>>           try:
>>> @@ -151,7 +152,10 @@ class QEMUMonitorProtocol:
>>>                   pass
>>>           self.__sock.setblocking(1)
>>>           if not self.__events and wait:
>>> +            if isinstance(wait, float):
>>> +                self.__sock.settimeout(wait)
>>>               self.__json_read(only_event=True)
>>> +            self.__sock.settimeout(None)
>>
>> If a timeout occurs, __json_read will do nothing and return (I 
>> guess...).
>>
>
> It will actually throw an exception.
>
>>>           event = self.__events[0]
>>
>> This will therefore probably return None...
>>
>
> So we'll never make it this far.
>
>>>           del self.__events[0]
>>
>> And I don't know what this will do. Will it be a no-op?
>>
>
> Better than a no-op!
>
>>>           return event
>>> diff --git a/tests/qemu-iotests/iotests.py
>>> b/tests/qemu-iotests/iotests.py
>>> index 1402854..e93e623 100644
>>> --- a/tests/qemu-iotests/iotests.py
>>> +++ b/tests/qemu-iotests/iotests.py
>>> @@ -78,6 +78,23 @@ def create_image(name, size):
>>>           i = i + 512
>>>       file.close()
>>> +# Test if 'match' is a recursive subset of 'event'
>>> +def event_match(event, match=None):
>>> +    if match is None:
>>> +        return True
>>> +
>>> +    for key in match:
>>> +        if key in event:
>>> +            if isinstance(event[key], dict):
>>> +                if not event_match(event[key], match[key]):
>>> +                    return False
>>> +            elif event[key] != match[key]:
>>> +                return False
>>> +        else:
>>> +            return False
>>> +
>>> +    return True
>>> +
>>>   class VM(object):
>>>       '''A QEMU VM'''
>>> @@ -92,6 +109,7 @@ class VM(object):
>>>                        '-machine', 'accel=qtest',
>>>                        '-display', 'none', '-vga', 'none']
>>>           self._num_drives = 0
>>> +        self._events = []
>>>       # This can be used to add an unused monitor instance.
>>>       def add_monitor_telnet(self, ip, port):
>>> @@ -202,14 +220,34 @@ class VM(object):
>>>       def get_qmp_event(self, wait=False):
>>>           '''Poll for one queued QMP events and return it'''
>>> +        if len(self._events) > 0:
>>> +            return self._events.pop(0)
>>>           return self._qmp.pull_event(wait=wait)
>>>       def get_qmp_events(self, wait=False):
>>>           '''Poll for queued QMP events and return a list of dicts'''
>>>           events = self._qmp.get_events(wait=wait)
>>> +        events.extend(self._events)
>>> +        del self._events[:]
>>>           self._qmp.clear_events()
>>>           return events
>>> +    def event_wait(self, name='BLOCK_JOB_COMPLETED', timeout=60.0,
>>> match=None):
>>> +        # Search cached events
>>> +        for event in self._events:
>>> +            if (event['event'] == name) and event_match(event, match):
>>> +                self._events.remove(event)
>>> +                return event
>>> +
>>> +        # Poll for new events
>>> +        while True:
>>> +            event = self._qmp.pull_event(wait=timeout)
>>
>> So if a timeout occurred, event will probably be None.
>>
>>> +            if (event['event'] == name) and event_match(event, match):
>>
>> And this (indexing event == None) will probably generate an exception. I
>> guess it's one way to fail the test, but certainly not the best...
>>
>> Max
>>
>
> In practice, the timeout throws a socket.timeout exception I don't 
> bother to catch, so execution of the test will fail at this point, 
> which is acceptable.

Well, if you find it acceptable, I'll be fine with it.

> Here's what happens in the next patch if I modify 'do_qmp_backup' to 
> wait for a made up event that will never happen:
>
> event = self.vm.event_wait(name="JOHN_SNOW_CHECKS_IN_A_21_PATCH_SERIES",
>             match={'data': {'device': kwargs['device']}})
> self.assertIsNotNone(event)
>
> +======================================================================
> +ERROR: test_incremental_simple (__main__.TestIncrementalBackup)
> +----------------------------------------------------------------------
> +Traceback (most recent call last):
> +  File "124", line 223, in test_incremental_simple
> +    self.create_anchor_backup()
> +  File "124", line 146, in create_anchor_backup
> +    format=drive['fmt'], target=drive['backup'])
> +  File "124", line 127, in do_qmp_backup
> +    match={'data': {'device': kwargs['device']}})
> +  File "/home/bos/jhuston/src/qemu/tests/qemu-iotests/iotests.py", 
> line 244, in event_wait
> +    event = self._qmp.pull_event(wait=timeout)
> +  File 
> "/home/bos/jhuston/src/qemu/tests/qemu-iotests/../../scripts/qmp/qmp.py", 
> line 157, in pull_event
> +    self.__json_read(only_event=True)
> +  File 
> "/home/bos/jhuston/src/qemu/tests/qemu-iotests/../../scripts/qmp/qmp.py", 
> line 63, in __json_read
> +    data = self.__sockfile.readline()
> +  File "/usr/lib64/python2.7/socket.py", line 447, in readline
> +    data = self._sock.recv(self._rbufsize)
> +timeout: timed out
> +
>
> Python tracebacks are still awful to read, but you can see we failed 
> due to a timeout.

But I wouldn't understand it. I mean, the content is there, but I know 
my mind would go blank just the instand a stacktrace appears, and I 
wouldn't bother to try to understand what "timeout" under "__json_read" 
could mean.

> Hmm, though... I am now noticing that pull_event will definitely fail 
> if you decide not to wait and there are no items in the queue, so...
>
> I think I will rewrite some of qmp.py while I'm here, and I'll make 
> the error for timeout a little nicer for the end user.

But please don't try too hard. Even though what I said might not sound 
like it, the most important thing is still that the test just fails if 
something goes wrong. It's always nice if it's simple to figure out why 
it failed, but as long as the test author can figure it out somehow, 
it'll suffice. :-)

Max

>
>>> +                return event
>>> +            self._events.append(event)
>>> +
>>> +        return None
>>> +
>>>   index_re = re.compile(r'([^\[]+)\[([^\]]+)\]')
>>>   class QMPTestCase(unittest.TestCase):
>>
>>