bitmaps: remove x- prefix from QMP api Part2

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

We can accomplish this by sorting **kwargs into an OrderedDict, which does preserve addition order.

---
  tests/qemu-iotests/iotests.py | 21 +++++++++++++++++----
  1 file changed, 17 insertions(+), 4 deletions(-)

tests/qemu-iotests/iotests.py +1 -0

index 9595429fea..9aec03c7a3 100644
@@ -30,6 +30,7 @@ import signal
  import logging
  import atexit
  import io
+from collections import OrderedDict
 
  sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'scripts'))
  import qtest

tests/qemu-iotests/iotests.py +3 -2

-    if type(msg) is dict or type(msg) is list:
-        print(json.dumps(msg, sort_keys=True))
+    if isinstance(msg, dict) or isinstance(msg, list):
+        sort_keys = not isinstance(msg, OrderedDict)
+        print(json.dumps(msg, sort_keys=sort_keys))
      else:
          print(msg)
 

tests/qemu-iotests/iotests.py +0 -0

          result = self.qmp(cmd, **kwargs)
          log(json.dumps(result, sort_keys=True), filters)

Quoted 10 lines · John Snow

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

We can accomplish this by sorting **kwargs into an OrderedDict, which does preserve addition order.

---
  tests/qemu-iotests/iotests.py | 21 +++++++++++++++++----
  1 file changed, 17 insertions(+), 4 deletions(-)

Quoted 16 lines

tests/qemu-iotests/iotests.py +1 -0

index 9595429fea..9aec03c7a3 100644
@@ -30,6 +30,7 @@ import signal
  import logging
  import atexit
  import io
+from collections import OrderedDict
 
  sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'scripts'))
  import qtest

@@ -75,6 +76,16 @@ def qemu_img(*args):
          sys.stderr.write('qemu-img received signal %i: %s\n' % (-exitcode, ' '.join(qemu_img_args + list(args))))
      return exitcode
 

tests/qemu-iotests/iotests.py def qemu_img(*args): · line 82

Quoted 4 lines

tests/qemu-iotests/iotests.py +4 -0

+def ordered_kwargs(kwargs):
+    # kwargs prior to 3.6 are not ordered, so:
+    od = OrderedDict()
+    for k in sorted(kwargs.keys()):

you can use for k, v in sorted(kwargs.items()):
and use then v instead of kwargs[k]

Quoted 9 lines

tests/qemu-iotests/iotests.py +6 -0

+        if isinstance(kwargs[k], dict):
+            od[k] = ordered_kwargs(kwargs[k])
+        else:
+            od[k] = kwargs[k]
+    return od
+
  def qemu_img_create(*args):
      args = list(args)
 

tests/qemu-iotests/iotests.py def filter_img_info(output, filename): · line 270

Quoted 4 lines

tests/qemu-iotests/iotests.py +0 -0

@@ -257,8 +268,9 @@ def filter_img_info(output, filename):
  def log(msg, filters=[]):
      for flt in filters:
          msg = flt(msg)

I think that trying to apply text filters to object should be fixed first.

Quoted 11 lines

tests/qemu-iotests/iotests.py +3 -2

-    if type(msg) is dict or type(msg) is list:
-        print(json.dumps(msg, sort_keys=True))
+    if isinstance(msg, dict) or isinstance(msg, list):
+        sort_keys = not isinstance(msg, OrderedDict)
+        print(json.dumps(msg, sort_keys=sort_keys))
      else:
          print(msg)
 

@@ -448,8 +460,9 @@ class VM(qtest.QEMUQtestMachine):
          return result
 

tests/qemu-iotests/iotests.py class VM(qtest.QEMUQtestMachine): · line 464

Quoted 5 lines

tests/qemu-iotests/iotests.py +2 -2

      def qmp_log(self, cmd, filters=[filter_testfiles], **kwargs):
-        logmsg = '{"execute": "%s", "arguments": %s}' % \
-            (cmd, json.dumps(kwargs, sort_keys=True))
+        full_cmd = OrderedDict({"execute": cmd,
+                                "arguments": ordered_kwargs(kwargs)})

no, you can't use dict as a parameter to constructor, as dict is not ordered, use tuple of tuples, like OrderedDict((('execute': cmd), ('execute': ...)))

tests/qemu-iotests/iotests.py class VM(qtest.QEMUQtestMachine): · line 466

