Bug 1941518

Can you please add the details of the original disk (block\file and sizes) and the details of the created scratch disks?
You can use 'qemu-img info' for it.

The documentation text flag should only be set after 'doc text' field is provided. Please provide the documentation text and set the flag to '?' again.

Original disk:

# qemu-img info /rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/5af27685-ef98-4329-a751-2bf682705792/b5612c4c-091b-4a54-b749-605f3997b607
image: /rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/5af27685-ef98-4329-a751-2bf682705792/b5612c4c-091b-4a54-b749-605f3997b607
file format: qcow2
virtual size: 50 GiB (53687091200 bytes)
disk size: 0 B
cluster_size: 65536
Format specific information:
    compat: 1.1
    compression type: zlib
    lazy refcounts: false
    bitmaps:
        [0]:
            flags:
                [0]: in-use
                [1]: auto
            name: 4e599572-0d01-42eb-b93d-cf4b669c003a
            granularity: 65536
    refcount bits: 16
    corrupt: false

Scratch disk:
# qemu-img info /rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/4818de44-070c-48f0-9498-beb64c61d51a/035acf4b-627f-482a-9cdf-30479f7bcdab
image: /rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/4818de44-070c-48f0-9498-beb64c61d51a/035acf4b-627f-482a-9cdf-30479f7bcdab
file format: qcow2
virtual size: 50 GiB (53687091200 bytes)
disk size: 0 B
cluster_size: 65536
Format specific information:
    compat: 1.1
    compression type: zlib
    lazy refcounts: false
    refcount bits: 16
    corrupt: false



lvs:

  035acf4b-627f-482a-9cdf-30479f7bcdab ea2fe42d-2fa1-410f-894d-29621bb08716 -wi-ao----    1.00g                                                                                 IU_4818de44-070c-48f0-9498-beb64c61d51a,MD_9,PU_00000000-0000-0000-0000-000000000000 


