Live Merge is Snapshot Deletion while the VM is up and running. A live merge is initiated when a user clicks the ‘delete’ command associated with a disk snapshot while VM is running. Live merge is an asynchronous operation and the process is quite complex.

Here is the table of live merge flow of events:

Engine VDSM
RemoveSnapshotCommand
RemoveSnapshotSingleDiskLiveCommand
MergeExtendCommand merge: this operation is performed by the running qemu process and monitored by libvirt
MergeVDSCommand getVolumeInfo
MergeStatusCommand Extend Volume: This is based on the volume format(raw/cow) to extend. Extending size can run only on SPM.
DestroyImageCommand Synchronizing volume chain after live merge: Update storage metadata for an image chain after a live merge completes.
SPM/HSM Clear/Sync Tasks from hosts and DB

Take a lab snapshot “test002” live deletion as an example. You will see lock status when the operation is in process in Engine DB and this snapshot entry will disappear after snapshot deletion completion.

vm_name | description | status | image_guid | image_group_id | parentid | imagestatus
------------+-------------+--------+--------------------------------------+--------------------------------------+--------------------------------------+-------------
<VM Name> | test2 | OK | f4294145-44a7-445e-820f-3d33f6ec5f4f | 5a7ed4b8-4d2c-4dc0-8290-c682fca2018a | 58f787b5-9721-4f19-a614-c6845a087c8f | 1
<VM Name> | test | OK | cbf79286-78ac-496c-98db-395178abae67 | 5a7ed4b8-4d2c-4dc0-8290-c682fca2018a | 00000000-0000-0000-0000-000000000000 | 1
<VM Name> | test | OK | 58f787b5-9721-4f19-a614-c6845a087c8f | 5a7ed4b8-4d2c-4dc0-8290-c682fca2018a | cbf79286-78ac-496c-98db-395178abae67 | 1
<VM Name> | test002 | LOCKED | 0434cb87-5752-462d-bce5-de178191caa9 | 5a7ed4b8-4d2c-4dc0-8290-c682fca2018a | f4294145-44a7-445e-820f-3d33f6ec5f4f | 1 >>>>>>
<VM Name> | Active VM | OK | 1989197f-520f-4dc2-bd3d-aafb1c019846 | 5a7ed4b8-4d2c-4dc0-8290-c682fca2018a | 0434cb87-5752-462d-bce5-de178191caa9 | 1
(5 rows)

Engine log records a successful flow as follows:

<<<RemoveSnapshotCommand>>>
2021-03-02 01:51:09,595-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Lock Acquired to object 'EngineLock:{exclusiveLocks="[d4155c57-8ff5-45f5-b2a5-8a25c8b96a59=VM]", sharedLocks=""}'
2021-03-02 01:51:09,636-07 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] method: get, params: [d4155c57-8ff5-45f5-b2a5-8a25c8b96a59], timeElapsed: 1ms
2021-03-02 01:51:09,642-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: RemoveSnapshotCommand internal: false. Entities affected : ID: d4155c57-8ff5-45f5-b2a5-8a25c8b96a59 Type: VMAction group MANIPULATE_VM_SNAPSHOTS with role type USER
2021-03-02 01:51:09,646-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Lock freed to object 'EngineLock:{exclusiveLocks="[d4155c57-8ff5-45f5-b2a5-8a25c8b96a59=VM]", sharedLocks=""}'

<<<RemoveSnapshotSingleDiskLiveCommand>>>
2021-03-02 01:51:09,731-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-1) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: RemoveSnapshotSingleDiskLiveCommand internal: true. Entities affected : ID: c876697b-5677-4e4f-9000-2ee7f84143e9 Type: Storage
2021-03-02 01:51:10,376-07 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Compiled stored procedure. Call string is [{call getimagebyimageid(?)}]
2021-03-02 01:51:10,376-07 DEBUG [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] SqlCall for procedure [GetImageByImageId] compiled
2021-03-02 01:51:10,377-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Executing Live Merge command step 'EXTEND'