Quoted 4 lines

tests/qemu-iotests/iotests.py +1 -0

+        logmsg = json.dumps(full_cmd)
          log(logmsg, filters)

and I prefere fixing the thing, that we do json.dumps both in log() and qmp_log() before this patch.

Also: so, we move all qmp_log callers to new logic (through sorting by hand with ordered_kwargs), and it works? Then, maybe, move all log callers to new logic, and get rid of json.dumps at all, to have one path instead of two?

Quoted 3 lines

tests/qemu-iotests/iotests.py +0 -0

          result = self.qmp(cmd, **kwargs)
          log(json.dumps(result, sort_keys=True), filters)

Quoted 8 lines

tests/qemu-iotests/iotests.py def qemu_img(*args): · line 82

Quoted 4 lines

tests/qemu-iotests/iotests.py +4 -0

+def ordered_kwargs(kwargs):
+    # kwargs prior to 3.6 are not ordered, so:
+    od = OrderedDict()
+    for k in sorted(kwargs.keys()):

you can use for k, v in sorted(kwargs.items()):
and use then v instead of kwargs[k]

I don't need to sort the tuples, though, Only the keys -- which are not duplicated. Is it really worth changing? ...

Quoted 3 lines

tests/qemu-iotests/iotests.py def qemu_img(*args): · line 84

Quoted 3 lines

tests/qemu-iotests/iotests.py +2 -0

+        if isinstance(kwargs[k], dict):
+            od[k] = ordered_kwargs(kwargs[k])

The motivation is that log() will log whatever you give it and apply filters that work on that kind of object. Some callers need to filter rich QMP objects and some callers need to filter text -- this is the way log() behaves right now and I simply didn't change it.

What qmp_log currently does is convert both the outgoing and incoming QMP objects to text, and then filters them as text. However, only precisely one test (206) uses this functionality.

So... I need some way for test 206 to do what it does. One way is to make a rich QMP filter, which is what I do later in this series under the pretense that other tests will likely want to filter QMP output, too.

The other approach involves teaching qmp_log to accept two kinds of filters (qmp and text) and then passing both along to log(), which will then filter the object before pretty-printing and then apply the text filters after pretty-printing, and then logging the result.

As it stands now, though, log() just applies all filters to the first argument without the caller needing to disambiguate. If I teach log() to use two types of filters, I need to go back through all of the iotests and teach all callers to specify e.g. qfilters= or tfilters=.

I opted for an approach that let me just edit test 206 instead -- and one that added a recursive QMP filter that might be useful in the future for other purposes.

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

We can accomplish this by sorting **kwargs into an OrderedDict, which does preserve addition order.

---
  tests/qemu-iotests/iotests.py | 21 +++++++++++++++++----
  1 file changed, 17 insertions(+), 4 deletions(-)

Quoted 3 lines · John Snow

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

Naive question - why do we need the sorting? Is it so that the output is deterministic?  Surely it can't be because the ordering otherwise makes a difference to execution.

Here's my review from a non-Python export viewpoint:

Quoted 7 lines

We can accomplish this by sorting **kwargs into an OrderedDict, which does preserve addition order.
---
  tests/qemu-iotests/iotests.py | 21 +++++++++++++++++----

  1 file changed, 17 insertions(+), 4 deletions(-)

Quoted 8 lines

(quoted diff) +0 -0

@@ -448,8 +460,9 @@ class VM(qtest.QEMUQtestMachine):

          return result
        def qmp_log(self, cmd, filters=[filter_testfiles], **kwargs):
-        logmsg = '{"execute": "%s", "arguments": %s}' % \
-            (cmd, json.dumps(kwargs, sort_keys=True))
+        full_cmd = OrderedDict({"execute": cmd,
+                                "arguments": ordered_kwargs(kwargs)}) +        logmsg = json.dumps(full_cmd)

Vladimir knows Python better than me, but once you fix this OrderedDict construction up to actually work, the patch looks reasonable to me.

Quoted 9 lines · Eric Blake

Quoted 3 lines · John Snow

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

Naive question - why do we need the sorting? Is it so that the output is deterministic?  Surely it can't be because the ordering otherwise makes a difference to execution.

Yeah, it's because dicts are unordered and prior to 3.6 they may shuffle around arbitrarily based on internal hashes.

kwargs in particular are unordered- the order we send over the wire may or may not reflect the order the test author wrote in their iotest.

