iotests: 077: Filter out 'resume' lines

In the "Overlapping multiple requests" cases, the 3rd reqs (the break
point B) doesn't wait for the 2nd, and once resumed the I/O will just
continue.  This is because the 2nd is already waiting for the 1st, and
in wait_serialising_requests() there is:

    /* If the request is already (indirectly) waiting for us, or
     * will wait for us as soon as it wakes up, then just go on
     * (instead of producing a deadlock in the former case). */
    if (!req->waiting_for) {
        /* actually break */
        ...
    }

Consequently, the following "sleep 100; resume A" command races with the
completion of that request, and sometimes results in an unexpected
order of output:

> @@ -56,9 +56,9 @@
>  wrote XXX/XXX bytes at offset XXX
>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>  blkdebug: Resuming request 'B'
> +blkdebug: Resuming request 'A'
>  wrote XXX/XXX bytes at offset XXX
>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -blkdebug: Resuming request 'A'
>  wrote XXX/XXX bytes at offset XXX
>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>  wrote XXX/XXX bytes at offset XXX

Filter out the "Resuming request" lines to make the output
deterministic.

Reported-by: Patchew <no-reply@patchew.org>
Signed-off-by: Fam Zheng <famz@redhat.com>
---
 tests/qemu-iotests/077     |  3 ++-
 tests/qemu-iotests/077.out | 48 ++++++++++++++++------------------------------
 2 files changed, 18 insertions(+), 33 deletions(-)

On 11/13/2017 09:00 AM, Fam Zheng wrote:
> In the "Overlapping multiple requests" cases, the 3rd reqs (the break
> point B) doesn't wait for the 2nd, and once resumed the I/O will just
> continue.  This is because the 2nd is already waiting for the 1st, and
> in wait_serialising_requests() there is:
> 

> Filter out the "Resuming request" lines to make the output
> deterministic.
> 
> Reported-by: Patchew <no-reply@patchew.org>
> Signed-off-by: Fam Zheng <famz@redhat.com>
> ---
>  tests/qemu-iotests/077     |  3 ++-
>  tests/qemu-iotests/077.out | 48 ++++++++++++++++------------------------------
>  2 files changed, 18 insertions(+), 33 deletions(-)
> 

Reviewed-by: Eric Blake <eblake@redhat.com>

> @@ -4,17 +4,6 @@ Formatting 'TEST_DIR/t.IMGFMT', fmt=IMGFMT size=134217728
>  == Some concurrent requests involving RMW ==
>  wrote XXX/XXX bytes at offset XXX
>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -blkdebug: Resuming request 'A'
> -wrote XXX/XXX bytes at offset XXX
> -XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -wrote XXX/XXX bytes at offset XXX
> -XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -blkdebug: Resuming request 'A'
> -wrote XXX/XXX bytes at offset XXX
> -XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -wrote XXX/XXX bytes at offset XXX
> -XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> -blkdebug: Resuming request 'A'

git diff does a really lousy job of displaying this one, but the end
result looks correct.

On 2017-11-13 16:00, Fam Zheng wrote:
> In the "Overlapping multiple requests" cases, the 3rd reqs (the break
> point B) doesn't wait for the 2nd, and once resumed the I/O will just
> continue.  This is because the 2nd is already waiting for the 1st, and
> in wait_serialising_requests() there is:
> 
>     /* If the request is already (indirectly) waiting for us, or
>      * will wait for us as soon as it wakes up, then just go on
>      * (instead of producing a deadlock in the former case). */
>     if (!req->waiting_for) {
>         /* actually break */
>         ...
>     }
> 
> Consequently, the following "sleep 100; resume A" command races with the
> completion of that request, and sometimes results in an unexpected
> order of output:
> 
>> @@ -56,9 +56,9 @@
>>  wrote XXX/XXX bytes at offset XXX
>>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>>  blkdebug: Resuming request 'B'
>> +blkdebug: Resuming request 'A'
>>  wrote XXX/XXX bytes at offset XXX
>>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> -blkdebug: Resuming request 'A'
>>  wrote XXX/XXX bytes at offset XXX
>>  XXX bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>>  wrote XXX/XXX bytes at offset XXX
> 
> Filter out the "Resuming request" lines to make the output
> deterministic.
> 
> Reported-by: Patchew <no-reply@patchew.org>
> Signed-off-by: Fam Zheng <famz@redhat.com>
> ---
>  tests/qemu-iotests/077     |  3 ++-
>  tests/qemu-iotests/077.out | 48 ++++++++++++++++------------------------------
>  2 files changed, 18 insertions(+), 33 deletions(-)

Thanks, applied to my block tree:

https://github.com/XanClic/qemu/commits/block

Max