<<<MergeExtendCommand>>>
2021-03-02 01:51:10,571-07 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-2) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: MergeExtendCommand internal: true. Entities affected : ID: c876697b-5677-4e4f-9000-2ee7f84143e9 Type: Storage
2021-03-02 01:51:10,572-07 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-2) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Base and top image sizes are the same; no image size update required

2021-03-02 01:51:11,656-07 INFO [org.ovirt.engine.core.bll.MergeCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-3) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: MergeCommand internal: true. Entities affected : ID: c876697b-5677-4e4f-9000-2ee7f84143e9 Type: Storage

<<<MergeVDSCommand>>>
2021-03-02 01:51:11,659-07 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-3) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] START, MergeVDSCommand(HostName = <HostName>, MergeVDSCommandParameters:{hostId='3ccc4344-a908-44b4-9c55-7180b62c0555', vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59', storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', storageDomainId='c876697b-5677-4e4f-9000-2ee7f84143e9', imageGroupId='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', imageId='1989197f-520f-4dc2-bd3d-aafb1c019846', baseImageId='0434cb87-5752-462d-bce5-de178191caa9', topImageId='1989197f-520f-4dc2-bd3d-aafb1c019846', bandwidth="0"}), log id: 51d4d075
2021-03-02 01:51:12,617-07 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-3) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] FINISH, MergeVDSCommand, return: d9e13559-c04e-47d9-afff-3a0e01c165dc, log id: 51d4d075
2021-03-02 01:51:12,617-07 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedThreadFactory-commandCoordinator-Thread-3) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] method: runVdsCommand, params: [Merge, MergeVDSCommandParameters:{hostId='3ccc4344-a908-44b4-9c55-7180b62c0555', vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59', storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', storageDomainId='c876697b-5677-4e4f-9000-2ee7f84143e9', imageGroupId='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', imageId='1989197f-520f-4dc2-bd3d-aafb1c019846', baseImageId='0434cb87-5752-462d-bce5-de178191caa9', topImageId='1989197f-520f-4dc2-bd3d-aafb1c019846', bandwidth="0"}], timeElapsed: 960ms

<<<MergeStatusCommand>>>
2021-03-02 01:51:47,824-07 INFO [org.ovirt.engine.core.bll.MergeStatusCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: MergeStatusCommand internal: true. Entities affected : ID: c876697b-5677-4e4f-9000-2ee7f84143e9 Type: Storage
2021-03-02 01:51:47,850-07 INFO [org.ovirt.engine.core.bll.MergeStatusCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Successfully removed volume 1989197f-520f-4dc2-bd3d-aafb1c019846 from the chain
2021-03-02 01:51:47,850-07 INFO [org.ovirt.engine.core.bll.MergeStatusCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-4) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Volume merge type 'COMMIT'
2021-03-02 01:51:49,817-07 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-40) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Executing Live Merge command step 'DESTROY_IMAGE'

<<<DestroyImageCommand>>>
2021-03-02 01:51:49,833-07 INFO [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-5) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] Running command: DestroyImageCommand internal: true. Entities affected : ID: c876697b-5677-4e4f-9000-2ee7f84143e9 Type: Storage