Therefore, it's a way to get consistent ordering.

Now, we CAN just rely on sort_keys=True to be done with it, however, this puts arguments before execute, and it's less nice to read -- and I'd have to change a LOT of test output.

This way keeps the order you expect to see while maintaining a strict order for the arguments. I think that's the nicest compromise until we can stipulate 3.6+ in the year 2034 where kwargs *are* strictly ordered.

Quoted 13 lines · John Snow

Quoted 9 lines · Eric Blake

Quoted 3 lines · John Snow

Python before 3.6 does not sort kwargs by default.
If we want to print out pretty-printed QMP objects while preserving the "exec" > "arguments" ordering, we need a custom sort.

Naive question - why do we need the sorting? Is it so that the output is deterministic?  Surely it can't be because the ordering otherwise makes a difference to execution.

Quoted 5 lines

Yeah, it's because dicts are unordered and prior to 3.6 they may shuffle around arbitrarily based on internal hashes.

kwargs in particular are unordered- the order we send over the wire may or may not reflect the order the test author wrote in their iotest.

Which shouldn't matter to what QMP executes, but MIGHT matter in getting reproducible log output.

Quoted 6 lines

Therefore, it's a way to get consistent ordering.

Now, we CAN just rely on sort_keys=True to be done with it, however, this puts arguments before execute, and it's less nice to read -- and I'd have to change a LOT of test output.

Okay, I'm finally seeing it; the existing code has:

    def qmp_log(self, cmd, filters=[filter_testfiles], **kwargs):
        logmsg = '{"execute": "%s", "arguments": %s}' % \
            (cmd, json.dumps(kwargs, sort_keys=True))

where our log is outputting a message that resembles a dict where "execute": is the first key, and the user's input dict is then sorted (the top-most output of {} is unsorted, but the nested ones are sorted, and possibly in a different order than the user typed them, but at least deterministic). But when you change to the user passing a full QMP command (rather than just a dict for the arguments of the QMP command), using sort_keys=True will sort everything _including_ putting "arguments" before "execute" (which is deterministic but changes log output); while using sort_keys=False will not affect output in newer python where kwargs remains ordered, but risks nondeterministic output on older python.

Quoted 4 lines

This way keeps the order you expect to see while maintaining a strict order for the arguments. I think that's the nicest compromise until we can stipulate 3.6+ in the year 2034 where kwargs *are* strictly ordered.

But kwargs strict ordering is only at the top-level, not recursive, right? That is, even if you can rely on:

foo(b=1, a=2)

providing kwargs where 'b' always outputs before 'a', I don't see how that would help:

foo(b={'d':3, 'c':4})

not reorder the keys within 'b' without your recursive ordering.

Only test 206 uses it, so remove it.

log() treats filters as if they can always filter its primary argument. qmp_log treats filters as if they're always text.

Change qmp_log to treat filters as if they're always qmp object filters, then change the logging call to rely on log()'s ability to serialize QMP objects, so we're not duplicating that effort.

Because kwargs have been sorted already, the order is preserved.

Edit the only caller who uses filters on qmp_log to use a qmp version, also added in this patch.

---
  tests/qemu-iotests/206        |  4 ++--
  tests/qemu-iotests/iotests.py | 24 +++++++++++++++++++++---
  2 files changed, 23 insertions(+), 5 deletions(-)

tests/qemu-iotests/206 +2 -2

index e92550fa59..5bb738bf23 100755
@@ -27,7 +27,7 @@ iotests.verify_image_format(supported_fmts=['qcow2'])
 
  def blockdev_create(vm, options):
      result = vm.qmp_log('blockdev-create',
-                        filters=[iotests.filter_testfiles],
+                        filters=[iotests.filter_qmp_testfiles],
                          job_id='job0', options=options)
 
      if 'return' in result:

@@ -55,7 +55,7 @@ with iotests.FilePath('t.qcow2') as disk_path, \
                            'size': 0 })
 
      vm.qmp_log('blockdev-add',
-               filters=[iotests.filter_testfiles],
+               filters=[iotests.filter_qmp_testfiles],
                 driver='file', filename=disk_path,
                 node_name='imgfile')
 

tests/qemu-iotests/iotests.py +21 -3

index 55fb60e039..812302538d 100644
@@ -246,10 +246,29 @@ def filter_qmp_event(event):
          event['timestamp']['microseconds'] = 'USECS'
      return event
 
