When iotest 223 was first written, it didn't matter if we waited for
the qemu process to clean up. But with the introduction of a later
qemu-nbd process trying to reuse the same file, there is a race where
even though the asynchronous qemu process has responded to "quit", it
has not yet had time to unlock the file and exit, resulting in:

-[{ "start": 0, "length": 65536, "depth": 0, "zero": false, "data": false},
-{ "start": 65536, "length": 2031616, "depth": 0, "zero": false, "data": true},
-{ "start": 2097152, "length": 2097152, "depth": 0, "zero": false, "data": false}]
+qemu-nbd: Failed to blk_new_open 'tests/qemu-iotests/scratch/t.qcow2': Failed to get shared "write" lock
+Is another process using the image [tests/qemu-iotests/scratch/t.qcow2]?
+qemu-img: Could not open 'driver=nbd,server.type=unix,server.path=tests/qemu-iotests/scratch/qemu-nbd.sock,x-dirty-bitmap=qemu:dirty-bitmap:b': Failed to connect socket tests/qemu-iotests/scratch/qemu-nbd.sock: Connection refused
+./common.nbd: line 33: kill: (11122) - No such process

Fixes: ddd09448
Reported-by: Alberto Garcia <berto@igalia.com>
Signed-off-by: Eric Blake <eblake@redhat.com>
---
 tests/qemu-iotests/223     | 1 +
 tests/qemu-iotests/223.out | 1 +
 2 files changed, 2 insertions(+)

diff --git a/tests/qemu-iotests/223 b/tests/qemu-iotests/223
index f120a016460..c0a4f9c14b7 100755
--- a/tests/qemu-iotests/223
+++ b/tests/qemu-iotests/223
@@ -179,6 +179,7 @@ _send_qemu_cmd $QEMU_HANDLE '{"execute":"nbd-server-remove",
 _send_qemu_cmd $QEMU_HANDLE '{"execute":"nbd-server-stop"}' "return"
 _send_qemu_cmd $QEMU_HANDLE '{"execute":"nbd-server-stop"}' "error" # Again
 _send_qemu_cmd $QEMU_HANDLE '{"execute":"quit"}' "return"
+wait=yes _cleanup_qemu

 echo
 echo "=== Use qemu-nbd as server ==="
diff --git a/tests/qemu-iotests/223.out b/tests/qemu-iotests/223.out
index 6476b77ba20..95c40a17ad7 100644
--- a/tests/qemu-iotests/223.out
+++ b/tests/qemu-iotests/223.out
@@ -89,6 +89,7 @@ read 2097152/2097152 bytes at offset 2097152
 {"return": {}}
 {"error": {"class": "GenericError", "desc": "NBD server not running"}}
 {"return": {}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}

 === Use qemu-nbd as server ===

-- 
2.20.1

Am 05.03.2019 um 19:29 hat Eric Blake geschrieben:
> When iotest 223 was first written, it didn't matter if we waited for
> the qemu process to clean up. But with the introduction of a later
> qemu-nbd process trying to reuse the same file, there is a race where
> even though the asynchronous qemu process has responded to "quit", it
> has not yet had time to unlock the file and exit, resulting in:
> 
> -[{ "start": 0, "length": 65536, "depth": 0, "zero": false, "data": false},
> -{ "start": 65536, "length": 2031616, "depth": 0, "zero": false, "data": true},
> -{ "start": 2097152, "length": 2097152, "depth": 0, "zero": false, "data": false}]
> +qemu-nbd: Failed to blk_new_open 'tests/qemu-iotests/scratch/t.qcow2': Failed to get shared "write" lock
> +Is another process using the image [tests/qemu-iotests/scratch/t.qcow2]?
> +qemu-img: Could not open 'driver=nbd,server.type=unix,server.path=tests/qemu-iotests/scratch/qemu-nbd.sock,x-dirty-bitmap=qemu:dirty-bitmap:b': Failed to connect socket tests/qemu-iotests/scratch/qemu-nbd.sock: Connection refused
> +./common.nbd: line 33: kill: (11122) - No such process
> 
> Fixes: ddd09448
> Reported-by: Alberto Garcia <berto@igalia.com>
> Signed-off-by: Eric Blake <eblake@redhat.com>

Makes sense to me. Berto, can you test it?

Kevin

