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

[John Snow <jsnow@redhat.com>]

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.

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

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.

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.

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