+def filter_qmp(qmsg, filter_fn):
+    '''Given a string filter, filter a QMP object's values.
+    filter_fn takes a (key, value) pair.'''
+    for key in qmsg:
+        if isinstance(qmsg[key], list):
+            qmsg[key] = [filter_qmp(atom, filter_fn) for atom in qmsg[key]]
+        elif isinstance(qmsg[key], dict):
+            qmsg[key] = filter_qmp(qmsg[key], filter_fn)
+        else:
+            qmsg[key] = filter_fn(key, qmsg[key])
+    return qmsg
+
  def filter_testfiles(msg):
      prefix = os.path.join(test_dir, "%s-" % (os.getpid()))
      return msg.replace(prefix, 'TEST_DIR/PID-')
 
+def filter_qmp_testfiles(qmsg):
+    def _filter(key, value):
+        if key == 'filename' or key == 'backing-file':
+            return filter_testfiles(value)
+        return value
+    return filter_qmp(qmsg, _filter)
+
  def filter_generated_node_ids(msg):
      return re.sub("#block[0-9]+", "NODE_NAME", msg)
 

@@ -462,10 +481,9 @@ class VM(qtest.QEMUQtestMachine):
      def qmp_log(self, cmd, filters=[], **kwargs):
          full_cmd = OrderedDict({"execute": cmd,
                                  "arguments": ordered_kwargs(kwargs)})
-        logmsg = json.dumps(full_cmd)
-        log(logmsg, filters)
+        log(full_cmd, filters)
          result = self.qmp(cmd, **kwargs)
-        log(json.dumps(result, sort_keys=True), filters)
+        log(result, filters)
          return result
 
      def run_job(self, job, auto_finalize=True, auto_dismiss=False):

Quoted 6 lines · John Snow

log() treats filters as if they can always filter its primary argument. qmp_log treats filters as if they're always text.

Change qmp_log to treat filters as if they're always qmp object filters, then change the logging call to rely on log()'s ability to serialize QMP objects, so we're not duplicating that effort.

As I understand, there still no use for qmp-object based filters (even after the series), do we really need them? I'm afraid it's premature complication.

Why not to keep all filters text based? If we need to filter some concrete fields, not the whole thing, I doubt that recursion and defining functions inside functions is a true way for it. Instead in concrete case, like in you test, it's better to select fields that should be in output, and output only them.

Quoted 72 lines

Because kwargs have been sorted already, the order is preserved.

Edit the only caller who uses filters on qmp_log to use a qmp version, also added in this patch.
---
  tests/qemu-iotests/206        |  4 ++-- tests/qemu-iotests/iotests.py | 24 +++++++++++++++++++++---

  2 files changed, 23 insertions(+), 5 deletions(-)

tests/qemu-iotests/206 +0 -0

index e92550fa59..5bb738bf23 100755
@@ -27,7 +27,7 @@ iotests.verify_image_format(supported_fmts=['qcow2'])

  def blockdev_create(vm, options):
      result = vm.qmp_log('blockdev-create',
-                        filters=[iotests.filter_testfiles], +                        filters=[iotests.filter_qmp_testfiles], job_id='job0', options=options) if 'return' in result:

tests/qemu-iotests/206 +1 -1

@@ -55,7 +55,7 @@ with iotests.FilePath('t.qcow2') as disk_path, \
                             'size': 0 })
       vm.qmp_log('blockdev-add',
-               filters=[iotests.filter_testfiles],
+               filters=[iotests.filter_qmp_testfiles],
                  driver='file', filename=disk_path,
                  node_name='imgfile')

tests/qemu-iotests/iotests.py +0 -0

index 55fb60e039..812302538d 100644
@@ -246,10 +246,29 @@ def filter_qmp_event(event):

          event['timestamp']['microseconds'] = 'USECS' return event

tests/qemu-iotests/iotests.py +12 -0

+def filter_qmp(qmsg, filter_fn):
+    '''Given a string filter, filter a QMP object's values.
+    filter_fn takes a (key, value) pair.'''
+    for key in qmsg:
+        if isinstance(qmsg[key], list):
+            qmsg[key] = [filter_qmp(atom, filter_fn) for atom in qmsg[key]]
+        elif isinstance(qmsg[key], dict):
+            qmsg[key] = filter_qmp(qmsg[key], filter_fn)
+        else:
+            qmsg[key] = filter_fn(key, qmsg[key])
+    return qmsg
+

  def filter_testfiles(msg):
      prefix = os.path.join(test_dir, "%s-" % (os.getpid())) return msg.replace(prefix, 'TEST_DIR/PID-')