Logs of the volume creation in VDSM:
2021-03-22 14:16:00,173+0100 INFO  (jsonrpc/1) [vdsm.api] START createVolume(sdUUID='ea2fe42d-2fa1-410f-894d-29621bb08716', spUUID='7f483e64-7645-4a37-a782-4d147dc1f7be', imgUUID='4818de44-070c-48f0-9498-beb64c61d51a', size='53687091200', volFormat=4, preallocate=2, diskType='SCRD', volUUID='035acf4b-627f-482a-9cdf-30479f7bcdab', desc='{"DiskAlias":"VM ovirt-test001 backup ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000', initialSize=None, addBitmaps=False) from=::ffff:x.x.x.91,37400, flow_id=3f113595-d5cf-4895-ba12-edda98d36bac, task_id=c7eb39f2-5667-41d5-bfd4-f80ba60262d5 (api:48)
2021-03-22 14:16:00,428+0100 INFO  (tasks/9) [storage.Volume] Creating volume 035acf4b-627f-482a-9cdf-30479f7bcdab (volume:1231)
2021-03-22 14:16:00,456+0100 INFO  (tasks/9) [storage.LVM] Creating LV (vg=ea2fe42d-2fa1-410f-894d-29621bb08716, lv=035acf4b-627f-482a-9cdf-30479f7bcdab, size=1024m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',), device=None) (lvm:1566)
2021-03-22 14:16:00,654+0100 INFO  (tasks/9) [storage.Volume] Creating volume symlink from '/dev/ea2fe42d-2fa1-410f-894d-29621bb08716/035acf4b-627f-482a-9cdf-30479f7bcdab' to '/rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/4818de44-070c-48f0-9498-beb64c61d51a/035acf4b-627f-482a-9cdf-30479f7bcdab' (blockVolume:512)
2021-03-22 14:16:00,655+0100 INFO  (tasks/9) [storage.Volume] Request to create COW volume /rhev/data-center/mnt/blockSD/ea2fe42d-2fa1-410f-894d-29621bb08716/images/4818de44-070c-48f0-9498-beb64c61d51a/035acf4b-627f-482a-9cdf-30479f7bcdab with capacity = 53687091200 (blockVolume:517)
2021-03-22 14:16:00,846+0100 INFO  (tasks/9) [storage.LVM] Change LVs tags (vg=ea2fe42d-2fa1-410f-894d-29621bb08716, lvs=('035acf4b-627f-482a-9cdf-30479f7bcdab',), delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_9', 'PU_00000000-0000-0000-0000-000000000000', 'IU_4818de44-070c-48f0-9498-beb64c61d51a']) (lvm:1778)
2021-03-22 14:16:01,022+0100 INFO  (tasks/9) [storage.LVM] Deactivating lvs: vg=ea2fe42d-2fa1-410f-894d-29621bb08716 lvs=['035acf4b-627f-482a-9cdf-30479f7bcdab'] (lvm:1746)
2021-03-22 14:16:10,498+0100 INFO  (jsonrpc/1) [vdsm.api] START getVolumeInfo(sdUUID='ea2fe42d-2fa1-410f-894d-29621bb08716', spUUID='7f483e64-7645-4a37-a782-4d147dc1f7be', imgUUID='4818de44-070c-48f0-9498-beb64c61d51a', volUUID='035acf4b-627f-482a-9cdf-30479f7bcdab', options=None) from=::ffff:x.x.x.91,39080, flow_id=3f113595-d5cf-4895-ba12-edda98d36bac, task_id=945083f3-1058-42ec-9e0c-d4b637e6e436 (api:48)
2021-03-22 14:16:10,679+0100 INFO  (jsonrpc/1) [storage.VolumeManifest] Info request: sdUUID=ea2fe42d-2fa1-410f-894d-29621bb08716 imgUUID=4818de44-070c-48f0-9498-beb64c61d51a volUUID = 035acf4b-627f-482a-9cdf-30479f7bcdab  (volume:239)
2021-03-22 14:16:10,704+0100 INFO  (jsonrpc/1) [storage.VolumeManifest] ea2fe42d-2fa1-410f-894d-29621bb08716/4818de44-070c-48f0-9498-beb64c61d51a/035acf4b-627f-482a-9cdf-30479f7bcdab info is {'uuid': '035acf4b-627f-482a-9cdf-30479f7bcdab', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'SCRD', 'voltype': 'LEAF', 'capacity': '53687091200', 'parent': '00000000-0000-0000-0000-000000000000', 'description': '{"DiskAlias":"VM ovirt-test001 backup ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}', 'pool': '', 'domain': 'ea2fe42d-2fa1-410f-894d-29621bb08716', 'image': '4818de44-070c-48f0-9498-beb64c61d51a', 'ctime': '1616418961', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '1073741824', 'truesize': '1073741824', 'status': 'OK', 'lease': {'path': '/dev/ea2fe42d-2fa1-410f-894d-29621bb08716/leases', 'offset': 114294784, 'owners': [], 'version': None}, 'children': []} (volume:278)
2021-03-22 14:16:10,704+0100 INFO  (jsonrpc/1) [vdsm.api] FINISH getVolumeInfo return={'info': {'uuid': '035acf4b-627f-482a-9cdf-30479f7bcdab', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'SCRD', 'voltype': 'LEAF', 'capacity': '53687091200', 'parent': '00000000-0000-0000-0000-000000000000', 'description': '{"DiskAlias":"VM ovirt-test001 backup ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}', 'pool': '', 'domain': 'ea2fe42d-2fa1-410f-894d-29621bb08716', 'image': '4818de44-070c-48f0-9498-beb64c61d51a', 'ctime': '1616418961', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '1073741824', 'truesize': '1073741824', 'status': 'OK', 'lease': {'path': '/dev/ea2fe42d-2fa1-410f-894d-29621bb08716/leases', 'offset': 114294784, 'owners': [], 'version': None}, 'children': []}} from=::ffff:x.x.x.91,39080, flow_id=3f113595-d5cf-4895-ba12-edda98d36bac, task_id=945083f3-1058-42ec-9e0c-d4b637e6e436 (api:54)

(In reply to Jean-Louis Dupond from comment #3)
> Original disk:
> 
> # qemu-img info
...
> virtual size: 50 GiB (53687091200 bytes)

This is the size that may be written to the scratch disk in the worst case

...
> Scratch disk:
...
> virtual size: 50 GiB (53687091200 bytes)

Looks good

> disk size: 0 B

This is not useful on block storage.

...
> lvs:
> 
>   035acf4b-627f-482a-9cdf-30479f7bcdab ea2fe42d-2fa1-410f-894d-29621bb08716
> -wi-ao----    1.00g   

This size is wrong, this scratch disk will never be extended, so it 
will fail to backup more than 1g (actually little less because of
qcow2 metadta).
                                                      
...
> Logs of the volume creation in VDSM:
> 2021-03-22 14:16:00,173+0100 INFO  (jsonrpc/1) [vdsm.api] START
> createVolume(sdUUID='ea2fe42d-2fa1-410f-894d-29621bb08716',
> spUUID='7f483e64-7645-4a37-a782-4d147dc1f7be',
> imgUUID='4818de44-070c-48f0-9498-beb64c61d51a', size='53687091200',
> volFormat=4, preallocate=2, diskType='SCRD',
> volUUID='035acf4b-627f-482a-9cdf-30479f7bcdab', desc='{"DiskAlias":"VM
> ovirt-test001 backup ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for
> ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}',
> srcImgUUID='00000000-0000-0000-0000-000000000000',
> srcVolUUID='00000000-0000-0000-0000-000000000000', initialSize=None,

initalSize=None is wrong, this should be initialSize='53687091200'

So we have a real bug.

This looks strange because we handle this case specifically.
Can you please add the full engine and VDSM logs?

From the engine logs, I can see the following calls - 


For block-based volumes with qcow2 format, we fetch the up-to-date volume info from VDSM -

edda98d36bac] START, GetVolumeInfoVDSCommand(HostName = ovn003, GetVolumeInfoVDSCommandParameters:{hostId='e8facc41-7088-4c5a-9a69-680d1d5e6dee', storagePoolId='7f483e64-7645-4a37-a782-4d147dc1f7be', storageDomainId='ea2fe42d-2fa1-410f-894d-29621bb08716', imageGroupId='5af27685-ef98-4329-a751-2bf682705792', imageId='b5612c4c-091b-4a54-b749-605f3997b607'}), log id: 6d93a679
2021-03-22 14:15:55,061+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-67) [3f113595-d5cf-4895-ba12-edda98d36bac] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@3d3ac386, log id: 6d93a679
2021-03-22 14:15:55,062+01 INFO  [org.ovirt.engine.core.bll.storage.backup.CreateScratchDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-67) [3f113595-d5cf-4895-ba12-edda98d36bac] Creating scratch disk for disk ID 5af27685-ef98-4329-a751-2bf682705792

Then we create the new scratch disk with the initial size that equal to the backed-up disk apparent size -

edda98d36bac] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='7f483e64-7645-4a37-a782-4d147dc1f7be', ignoreFailoverLimit='false', storageDomainId='ea2fe42d-2fa1-410f-894d-29621bb08716', imageGroupId='4818de44-070c-48f0-9498-beb64c61d51a', imageSizeInBytes='53687091200', volumeFormat='COW', newImageId='035acf4b-627f-482a-9cdf-30479f7bcdab', imageType='Sparse', newImageDescription='{"DiskAlias":"VM ovirt-test001 backup ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}', imageInitialSizeInBytes='0', imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000', shouldAddBitmaps='false'}), log id: 29261de9