On Tue 05 Mar 2019 07:29:08 PM CET, Eric Blake wrote:
> When iotest 223 was first written, it didn't matter if we waited for
> the qemu process to clean up. But with the introduction of a later
> qemu-nbd process trying to reuse the same file, there is a race where
> even though the asynchronous qemu process has responded to "quit", it
> has not yet had time to unlock the file and exit, resulting in:
>
> -[{ "start": 0, "length": 65536, "depth": 0, "zero": false, "data": false},
> -{ "start": 65536, "length": 2031616, "depth": 0, "zero": false, "data": true},
> -{ "start": 2097152, "length": 2097152, "depth": 0, "zero": false, "data": false}]
> +qemu-nbd: Failed to blk_new_open 'tests/qemu-iotests/scratch/t.qcow2': Failed to get shared "write" lock
> +Is another process using the image [tests/qemu-iotests/scratch/t.qcow2]?
> +qemu-img: Could not open 'driver=nbd,server.type=unix,server.path=tests/qemu-iotests/scratch/qemu-nbd.sock,x-dirty-bitmap=qemu:dirty-bitmap:b': Failed to connect socket tests/qemu-iotests/scratch/qemu-nbd.sock: Connection refused
> +./common.nbd: line 33: kill: (11122) - No such process
>
> Fixes: ddd09448
> Reported-by: Alberto Garcia <berto@igalia.com>
> Signed-off-by: Eric Blake <eblake@redhat.com>

Tested-by: Alberto Garcia <berto@igalia.com>

Berto

On 3/6/19 7:03 AM, Alberto Garcia wrote:
> On Tue 05 Mar 2019 07:29:08 PM CET, Eric Blake wrote:
>> When iotest 223 was first written, it didn't matter if we waited for
>> the qemu process to clean up. But with the introduction of a later
>> qemu-nbd process trying to reuse the same file, there is a race where
>> even though the asynchronous qemu process has responded to "quit", it
>> has not yet had time to unlock the file and exit, resulting in:
>>
>> -[{ "start": 0, "length": 65536, "depth": 0, "zero": false, "data": false},
>> -{ "start": 65536, "length": 2031616, "depth": 0, "zero": false, "data": true},
>> -{ "start": 2097152, "length": 2097152, "depth": 0, "zero": false, "data": false}]
>> +qemu-nbd: Failed to blk_new_open 'tests/qemu-iotests/scratch/t.qcow2': Failed to get shared "write" lock
>> +Is another process using the image [tests/qemu-iotests/scratch/t.qcow2]?
>> +qemu-img: Could not open 'driver=nbd,server.type=unix,server.path=tests/qemu-iotests/scratch/qemu-nbd.sock,x-dirty-bitmap=qemu:dirty-bitmap:b': Failed to connect socket tests/qemu-iotests/scratch/qemu-nbd.sock: Connection refused
>> +./common.nbd: line 33: kill: (11122) - No such process
>>
>> Fixes: ddd09448
>> Reported-by: Alberto Garcia <berto@igalia.com>
>> Signed-off-by: Eric Blake <eblake@redhat.com>
> 
> Tested-by: Alberto Garcia <berto@igalia.com>

Thanks; will queue through my NBD tree this week.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Am 06.03.2019 um 14:04 hat Eric Blake geschrieben:
> On 3/6/19 7:03 AM, Alberto Garcia wrote:
> > On Tue 05 Mar 2019 07:29:08 PM CET, Eric Blake wrote:
> >> When iotest 223 was first written, it didn't matter if we waited for
> >> the qemu process to clean up. But with the introduction of a later
> >> qemu-nbd process trying to reuse the same file, there is a race where
> >> even though the asynchronous qemu process has responded to "quit", it
> >> has not yet had time to unlock the file and exit, resulting in:
> >>
> >> -[{ "start": 0, "length": 65536, "depth": 0, "zero": false, "data": false},
> >> -{ "start": 65536, "length": 2031616, "depth": 0, "zero": false, "data": true},
> >> -{ "start": 2097152, "length": 2097152, "depth": 0, "zero": false, "data": false}]
> >> +qemu-nbd: Failed to blk_new_open 'tests/qemu-iotests/scratch/t.qcow2': Failed to get shared "write" lock
> >> +Is another process using the image [tests/qemu-iotests/scratch/t.qcow2]?
> >> +qemu-img: Could not open 'driver=nbd,server.type=unix,server.path=tests/qemu-iotests/scratch/qemu-nbd.sock,x-dirty-bitmap=qemu:dirty-bitmap:b': Failed to connect socket tests/qemu-iotests/scratch/qemu-nbd.sock: Connection refused
> >> +./common.nbd: line 33: kill: (11122) - No such process
> >>
> >> Fixes: ddd09448
> >> Reported-by: Alberto Garcia <berto@igalia.com>
> >> Signed-off-by: Eric Blake <eblake@redhat.com>
> > 
> > Tested-by: Alberto Garcia <berto@igalia.com>
> 
> Thanks; will queue through my NBD tree this week.

Ah, if it doesn't go through my tree, you get my explicit:

Reviewed-by: Kevin Wolf <kwolf@redhat.com>