tests/qemu-iotests/iotests.py +7 -0

+def filter_qmp_testfiles(qmsg):
+    def _filter(key, value):
+        if key == 'filename' or key == 'backing-file':
+            return filter_testfiles(value)
+        return value
+    return filter_qmp(qmsg, _filter)
+

  def filter_generated_node_ids(msg):
      return re.sub("#block[0-9]+", "NODE_NAME", msg)

tests/qemu-iotests/iotests.py +0 -0

@@ -462,10 +481,9 @@ class VM(qtest.QEMUQtestMachine):

      def qmp_log(self, cmd, filters=[], **kwargs):
          full_cmd = OrderedDict({"execute": cmd, "arguments": ordered_kwargs(kwargs)}) -        logmsg = json.dumps(full_cmd)
-        log(logmsg, filters)
+        log(full_cmd, filters)
          result = self.qmp(cmd, **kwargs)
-        log(json.dumps(result, sort_keys=True), filters)
+        log(result, filters)
          return result
      def run_job(self, job, auto_finalize=True, auto_dismiss=False):

Quoted 8 lines · Vladimir Sementsov-Ogievskiy

Quoted 6 lines · John Snow

log() treats filters as if they can always filter its primary argument. qmp_log treats filters as if they're always text.

Change qmp_log to treat filters as if they're always qmp object filters, then change the logging call to rely on log()'s ability to serialize QMP objects, so we're not duplicating that effort.

Quoted 2 lines

As I understand, there still no use for qmp-object based filters (even after the series), do we really need them? I'm afraid it's premature complication.

aha, sorry, missed that you use it in 206.
But still not sure that it worth it. Isn't it better to just remove fields from dict, which are unpredictable, instead of substituting them..

The other idea here: if we want
automatically logged qmp commands (qmp_log(), actually), it should filter unpredictable things from output automatically, just by command, which is the first argument. Caller should not care about it, as it may be derived from command, how to filter it's output. And then, we just need a kind of dict of functions, which do not do something like generic recursion, but specifically prepares common-test-output for the concrete command...

But still not sure that it worth it. Isn't it better to just remove fields from dict, which are unpredictable, instead of substituting them..

Quoted 3 lines · Vladimir Sementsov-Ogievskiy

But still not sure that it worth it. Isn't it better to just remove fields from dict,
which are unpredictable, instead of substituting them..

For getting the test to pass when we have a key:unpredictable value in the dict, you are right that both changing it to key:SUBST or removing key work at producing reproducible output. But when it comes to debugging test failure, having key:SUBST in the logs gives you a hint at what else to look at, whereas omitting key altogether may make the reason for the failure completely disappear from the logs.

Thus, I would argue that even though it is more complex to write a filter that can recursively substitute, the resulting output is easier to debug if a test starts failing - and that if the work in doing the more complex filtering has already been submitted and is not too much of a burden to maintain, then we might as well use it rather than going with the simpler case of just eliding the problematic keys or using just textual filtering.

However, I'm not in a good position to argue whether there is a reasonable maintenance burden with the patches in this series, vs. what it would take to rewrite 206 to do just textual filtering instead of QMP dict substitution filtering.

Quoted 21 lines · Eric Blake

Quoted 3 lines · Vladimir Sementsov-Ogievskiy

But still not sure that it worth it. Isn't it better to just remove fields from dict,
which are unpredictable, instead of substituting them..

For getting the test to pass when we have a key:unpredictable value in the dict, you are right that both changing it to key:SUBST or removing key work at producing reproducible output. But when it comes to debugging test failure, having key:SUBST in the logs gives you a hint at what else to look at, whereas omitting key altogether may make the reason for the failure completely disappear from the logs.

Thus, I would argue that even though it is more complex to write a filter that can recursively substitute, the resulting output is easier to debug if a test starts failing - and that if the work in doing the more complex filtering has already been submitted and is not too much of a burden to maintain, then we might as well use it rather than going with the simpler case of just eliding the problematic keys or using just textual filtering.

Quoted 5 lines

