diff mbox series

[v4,3/5] iotests: change qmp_log filters to expect QMP objects only

Message ID 20181219015230.18652-4-jsnow@redhat.com (mailing list archive)
State New, archived
Headers show
Series bitmaps: remove x- prefix from QMP api Part2 | expand

Commit Message

John Snow Dec. 19, 2018, 1:52 a.m. UTC
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(-)

Comments

Vladimir Sementsov-Ogievskiy Dec. 19, 2018, 11:07 a.m. UTC | #1
19.12.2018 4:52, John Snow wrote:
> 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.

> 
> 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(-)
> 
> diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
> index e92550fa59..5bb738bf23 100755
> --- a/tests/qemu-iotests/206
> +++ b/tests/qemu-iotests/206
> @@ -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')
>   
> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
> index 55fb60e039..812302538d 100644
> --- a/tests/qemu-iotests/iotests.py
> +++ b/tests/qemu-iotests/iotests.py
> @@ -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):
>
Vladimir Sementsov-Ogievskiy Dec. 19, 2018, 11:27 a.m. UTC | #2
19.12.2018 14:07, Vladimir Sementsov-Ogievskiy wrote:
> 19.12.2018 4:52, John Snow wrote:
>> 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.

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

> 
> 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.
> 
>>
>> 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(-)
>>
>> diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
>> index e92550fa59..5bb738bf23 100755
>> --- a/tests/qemu-iotests/206
>> +++ b/tests/qemu-iotests/206
>> @@ -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')
>> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
>> index 55fb60e039..812302538d 100644
>> --- a/tests/qemu-iotests/iotests.py
>> +++ b/tests/qemu-iotests/iotests.py
>> @@ -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):
>>
> 
>
John Snow Dec. 19, 2018, 5:29 p.m. UTC | #3
On 12/19/18 6:27 AM, Vladimir Sementsov-Ogievskiy wrote:
> 19.12.2018 14:07, Vladimir Sementsov-Ogievskiy wrote:
>> 19.12.2018 4:52, John Snow wrote:
>>> 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.
> 
> 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..
> 

I'd like to keep the QMP output a prettified version of the plaintext
output, and not have it omit things. You can make the case for changing
that behavior in a separate patch.

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

Feel free to enhance the test suite later to understand all the types of
commands and replies and scrub them automatically. For now, specifying
the filters matches behavior in much of the rest of the test suite and I
am not motivated to fix it.
John Snow Dec. 19, 2018, 6:35 p.m. UTC | #4
On 12/19/18 6:07 AM, Vladimir Sementsov-Ogievskiy wrote:
> 19.12.2018 4:52, John Snow wrote:
>> 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.

> 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.
> 
>>
>> 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(-)
>>
>> diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
>> index e92550fa59..5bb738bf23 100755
>> --- a/tests/qemu-iotests/206
>> +++ b/tests/qemu-iotests/206
>> @@ -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')
>>   
>> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
>> index 55fb60e039..812302538d 100644
>> --- a/tests/qemu-iotests/iotests.py
>> +++ b/tests/qemu-iotests/iotests.py
>> @@ -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):
>>
> 
>
Eric Blake Dec. 19, 2018, 7:01 p.m. UTC | #5
On 12/19/18 5:27 AM, Vladimir Sementsov-Ogievskiy wrote:

> 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.
John Snow Dec. 19, 2018, 7:52 p.m. UTC | #6
On 12/19/18 2:01 PM, Eric Blake wrote:
> On 12/19/18 5:27 AM, Vladimir Sementsov-Ogievskiy wrote:
> 
>> 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.
> 

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.
Vladimir Sementsov-Ogievskiy Dec. 20, 2018, 9:11 a.m. UTC | #7
19.12.2018 21:35, John Snow wrote:
> 
> 
> On 12/19/18 6:07 AM, Vladimir Sementsov-Ogievskiy wrote:
>> 19.12.2018 4:52, John Snow wrote:
>>> 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.

oops, I'm totally ashamed)

Interesting, about least surprising behavior, for me it's a surprise. I thought,
that assumed behavior is filtering final text..

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

Ohm, stop listening me, I had false assumptions. Ok, at this point, I'll move to
reviewing your next series, hope it didn't complicated due to my false criticism.

> 
>> 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.
>>
>>>
>>> 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(-)
>>>
>>> diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
>>> index e92550fa59..5bb738bf23 100755
>>> --- a/tests/qemu-iotests/206
>>> +++ b/tests/qemu-iotests/206
>>> @@ -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')
>>>    
>>> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
>>> index 55fb60e039..812302538d 100644
>>> --- a/tests/qemu-iotests/iotests.py
>>> +++ b/tests/qemu-iotests/iotests.py
>>> @@ -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):
>>>
>>
>>
>
Vladimir Sementsov-Ogievskiy Dec. 20, 2018, 9:33 a.m. UTC | #8
19.12.2018 22:52, John Snow wrote:
> 
> 
> On 12/19/18 2:01 PM, Eric Blake wrote:
>> On 12/19/18 5:27 AM, Vladimir Sementsov-Ogievskiy wrote:
>>
>>> 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.
>>
> 
> 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.

Yes, at least (2-3) makes sense for me.

> 
> 
> 
> 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.
>
diff mbox series

Patch

diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
index e92550fa59..5bb738bf23 100755
--- a/tests/qemu-iotests/206
+++ b/tests/qemu-iotests/206
@@ -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')
 
diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 55fb60e039..812302538d 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -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):