RedHat Virtualization (RHV) での Live Merge について

ライブマージは、VM が稼働中のスナップショットの削除です。 VM の実行中に、ユーザーがディスクスナップショットに関連付けられた「削除」コマンドをクリックすると、ライブマージが開始されます。ライブマージは非同期操作であり、プロセスは非常に複雑です。

イベントのライブマージフローの表は次のとおりです:

エンジン	VDSM
RemoveSnapshotCommand	–
RemoveSnapshotSingleDiskLiveCommand	–
MergeExtendCommand	マージ:この操作は実行中の qemu プロセスによって実行され、libvirt によって監視されます
MergeVDSCommand	getVolumeInfo
MergeStatusCommand	Extend Volume:これは、拡張するボリューム形式 (raw/cow) に基づいています。サイズの拡張は SPM でのみ実行できます。
DestroyImageCommand	ライブマージ後のボリュームチェーンの同期:ライブマージの完了後にイメージチェーンのストレージメタデータを更新します。
ホストおよび DB からの SPM/HSM クリア/同期タスク	–

例として、ラボスナップショット「test002」のライブ削除を取り上げます。エンジン DB で操作が進行中の場合はロックステータスが表示され、スナップショットの削除が完了すると、このスナップショットエントリは表示されなくなります。

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)

エンジンログには、成功したフローが次のように記録されます。

<<<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 ログには、成功したフローが次のように記録されます:

<<<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): '1xtnd\xe9CA\xf8\xe7.\x00\x90ONwV{iv\xc8\xa9\xca\x91\x81\x17\xde\xe5\xbc-FRW\x87\xcb4\x040000000000000c0000000000000' (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)