However, I'm not in a good position to argue whether there is a reasonable maintenance burden with the patches in this series, vs. what it would take to rewrite 206 to do just textual filtering instead of QMP dict substitution filtering.

My reasoning is this:

(1) It would be good if QMP filters behaved similarly to their plaintext companions, as this is the least surprising behavior, and

(2) It would be best to log the keys provided in responses in case we wish to test for their presence (and that their values match something we were able to predict via a pattern), and

(3) Not arbitrarily changing the nature of the response invisibly in a way that obscures it from log files to aid debugging, like you say.

I offer some ideas for how to add text filtering for QMP objects in iotests in some of my replies, but it's not going to happen in 2018, IMO. I want pretty-printing of QMP commands more than I want text filtering of serialized QMP objects.

Quoted 6 lines · John Snow

log() treats filters as if they can always filter its primary argument. qmp_log treats filters as if they're always text.

Change qmp_log to treat filters as if they're always qmp object filters, then change the logging call to rely on log()'s ability to serialize QMP objects, so we're not duplicating that effort.

As I understand, there still no use for qmp-object based filters (even after the series), do we really need them? I'm afraid it's premature complication.

Why not to keep all filters text based? If we need to filter some concrete fields, not the whole thing, I doubt that recursion and defining functions inside functions is a true way for it. Instead in concrete case, like in you test, it's better to select fields that should be in output, and output only them.

Quoted 80 lines

Because kwargs have been sorted already, the order is preserved.

Edit the only caller who uses filters on qmp_log to use a qmp version, also added in this patch.

---
  tests/qemu-iotests/206        |  4 ++--
  tests/qemu-iotests/iotests.py | 24 +++++++++++++++++++++---
  2 files changed, 23 insertions(+), 5 deletions(-)

tests/qemu-iotests/206 +2 -2

index e92550fa59..5bb738bf23 100755
@@ -27,7 +27,7 @@ iotests.verify_image_format(supported_fmts=['qcow2'])
 
  def blockdev_create(vm, options):
      result = vm.qmp_log('blockdev-create',
-                        filters=[iotests.filter_testfiles],
+                        filters=[iotests.filter_qmp_testfiles],
                          job_id='job0', options=options)
 
      if 'return' in result:

@@ -55,7 +55,7 @@ with iotests.FilePath('t.qcow2') as disk_path, \
                            'size': 0 })
 
      vm.qmp_log('blockdev-add',
-               filters=[iotests.filter_testfiles],
+               filters=[iotests.filter_qmp_testfiles],
                 driver='file', filename=disk_path,
                 node_name='imgfile')
 

tests/qemu-iotests/iotests.py +21 -3

index 55fb60e039..812302538d 100644
@@ -246,10 +246,29 @@ def filter_qmp_event(event):
          event['timestamp']['microseconds'] = 'USECS'
      return event
 
+def filter_qmp(qmsg, filter_fn):
+    '''Given a string filter, filter a QMP object's values.
+    filter_fn takes a (key, value) pair.'''
+    for key in qmsg:
+        if isinstance(qmsg[key], list):
+            qmsg[key] = [filter_qmp(atom, filter_fn) for atom in qmsg[key]]
+        elif isinstance(qmsg[key], dict):
+            qmsg[key] = filter_qmp(qmsg[key], filter_fn)
+        else:
+            qmsg[key] = filter_fn(key, qmsg[key])
+    return qmsg
+
  def filter_testfiles(msg):
      prefix = os.path.join(test_dir, "%s-" % (os.getpid()))
      return msg.replace(prefix, 'TEST_DIR/PID-')
 
+def filter_qmp_testfiles(qmsg):
+    def _filter(key, value):
+        if key == 'filename' or key == 'backing-file':
+            return filter_testfiles(value)
+        return value
+    return filter_qmp(qmsg, _filter)
+
  def filter_generated_node_ids(msg):
      return re.sub("#block[0-9]+", "NODE_NAME", msg)
 

@@ -462,10 +481,9 @@ class VM(qtest.QEMUQtestMachine):
      def qmp_log(self, cmd, filters=[], **kwargs):
          full_cmd = OrderedDict({"execute": cmd,
                                  "arguments": ordered_kwargs(kwargs)})
-        logmsg = json.dumps(full_cmd)
-        log(logmsg, filters)
+        log(full_cmd, filters)
          result = self.qmp(cmd, **kwargs)