<<<DestroyImageVDSCommand>>>
2021-03-02 01:51:49,846-07 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-5) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] START, DestroyImageVDSCommand( DestroyImageVDSCommandParameters:{storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', ignoreFailoverLimit="false", storageDomainId='c876697b-5677-4e4f-9000-2ee7f84143e9', imageGroupId='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', imageId='00000000-0000-0000-0000-000000000000', imageList="[1989197f-520f-4dc2-bd3d-aafb1c019846]", postZero='true', force="false"}), log id: 1fff4ff1
2021-03-02 01:51:49,940-07 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (EE-ManagedThreadFactory-commandCoordinator-Thread-5) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] FINISH, DestroyImageVDSCommand, return: , log id: 1fff4ff1
2021-03-02 01:51:49,940-07 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedThreadFactory-commandCoordinator-Thread-5) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] method: runVdsCommand, params: [DestroyImage, DestroyImageVDSCommandParameters:{storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', ignoreFailoverLimit="false", storageDomainId='c876697b-5677-4e4f-9000-2ee7f84143e9', imageGroupId='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', imageId='00000000-0000-0000-0000-000000000000', imageList="[1989197f-520f-4dc2-bd3d-aafb1c019846]", postZero='true', force="false"}], timeElapsed: 94ms

<<<SPM/HSM Task Commands>>>
2021-03-02 01:52:19,058-07 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'eb17d73d-20ef-425d-ac60-2e14cee45a9d'
2021-03-02 01:52:19,058-07 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', ignoreFailoverLimit="false", taskId='eb17d73d-20ef-425d-ac60-2e14cee45a9d'}), log id: 23d2d8ad
2021-03-02 01:52:19,058-07 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] START, HSMClearTaskVDSCommand(HostName = <HostName>, HSMTaskGuidBaseVDSCommandParameters:{hostId='0fc29fb8-aeed-477c-b699-a6cf736c7214', taskId='eb17d73d-20ef-425d-ac60-2e14cee45a9d'}), log id: 2a1397b5

2021-03-02 01:52:19,065-07 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] FINISH, HSMClearTaskVDSCommand, return: , log id: 2a1397b5
2021-03-02 01:52:19,065-07 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] FINISH, SPMClearTaskVDSCommand, return: , log id: 23d2d8ad
2021-03-02 01:52:19,065-07 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] method: runVdsCommand, params: [SPMClearTask, SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', ignoreFailoverLimit="false", taskId='eb17d73d-20ef-425d-ac60-2e14cee45a9d'}], timeElapsed: 7ms
2021-03-02 01:52:19,069-07 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-2883) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] BaseAsyncTask::removeTaskFromDB: Removed task 'eb17d73d-20ef-425d-ac60-2e14cee45a9d' from DataBase

<<<Completion>>>>
2021-03-02 01:52:24,746-07 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-30) [6a5338d9-4ec6-43b9-8051-18d8baf1d913] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_SUCCESS(356), Snapshot 'test002' deletion for VM '<VM Name>' has been completed.

vdsm log records a successful flow as follows:

<<<merge>>>

2021-03-02 01:51:11,663-0700 INFO (jsonrpc/4) [api.virt] START merge(drive={u'imageID': u'5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', u'volumeID': u'1989197f-520f-4dc2-bd3d-aafb1c019846', u'domainID': u'c876697b-5677-4e4f-9000-2ee7f84143e9', u'poolID': u'214e292f-6cbc-41b3-8a3a-89b9fc49ad0c'}, baseVolUUID=u'0434cb87-5752-462d-bce5-de178191caa9', topVolUUID=u'1989197f-520f-4dc2-bd3d-aafb1c019846', bandwidth=u'0', jobUUID=u'd9e13559-c04e-47d9-afff-3a0e01c165dc') from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, vmId=d4155c57-8ff5-45f5-b2a5-8a25c8b96a59 (api:48)
2021-03-02 01:51:11,678-0700 DEBUG (jsonrpc/4) [storage.TaskManager.Task] (Task='74521b7a-210b-41a9-bef2-a2e2d76ffb78') moving from state preparing -> state preparing (task:602)