We can see here that the original backed-up disk size is '0' so there is no chance for any data to be pushed to the scratch disk.

That's why you see the initial size in the VDSM logs as 'None'.

Can you confirm that the disk was empty?

The disk is a 50GB preallocated QCOW disk.

And there is data on it:
/dev/sda1        49G   36G   11G  78% /

(In reply to Jean-Louis Dupond from comment #7)
> The disk is a 50GB preallocated QCOW disk.
> 
> And there is data on it:
> /dev/sda1        49G   36G   11G  78% /

I guess the disk was created as:

    Allocation Policy: Preallocated
    Enable incremental backup: true

So the logical volume should be 50g. The scratch disk should be created
at this same size.

(In reply to Eyal Shenitzky from comment #6)
> edda98d36bac] START, CreateVolumeVDSCommand(
> CreateVolumeVDSCommandParameters:{storagePoolId='7f483e64-7645-4a37-a782-
> 4d147dc1f7be', ignoreFailoverLimit='false',
> storageDomainId='ea2fe42d-2fa1-410f-894d-29621bb08716',
> imageGroupId='4818de44-070c-48f0-9498-beb64c61d51a',
> imageSizeInBytes='53687091200', volumeFormat='COW',
> newImageId='035acf4b-627f-482a-9cdf-30479f7bcdab', imageType='Sparse',
> newImageDescription='{"DiskAlias":"VM ovirt-test001 backup
> ff237b7e-6683-499d-adcb-c3cd0595b5e0 scratch disk for
> ovirt-test001_Disk1","DiskDescription":"Backup ff237b7e-6683-499d-ad"}',
> imageInitialSizeInBytes='0', imageId='00000000-0000-0000-0000-000000000000',
> sourceImageGroupId='00000000-0000-0000-0000-000000000000',
> shouldAddBitmaps='false'}), log id: 29261de9
> 
> We can see here that the original backed-up disk size is '0' so there is no
> chance for any data to be pushed to the scratch disk.

We don't see the size returned by vdsm here. We need complete vdsm and engine
logs to understand what happened here.

Jean-Louis, can you attach the logs to the bug?

If the logs contains sensitive info you can remove the info from the logs.

The getVolumeInfo (of the VMs disk):
2021-03-23 09:34:30,566+0100 INFO  (jsonrpc/0) [vdsm.api] FINISH getVolumeInfo return={'info': {'uuid': 'b5612c4c-091b-4a54-b749-605f3997b607', 'type': 'PREALLOCATED', 'format': 'COW', 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '53687091200', 'parent': '00000000-0000-0000-0000-000000000000', 'description': '{"DiskAlias":"ovirt-test001_Disk1","DiskDescription":""}', 'pool': '', 'domain': 'ea2fe42d-2fa1-410f-894d-29621bb08716', 'image': '5af27685-ef98-4329-a751-2bf682705792', 'ctime': '1603104770', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '53687091200', 'truesize': '53687091200', 'status': 'OK', 'lease': {'path': '/dev/ea2fe42d-2fa1-410f-894d-29621bb08716/leases', 'offset': 108003328, 'owners': [], 'version': None}, 'children': []}} from=::ffff:x.x.x.91,56512, flow_id=34e22c6c-a760-40eb-8d5d-40c4babf1f66, task_id=b90514b0-2cd9-4a39-a5e1-c0aae1dd0e93 (api:54)

The createVolume:
2021-03-23 09:34:30,620+0100 INFO  (jsonrpc/7) [vdsm.api] START createVolume(sdUUID='ea2fe42d-2fa1-410f-894d-29621bb08716', spUUID='7f483e64-7645-4a37-a782-4d147dc1f7be', imgUUID='f23f8c66-0c38-4837-8d1d-d5307a43e8a8', size='53687091200', volFormat=4, preallocate=2, diskType='SCRD', volUUID='980aaac4-6a86-436b-8c0c-6518fd362145', desc='{"DiskAlias":"VM ovirt-test001 backup 379f204f-bd7e-43b5-a2e2-2c2c951f11ad scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup 379f204f-bd7e-43b5-a2"}', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000', initialSize=None, addBitmaps=False) from=::ffff:x.x.x.91,37400, flow_id=34e22c6c-a760-40eb-8d5d-40c4babf1f66, task_id=d45469fa-ab2f-4d49-bdc1-7f12436492bd (api:48)


The size is just returned correctly, so VDSM does it job just fine.

But I digged some more into the engine code, and could it be its the following?
In backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/storage/disk/image/AddImageFromScratchCommand.java (which is called to create the disk) we have the following:
    private Long getInitialSize() {
        DiskImage diskImage = getParameters().getDiskInfo();
        Long initialSize = null;
        if (ImagesHandler.isImageInitialSizeSupported(getStorageDomain().getStorageType()) &&
                diskImage.getImage().getVolumeType().equals(VolumeType.Sparse) &&
                diskImage.getActualSizeInBytes() != 0) {
            initialSize = diskImage.getActualSizeInBytes();
        }

        return initialSize;
    }


It just doesn't do anything with the InitialSize we've set?
And as we don't set a ActualSize, this returns 0, so initialSize -> 0

Thanks Jean-Louis, this seems to be the bug. The infrastructure for creating
disks overrides user provided value incorrectly. This should be an easy fix.

Please provide a verification steps. Thanks. Where to look for 'initalSize' value in particular?

Steps to Reproduce:
1. Create a VM with 2 GB preallocated disk enabled for backup
2. Run the VM
3. Start a full backup for the VM
4. Created scratch disk size should be equal to the backed-up disk (2 GB)


You can look at the createVolumeVDSCommand parameters imageInitialSizeInBytes field (should not be zero as in the example) - 

4ada-a3c7-c63ee3d5a2e2] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='7f483e64-7645-4a37-a782-4d147dc1f7be', ignoreFailoverLimit='false', storageDomainId='ea2fe42d-2fa1-410f-894d-29621bb08716', imageGroupId='9742fd76-3efa-420d-a42d-bff597415e4f', imageSizeInBytes='53687091200', volumeFormat='COW', newImageId='7e18afae-54b0-4195-9950-2430723d027f', imageType='Sparse', newImageDescription='{"DiskAlias":"VM ovirt-test001 backup 8f6a9f14-a5aa-486b-bcd5-63580c6805b8 scratch disk for ovirt-test001_Disk1","DiskDescription":"Backup 8f6a9f14-a5aa-486b-bc"}', imageInitialSizeInBytes='0', imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000', shouldAddBitmaps='false'}), log id: 5df7fed

Verified on rhv-4.4.6-4

This scenario verification is only relevant for block storage.

1. Create a VM with 2 GB preallocated disk with incremental backup enabled:

<disk>
  <storage_domains>
    <storage_domain id="{{underlying_sd}}"/>
  </storage_domains>
  <name>{{tc_name}}_cow</name>
  <provisioned_size>2073741824</provisioned_size>
  <format>cow</format>
  <sparse>false</sparse>
  <backup>incremental</backup>
</disk>

2. Run the VM
3. Start a full backup for the VM
4. Created scratch disk size should be equal to the backed-up disk (2 GB)

Expected: imageInitialSizeInBytes not equals 0

Actual:

2021-04-12 15:56:46,279+03 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-71) [b1c66f5e-ce05-4679-a036-68cb4dc8915c] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='ffcbe476-0064-4218-8d44-0acd728db84a', ignoreFailoverLimit='false', storageDomainId='9ba44087-57e2-4cbb-8f67-a7a63745d653', imageGroupId='e4479547-5ffb-4773-964f-e3824a4b10fa', imageSizeInBytes='2073743360', volumeFormat='COW', newImageId='7a79425f-b6e2-40d8-93dd-f5daf462b1bc', imageType='Sparse', newImageDescription='{"DiskAlias":"VM 27150 backup 89d8b6f3-60a3-4804-af7e-e6b33cecd24a scratch disk for 27150_cow","DiskDescription":"Backup 89d8b6f3-60a3-4804-af7e-e6b33cecd24a scratch disk"}', imageInitialSizeInBytes='2147483648', imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000', shouldAddBitmaps='false'}), log id: 8b77cae

This bugzilla is included in oVirt 4.4.6 release, published on May 4th 2021.

Since the problem described in this bug report should be resolved in oVirt 4.4.6 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.