-        log(json.dumps(result, sort_keys=True), filters)
+        log(result, filters)
          return result
 
      def run_job(self, job, auto_finalize=True, auto_dismiss=False):

Quoted 11 lines · Vladimir Sementsov-Ogievskiy

Quoted 6 lines · John Snow

log() treats filters as if they can always filter its primary argument. qmp_log treats filters as if they're always text.

Change qmp_log to treat filters as if they're always qmp object filters, then change the logging call to rely on log()'s ability to serialize QMP objects, so we're not duplicating that effort.

As I understand, there still no use for qmp-object based filters (even after the series), do we really need them? I'm afraid it's premature complication.

There are callers of log() that use qmp filters. Those callers can now migrate over to qmp_log to get both the call and response.

There ARE users of QMP filters.

Look at git grep 'log(vm' for callers that are passing rich QMP objects. The ones that pass filters are usually passing filter_qmp_event.

Now, if we choose, we can move them over to using qmp_log and amend the logging output to get both the outgoing and returning message.

-- hmm, maybe, if you want, and I am NOT suggesting I will do this before the holiday break (and therefore not in this series) -- what we can do is this:

log(txt, filters=[]) -- Takes text and text filters only.

log_qmp(obj, tfilters=[], qfilters=[]) -- Logs a QMP object, takes QMP filters for pre-filtering and tfilters for post-filtering. Contains the json.dumps call. Simply passes tfilters down to log().

vm.qmp(log=1, tfilters=[], qfilters=[], ...) -- Perform the actual QMP call and response, logging the outgoing and incoming objects via log_qmp.

I can use this patchset as a starting point to do that. It will involve amending a lot of existing tests and test outputs, so I won't do this unless there appears to be some support for that API in advance.

Quoted 88 lines

Why not to keep all filters text based? If we need to filter some concrete fields, not the whole thing, I doubt that recursion and defining functions inside functions is a true way for it. Instead in concrete case, like in you test, it's better to select fields that should be in output, and output only them.

Quoted 80 lines

Because kwargs have been sorted already, the order is preserved.

Edit the only caller who uses filters on qmp_log to use a qmp version, also added in this patch.

---
   tests/qemu-iotests/206        |  4 ++--
   tests/qemu-iotests/iotests.py | 24 +++++++++++++++++++++---
   2 files changed, 23 insertions(+), 5 deletions(-)

tests/qemu-iotests/206 +2 -2

index e92550fa59..5bb738bf23 100755
@@ -27,7 +27,7 @@ iotests.verify_image_format(supported_fmts=['qcow2'])
 
   def blockdev_create(vm, options):
       result = vm.qmp_log('blockdev-create',
-                        filters=[iotests.filter_testfiles],
+                        filters=[iotests.filter_qmp_testfiles],
                           job_id='job0', options=options)
 
       if 'return' in result:

@@ -55,7 +55,7 @@ with iotests.FilePath('t.qcow2') as disk_path, \
                             'size': 0 })
 
       vm.qmp_log('blockdev-add',
-               filters=[iotests.filter_testfiles],
+               filters=[iotests.filter_qmp_testfiles],
                  driver='file', filename=disk_path,
                  node_name='imgfile')
 

tests/qemu-iotests/iotests.py +21 -3

index 55fb60e039..812302538d 100644
@@ -246,10 +246,29 @@ def filter_qmp_event(event):
           event['timestamp']['microseconds'] = 'USECS'
       return event
 
+def filter_qmp(qmsg, filter_fn):
+    '''Given a string filter, filter a QMP object's values.
+    filter_fn takes a (key, value) pair.'''
+    for key in qmsg:
+        if isinstance(qmsg[key], list):
+            qmsg[key] = [filter_qmp(atom, filter_fn) for atom in qmsg[key]]
+        elif isinstance(qmsg[key], dict):
+            qmsg[key] = filter_qmp(qmsg[key], filter_fn)
+        else:
+            qmsg[key] = filter_fn(key, qmsg[key])
+    return qmsg
+
   def filter_testfiles(msg):
       prefix = os.path.join(test_dir, "%s-" % (os.getpid()))
       return msg.replace(prefix, 'TEST_DIR/PID-')
 