<<<getVolumeInfo>>>
2021-03-02 01:51:11,678-0700 INFO (jsonrpc/4) [vdsm.api] START getVolumeInfo(sdUUID='c876697b-5677-4e4f-9000-2ee7f84143e9', spUUID='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', imgUUID='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', volUUID=u'0434cb87-5752-462d-bce5-de178191caa9', options=None) from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, task_id=74521b7a-210b-41a9-bef2-a2e2d76ffb78 (api:48)
2021-03-02 01:51:12,410-0700 INFO (jsonrpc/4) [vdsm.api] FINISH getVolumeInfo return={'info': {'status': 'OK', 'domain': 'c876697b-5677-4e4f-9000-2ee7f84143e9', 'voltype': 'INTERNAL', 'description': '', 'parent': 'f4294145-44a7-445e-820f-3d33f6ec5f4f', 'format': 'COW', 'generation': 1, 'image': '5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', 'disktype': 'DATA', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1073741824', 'children': [], 'pool': '', 'ctime': '1614649379', 'capacity': '51539607552', 'uuid': u'0434cb87-5752-462d-bce5-de178191caa9', 'truesize': '1073741824', 'type': 'SPARSE', 'lease': {'path': '/dev/c876697b-5677-4e4f-9000-2ee7f84143e9/leases', 'owners': [], 'version': None, 'offset': 118489088}}} from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, task_id=74521b7a-210b-41a9-bef2-a2e2d76ffb78 (api:54)

2021-03-02 01:51:11,807-0700 INFO (jsonrpc/4) [storage.VolumeManifest] Info request: sdUUID=c876697b-5677-4e4f-9000-2ee7f84143e9 imgUUID=5a7ed4b8-4d2c-4dc0-8290-c682fca2018a volUUID = 0434cb87-5752-462d-bce5-de178191caa9 (volume:240)
2021-03-02 01:51:12,411-0700 DEBUG (jsonrpc/4) [storage.ResourceManager] Trying to release resource '00_storage.c876697b-5677-4e4f-9000-2ee7f84143e9' (resourceManager:568)

<<<Extend Volume>>>
2021-03-02 01:51:12,582-0700 INFO (jsonrpc/4) [vdsm.api] START sendExtendMsg(spUUID='214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', volDict={'newSize': 3221225472, 'domainID': 'c876697b-5677-4e4f-9000-2ee7f84143e9', 'name': 'sda', 'poolID': '214e292f-6cbc-41b3-8a3a-89b9fc49ad0c', 'clock': <Clock(total=0.00*, extend-volume=0.00*)>, 'internal': True, 'volumeID': u'0434cb87-5752-462d-bce5-de178191caa9', 'imageID': '5a7ed4b8-4d2c-4dc0-8290-c682fca2018a'}, newSize=3221225472, callbackFunc=<bound method Vm.__afterVolumeExtension of <vdsm.virt.vm.Vm object at 0x7f00d41e5850>>) from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, task_id=8b842d80-5025-45a1-beeb-fba619bb234b (api:48)
2021-03-02 01:51:12,583-0700 DEBUG (jsonrpc/4) [storage.SPM.Messages.Extend] new extend msg created: domain: c876697b-5677-4e4f-9000-2ee7f84143e9, volume: 0434cb87-5752-462d-bce5-de178191caa9 (mailbox:127)
2021-03-02 01:51:12,583-0700 DEBUG (mailbox-hsm) [storage.MailBox.HsmMailMonitor] HSM_MailMonitor - start: 64, end: 128, len: 4096, message(1/63): '1xtndxe9CAxf8xe7.x00x90ONwV{ivxc8xa9xcax91x81x17xdexe5xbc-FRWx87xcb4x040000000000000c0000000000000' (mailbox:421)
2021-03-02 01:51:12,583-0700 DEBUG (mailbox-hsm) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-87 /usr/bin/dd if=/rhev/data-center/214e292f-6cbc-41b3-8a3a-89b9fc49ad0c/mastersd/dom_md/outbox iflag=direct,fullblock bs=4096 count=1 skip=6 (cwd None) (commands:198)
2021-03-02 01:51:12,596-0700 INFO (jsonrpc/4) [vdsm.api] FINISH sendExtendMsg return=None from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, task_id=8b842d80-5025-45a1-beeb-fba619bb234b (api:54)
2021-03-02 01:51:12,597-0700 DEBUG (jsonrpc/4) [storage.TaskManager.Task] (Task='8b842d80-5025-45a1-beeb-fba619bb234b') finished: None (task:1201)
2021-03-02 01:51:12,597-0700 DEBUG (jsonrpc/4) [storage.TaskManager.Task] (Task='8b842d80-5025-45a1-beeb-fba619bb234b') moving from state preparing -> state finished (task:602)

2021-03-02 01:51:12,614-0700 INFO (jsonrpc/4) [api.virt] FINISH merge return={'status': {'message': 'Done', 'code': 0}} from=::ffff:10.80.148.51,35316, flow_id=6a5338d9-4ec6-43b9-8051-18d8baf1d913, vmId=d4155c57-8ff5-45f5-b2a5-8a25c8b96a59 (api:54)
2021-03-02 01:51:12,715-0700 DEBUG (libvirt/events) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') unhandled libvirt event (event_name=Unknown id 8, args=('/rhev/data-center/mnt/blockSD/c876697b-5677-4e4f-9000-2ee7f84143e9/images/5a7ed4b8-4d2c-4dc0-8290-c682fca2018a/1989197f-520f-4dc2-bd3d-aafb1c019846', 4, 3, 8)) (clientIF:691
2021-03-02 01:51:14,866-0700 DEBUG (mailbox-hsm/3) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') Refreshing drive volume for sda (domainID: c876697b-5677-4e4f-9000-2ee7f84143e9, volumeID: 0434cb87-5752-462d-bce5-de178191caa9) (vm:1307)
2021-03-02 01:51:15,040-0700 DEBUG (mailbox-hsm/3) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') Verifying extension for volume 0434cb87-5752-462d-bce5-de178191caa9, requested size 3221225472, current size 3221225472 (vm:1317)
2021-03-02 01:51:15,040-0700 INFO (mailbox-hsm/3) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') Extend volume 0434cb87-5752-462d-bce5-de178191caa9 completed <Clock(total=2.46, extend-volume=2.28, refresh-volume=0.18)> (vm:1400)

<<<Synchronizing volume chain after live merge>>>
2021-03-02 01:51:17,977-0700 INFO (merge/d4155c57) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') Synchronizing volume chain after live merge (job d9e13559-c04e-47d9-afff-3a0e01c165dc) (vm:6206)
2021-03-02 01:51:17,988-0700 DEBUG (merge/d4155c57) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') vdsm chain: ['58f787b5-9721-4f19-a614-c6845a087c8f', '0434cb87-5752-462d-bce5-de178191caa9', '1989197f-520f-4dc2-bd3d-aafb1c019846', 'cbf79286-78ac-496c-98db-395178abae67', 'f4294145-44a7-445e-820f-3d33f6ec5f4f'], libvirt chain: ['cbf79286-78ac-496c-98db-395178abae67', '58f787b5-9721-4f19-a614-c6845a087c8f', 'f4294145-44a7-445e-820f-3d33f6ec5f4f', '0434cb87-5752-462d-bce5-de178191caa9'] (vm:5982)
2021-03-02 01:51:17,989-0700 DEBUG (merge/d4155c57) [storage.TaskManager.Task] (Task='6f65ead2-cc39-4ce8-aa07-8c789bee9eb9') moving from state init -> state preparing (task:602)
2021-03-02 01:51:17,989-0700 INFO (merge/d4155c57) [vdsm.api] START imageSyncVolumeChain(sdUUID='c876697b-5677-4e4f-9000-2ee7f84143e9', imgUUID='5a7ed4b8-4d2c-4dc0-8290-c682fca2018a', volUUID='1989197f-520f-4dc2-bd3d-aafb1c019846', newChain=['cbf79286-78ac-496c-98db-395178abae67', '58f787b5-9721-4f19-a614-c6845a087c8f', 'f4294145-44a7-445e-820f-3d33f6ec5f4f', '0434cb87-5752-462d-bce5-de178191caa9']) from=internal, task_id=6f65ead2-cc39-4ce8-aa07-8c789bee9eb9 (api:48)

<<<Completion>>>
2021-03-02 01:51:18,466-0700 INFO (merge/d4155c57) [virt.vm] (vmId='d4155c57-8ff5-45f5-b2a5-8a25c8b96a59') Synchronization completed (job d9e13559-c04e-47d9-afff-3a0e01c165dc) (vm:6215)