Re: block-dirty-bitmap-add fails with "Operation not supported" in 4.2 rc5 (worked in 4.1)

[Nir Soffer]

On Thu, Dec 12, 2019 at 2:04 PM Nir Soffer <address@hidden> wrote:
>
> We have a test for full backup flow testing that we can consume the
> data using our nbd client.
>
> The test[0] is starting a full backup flow, based on Eric examples
> from [1] and [2].

Looking at qemu-iotests/256, I switch the order of the actions in the
transaction
from:

actions = [
    {"type": 'blockdev-backup", "data": ...},
    { "type": "block-dirty-bitmap-add", "data": ...},
]

To:

 actions = [
    { "type": "block-dirty-bitmap-add", "data": ...},
    {"type": 'blockdev-backup", "data": ...},
]

And now the the tests pass with 4.2 rc5.

I'm not sure why it was ok to add the bitmap after starting the block
job before and now it is not, but it makes sense to me.

> This used to work in 4.1, and broke when I upgraded to 4.2 rc5. Here
> is the error I get:
>
> E               test.qmp.CommandFailed: Command {'execute':
> 'transaction', 'arguments': {'actions': [{'type': 'blockdev-backup',
> 'data': {'device': 'ide0-hd0', 'job-id': 'backup-sda', 'sync': 'none',
> 'target': 'backup-sda'}}, {'type': 'block-dirty-bitmap-add', 'data':
> {'name': 'check1', 'node': 'ide0-hd0', 'persistent': True}}]}} failed:
> {'class': 'GenericError', 'desc': "Can't store persistent bitmaps to
> ide0-hd0: Operation not supported"}
>
> I guess 4.2 change the way bitmaps are created?
>
> [0] 
> https://github.com/oVirt/ovirt-imageio/blob/c92835d5b2e0c865ddbd3f43eb5166cc905d7eeb/common/test/backup.py#L26
> [1] https://www.spinics.net/linux/fedora/libvir/msg174457.html
> [2] https://www.spinics.net/linux/fedora/libvir/msg174528.html
>
> See complete flow from the test logs below.
>
> Nir
>
> ---
>
> 13:55:11 DEBUG   (MainThread) [qemu_nbd] Starting qemu-nbd
> ['qemu-nbd', '--format', 'qcow2', '--export-name', b'',
> '--persistent', '--cache=none', '--aio=native', '--discard=unmap',
> '--socket=/var/tmp/imageio-storage/file-512-ext4-mount/file.sock',
> '/var/tmp/imageio-storage/file-512-ext4-mount/file']
> 13:55:11 DEBUG   (MainThread) [test] Waiting for socket
> /var/tmp/imageio-storage/file-512-ext4-mount/file.sock up to 1.000000
> seconds
> 13:55:11 DEBUG   (MainThread) [test] Waited for
> /var/tmp/imageio-storage/file-512-ext4-mount/file.sock 0.020641
> seconds
> 13:55:11 DEBUG   (MainThread) [qemu_nbd] qemu-nbd socket ready
> 13:55:11 INFO    (MainThread) [nbd] Connecting to
> /var/tmp/imageio-storage/file-512-ext4-mount/file.sock ''
> 13:55:11 DEBUG   (MainThread) [nbd] Received server flags: 3
> 13:55:11 DEBUG   (MainThread) [nbd] Sending client flags: 1
> 13:55:11 DEBUG   (MainThread) [nbd] Sending option: 8 data: b''
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=8 type=1 len=0
> 13:55:11 DEBUG   (MainThread) [nbd] Structured reply enabled
> 13:55:11 DEBUG   (MainThread) [nbd] Sending option: 10 data:
> bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x0fbase:allocation')
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=10 type=4 len=19
> 13:55:11 DEBUG   (MainThread) [nbd] Meta context base:allocation is
> available id=0
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=10 type=1 len=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending option: 7 data:
> bytearray(b'\x00\x00\x00\x00\x00\x00')
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=7 type=3 len=14
> 13:55:11 DEBUG   (MainThread) [nbd] Received block size info minimum=1
> preferred=4096 maximum=33554432
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=7 type=3 len=12
> 13:55:11 DEBUG   (MainThread) [nbd] Received export info
> size=5368709120 flags=3309
> 13:55:11 DEBUG   (MainThread) [nbd] Received reply magic=3e889045565a9
> option=7 type=1 len=0
> 13:55:11 INFO    (MainThread) [nbd] Ready for transmission
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_WRITE handle=0
> offset=0 length=2 flags=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_WRITE handle=1
> offset=1073741824 length=11 flags=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_WRITE handle=2
> offset=2147483648 length=11 flags=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_WRITE handle=3
> offset=3221225472 length=11 flags=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_WRITE handle=4
> offset=4294967296 length=11 flags=0
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_FLUSH handle=5
> offset=0 length=0 flags=0
> 13:55:11 INFO    (MainThread) [nbd] Initiating a soft disconnect
> 13:55:11 DEBUG   (MainThread) [nbd] Sending NBD_CMD_DISC handle=6
> offset=0 length=0 flags=0
> 13:55:11 DEBUG   (MainThread) [qemu_nbd] Terminating qemu-nbd gracefully
> 13:55:11 DEBUG   (MainThread) [qemu_nbd] qemu-nbd terminated with exit code 0
> 13:55:11 DEBUG   (MainThread) [backup] Creating scratch disk
> 13:55:11 DEBUG   (MainThread) [qemu] Starting qemu ['qemu-kvm',
> '-machine', 'accel=kvm:tcg', '-drive',
> 'file=/var/tmp/imageio-storage/file-512-ext4-mount/file,format=qcow2',
> '-nographic', '-qmp',
> 'unix:/var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/qmp.sock,server,nowait',
> '-audiodev', 'none,id=1', '-S']
> 13:55:11 DEBUG   (MainThread) [test] Waiting for socket
> /var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/qmp.sock
> up to 1.000000 seconds
> 13:55:11 DEBUG   (MainThread) [test] Waited for
> /var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/qmp.sock
> 0.040733 seconds
> 13:55:11 DEBUG   (MainThread) [qmp] Talking with qemu 4.1.95
> 13:55:11 DEBUG   (MainThread) [qmp] Sending {'execute': 'qmp_capabilities'}
> 13:55:11 DEBUG   (MainThread) [qmp] Received return: {}
> 13:55:11 DEBUG   (MainThread) [backup] Starting backup
> 13:55:11 DEBUG   (MainThread) [backup] Starting nbd server listening
> on /var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/sock
> 13:55:11 DEBUG   (MainThread) [qmp] Sending {'execute':
> 'nbd-server-start', 'arguments': {'addr': {'type': 'unix', 'data':
> {'path': 
> '/var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/sock'}}}}
> 13:55:11 DEBUG   (MainThread) [qmp] Received return: {}
> 13:55:11 DEBUG   (MainThread) [qmp] Sending {'execute': 'query-block'}
> 13:55:11 DEBUG   (MainThread) [qmp] Received return: [{'io-status':
> 'ok', 'device': 'ide0-hd0', 'locked': False, 'removable': False,
> 'inserted': {'iops_rd': 0, 'detect_zeroes': 'off', 'image':
> {'virtual-size': 5368709120, 'filename':
> '/var/tmp/imageio-storage/file-512-ext4-mount/file', 'cluster-size':
> 65536, 'format': 'qcow2', 'actual-size': 860160, 'format-specific':
> {'type': 'qcow2', 'data': {'compat': '1.1', 'lazy-refcounts': False,
> 'refcount-bits': 16, 'corrupt': False}}, 'dirty-flag': False},
> 'iops_wr': 0, 'ro': False, 'node-name': '#block126',
> 'backing_file_depth': 0, 'drv': 'qcow2', 'iops': 0, 'bps_wr': 0,
> 'write_threshold': 0, 'encrypted': False, 'bps': 0, 'bps_rd': 0,
> 'cache': {'no-flush': False, 'direct': False, 'writeback': True},
> 'file': '/var/tmp/imageio-storage/file-512-ext4-mount/file',
> 'encryption_key_missing': False}, 'qdev':
> '/machine/unattached/device[24]', 'type': 'unknown'}, {'io-status':
> 'ok', 'device': 'ide1-cd0', 'locked': False, 'removable': True,
> 'qdev': '/machine/unattached/device[25]', 'tray_open': False, 'type':
> 'unknown'}, {'device': 'floppy0', 'locked': False, 'removable': True,
> 'qdev': '/machine/unattached/device[17]', 'type': 'unknown'},
> {'device': 'sd0', 'locked': False, 'removable': True, 'type':
> 'unknown'}]
> 13:55:11 DEBUG   (MainThread) [backup] Adding backup node for ide0-hd0
> 13:55:11 DEBUG   (MainThread) [qmp] Sending {'execute':
> 'blockdev-add', 'arguments': {'driver': 'qcow2', 'node-name':
> 'backup-sda', 'file': {'driver': 'file', 'filename':
> '/var/tmp/ovirt-imageio-common/test_full_backup_single_image_1/scratch.qcow2'},
> 'backing': 'ide0-hd0'}}
> 13:55:11 DEBUG   (MainThread) [qmp] Received return: {}
> 13:55:11 DEBUG   (MainThread) [backup] Starting backup job
> 13:55:11 DEBUG   (MainThread) [qmp] Sending {'execute': 'transaction',
> 'arguments': {'actions': [{'type': 'blockdev-backup', 'data':
> {'device': 'ide0-hd0', 'job-id': 'backup-sda', 'sync': 'none',
> 'target': 'backup-sda'}}, {'type': 'block-dirty-bitmap-add', 'data':
> {'name': 'check1', 'node': 'ide0-hd0', 'persistent': True}}]}}
> 13:55:11 DEBUG   (MainThread) [qmp] Received event: JOB_STATUS_CHANGE:
> {'status': 'created', 'id': 'backup-sda'}
> 13:55:11 DEBUG   (MainThread) [qmp] Received event: JOB_STATUS_CHANGE:
> {'status': 'aborting', 'id': 'backup-sda'}
> 13:55:11 DEBUG   (MainThread) [qmp] Received event: JOB_STATUS_CHANGE:
> {'status': 'concluded', 'id': 'backup-sda'}
> 13:55:11 DEBUG   (MainThread) [qmp] Received event: JOB_STATUS_CHANGE:
> {'status': 'null', 'id': 'backup-sda'}
> 13:55:11 DEBUG   (MainThread) [qemu] Terminating qemu gracefully
> 13:55:11 DEBUG   (MainThread) [qemu] qemu terminated with exit code 0