+def filter_qmp_testfiles(qmsg):
+    def _filter(key, value):
+        if key == 'filename' or key == 'backing-file':
+            return filter_testfiles(value)
+        return value
+    return filter_qmp(qmsg, _filter)
+
   def filter_generated_node_ids(msg):
       return re.sub("#block[0-9]+", "NODE_NAME", msg)
 

@@ -462,10 +481,9 @@ class VM(qtest.QEMUQtestMachine):
       def qmp_log(self, cmd, filters=[], **kwargs):
           full_cmd = OrderedDict({"execute": cmd,
                                   "arguments": ordered_kwargs(kwargs)})
-        logmsg = json.dumps(full_cmd)
-        log(logmsg, filters)
+        log(full_cmd, filters)
           result = self.qmp(cmd, **kwargs)
-        log(json.dumps(result, sort_keys=True), filters)
+        log(result, filters)
           return result
 
       def run_job(self, job, auto_finalize=True, auto_dismiss=False):

New interface, new smoke test.

---
  tests/qemu-iotests/236     | 131 ++++++++++++++++++++++++
  tests/qemu-iotests/236.out | 198 +++++++++++++++++++++++++++++++++++++
  tests/qemu-iotests/group   |   1 +
  3 files changed, 330 insertions(+)

create mode 100755 tests/qemu-iotests/236
create mode 100644 tests/qemu-iotests/236.out

tests/qemu-iotests/236 new file +5 -0

+
+    log('')
+    log('--- Disabling B & Adding C ---\n')
+    vm.qmp_log("transaction", indent=2, actions=[
+        { "type": "block-dirty-bitmap-disable",

Quoted 10 lines · John Snow

New interface, new smoke test.
---
  tests/qemu-iotests/236     | 131 ++++++++++++++++++++++++ tests/qemu-iotests/236.out | 198 +++++++++++++++++++++++++++++++++++++ tests/qemu-iotests/group   |   1 +

  3 files changed, 330 insertions(+)

  create mode 100755 tests/qemu-iotests/236
  create mode 100644 tests/qemu-iotests/236.out

Quoted 15 lines

+
+    log('')
+    log('--- Disabling B & Adding C ---\n')
+    vm.qmp_log("transaction", indent=2, actions=[ +        { "type": "block-dirty-bitmap-disable",
+          "data": { "node": "drive0", "name": "bitmapB" }}, +        { "type": "block-dirty-bitmap-add",
+          "data": { "node": "drive0", "name": "bitmapC", +                    "granularity": granularity }}, +        # Purely extraneous, but test that it works:
+        { "type": "block-dirty-bitmap-disable",
+          "data": { "node": "drive0", "name": "bitmapC" }}, +        { "type": "block-dirty-bitmap-enable",
+          "data": { "node": "drive0", "name": "bitmapC" }}, +    ])

One other possible addition just before this point:

qmp_log("transaction", indent=2, actions=[
        { "type": "block-dirty-bitmap-disable", "data": { "node": "drive0", "name": "bitmapB" }}, { "type": "block-dirty-bitmap-add", "data": { "node": "drive0", "name": "bitmapC", "granularity": granularity }}, { "type": "block-dirty-bitmap-remove", "data": { "node": "drive0", "name": "bitmapA" }}, { "type": "abort", "data": {}}
  ])

to check that we properly undo things on an aborted transaction (B should still be enabled, C should not exist, and A should not be damaged).

Quoted 7 lines

+    # A and D should be equivalent>> +    # Some formats round the size of the disk, so don't print the checksums.
+    check_a = vm.qmp('x-debug-block-dirty-bitmap-sha256',
+                     node="drive0", name="bitmapA")['return']['sha256']
+    check_b = vm.qmp('x-debug-block-dirty-bitmap-sha256',
+                     node="drive0", name="bitmapD")['return']['sha256']
+    assert(check_a == check_b)

Image agnostic also means that you avoid an 32- vs. 64-bit platform discrepancies (we've had issues in the past where the sum is different for some image sizes, because the bitmap is always in terms of 'long's, but there is one less 'long' in a 32-bit bitmap for the disk size). Makes sense.

Also, I don't see any tests of block-dirty-bitmap-remove - this would be a good point in the test to insert a final cleanup.

Quoted 8 lines

+++ b/tests/qemu-iotests/group

(quoted diff) +0 -0

@@ -233,3 +233,4 @@

  233 auto quick
  234 auto quick migration
  235 auto quick
+236 auto quick
\ No newline at end of file

Umm - what's that still doing here?