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

[John Snow]

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 <address@hidden>
> > ---
> >   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):