[ovirt-users] oVIRT 4.1.3 / iSCSI / VM Multiple Disks / Snapshot deletion issue.

Thu Jul 13 08:38:24 UTC 2017

Hi,

Can you please attach full engine and vdsm logs?

On Thu, Jul 13, 2017 at 1:07 AM, Devin Acosta <devin at pabstatencio.com> wrote:
> We are running a fresh install of oVIRT 4.1.3, using ISCSI, the VM in
> question has multiple Disks (4 to be exact). It snapshotted OK while on
> iSCSI however when I went to delete the single snapshot that existed it went
> into Locked state and never came back. The deletion has been going for well
> over an hour, and I am not convinced since the snapshot is less than 12
> hours old that it’s really doing anything.
>
> I have seen that doing some Googling indicates there might be some known
> issues with iSCSI/Block Storage/Multiple Disk Snapshot issues.
>
> In the logs on the engine it shows:
>
> 2017-07-12 21:59:42,473Z INFO
> [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback]
> (DefaultQuartzScheduler2) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'ColdMergeSnapshotSingleDisk' (id: '75c535fd-4558-459a-9992-875c48578a97')
> waiting on child command id: 'd92e9a22-5f0f-4b61-aac6-5601f8ac2cda'
> type:'PrepareMerge' to complete
> 2017-07-12 21:59:52,480Z INFO
> [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
> (DefaultQuartzScheduler2) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'RemoveSnapshot' (id: '40482d09-8a7c-4dbd-8324-3e789296887a') waiting on
> child command id: '75c535fd-4558-459a-9992-875c48578a97'
> type:'ColdMergeSnapshotSingleDisk' to complete
> 2017-07-12 21:59:52,483Z INFO
> [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback]
> (DefaultQuartzScheduler2) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'ColdMergeSnapshotSingleDisk' (id: '75c535fd-4558-459a-9992-875c48578a97')
> waiting on child command id: 'd92e9a22-5f0f-4b61-aac6-5601f8ac2cda'
> type:'PrepareMerge' to complete
> 2017-07-12 22:00:02,490Z INFO
> [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
> (DefaultQuartzScheduler6) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'RemoveSnapshot' (id: '40482d09-8a7c-4dbd-8324-3e789296887a') waiting on
> child command id: '75c535fd-4558-459a-9992-875c48578a97'
> type:'ColdMergeSnapshotSingleDisk' to complete
> 2017-07-12 22:00:02,493Z INFO
> [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback]
> (DefaultQuartzScheduler6) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'ColdMergeSnapshotSingleDisk' (id: '75c535fd-4558-459a-9992-875c48578a97')
> waiting on child command id: 'd92e9a22-5f0f-4b61-aac6-5601f8ac2cda'
> type:'PrepareMerge' to complete
> 2017-07-12 22:00:12,498Z INFO
> [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
> (DefaultQuartzScheduler3) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'RemoveSnapshot' (id: '40482d09-8a7c-4dbd-8324-3e789296887a') waiting on
> child command id: '75c535fd-4558-459a-9992-875c48578a97'
> type:'ColdMergeSnapshotSingleDisk' to complete
> 2017-07-12 22:00:12,501Z INFO
> [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback]
> (DefaultQuartzScheduler3) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'ColdMergeSnapshotSingleDisk' (id: '75c535fd-4558-459a-9992-875c48578a97')
> waiting on child command id: 'd92e9a22-5f0f-4b61-aac6-5601f8ac2cda'
> type:'PrepareMerge' to complete
> 2017-07-12 22:00:22,508Z INFO
> [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
> (DefaultQuartzScheduler5) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'RemoveSnapshot' (id: '40482d09-8a7c-4dbd-8324-3e789296887a') waiting on
> child command id: '75c535fd-4558-459a-9992-875c48578a97'
> type:'ColdMergeSnapshotSingleDisk' to complete
> 2017-07-12 22:00:22,511Z INFO
> [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback]
> (DefaultQuartzScheduler5) [a5f6eaf2-7996-4d51-ba62-050272d1f097] Command
> 'ColdMergeSnapshotSingleDisk' (id: '75c535fd-4558-459a-9992-875c48578a97')
> waiting on child command id: 'd92e9a22-5f0f-4b61-aac6-5601f8ac2cda'
> type:'PrepareMerge' to complete
>
> This is what I seen on the SPM when I grep’d the Snapshot ID.
>
> 2017-07-12 14:22:18,773-0700 INFO  (jsonrpc/6) [vdsm.api] START
> createVolume(sdUUID=u'0c02a758-4295-4199-97de-b041744b3b15',
> spUUID=u'00000001-0001-0001-0001-000000000311',
> imgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d', size=u'107374182400',
> volFormat=4, preallocate=2, diskType=2,
> volUUID=u'5921ba71-0f00-46cd-b0be-3c2ac1396845', desc=u'',
> srcImgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d',
> srcVolUUID=u'0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', initialSize=None)
> from=::ffff:10.4.64.7,60016, flow_id=e94eebf8-75dc-407a-8916-f4ff632f843e
> (api:46)
> 2017-07-12 14:22:19,095-0700 WARN  (tasks/6) [root] File:
> /rhev/data-center/00000001-0001-0001-0001-000000000311/0c02a758-4295-4199-97de-b041744b3b15/images/6a887015-67cd-4f7b-b709-eef97142258d/5921ba71-0f00-46cd-b0be-3c2ac1396845
> already removed (utils:120)
> 2017-07-12 14:22:19,096-0700 INFO  (tasks/6) [storage.Volume] Request to
> create snapshot
> 6a887015-67cd-4f7b-b709-eef97142258d/5921ba71-0f00-46cd-b0be-3c2ac1396845 of
> volume
> 6a887015-67cd-4f7b-b709-eef97142258d/0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae
> (blockVolume:545)
> 2017-07-12 14:22:19,676-0700 INFO  (tasks/6) [storage.LVM] Change LV tags
> (vg=0c02a758-4295-4199-97de-b041744b3b15,
> lv=5921ba71-0f00-46cd-b0be-3c2ac1396845, delTags=['OVIRT_VOL_INITIALIZING'],
> addTags=['MD_10', u'PU_0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae',
> u'IU_6a887015-67cd-4f7b-b709-eef97142258d']) (lvm:1344)
> 2017-07-12 14:22:36,010-0700 INFO  (jsonrpc/5) [vdsm.api] START
> getVolumeInfo(sdUUID=u'0c02a758-4295-4199-97de-b041744b3b15',
> spUUID=u'00000001-0001-0001-0001-000000000311',
> imgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d',
> volUUID=u'5921ba71-0f00-46cd-b0be-3c2ac1396845', options=None)
> from=::ffff:10.4.64.7,59664, flow_id=e94eebf8-75dc-407a-8916-f4ff632f843e
> (api:46)
> 2017-07-12 14:22:36,077-0700 INFO  (jsonrpc/5) [storage.VolumeManifest] Info
> request: sdUUID=0c02a758-4295-4199-97de-b041744b3b15
> imgUUID=6a887015-67cd-4f7b-b709-eef97142258d volUUID =
> 5921ba71-0f00-46cd-b0be-3c2ac1396845  (volume:238)
> 2017-07-12 14:22:36,185-0700 INFO  (jsonrpc/5) [storage.VolumeManifest]
> 0c02a758-4295-4199-97de-b041744b3b15/6a887015-67cd-4f7b-b709-eef97142258d/5921ba71-0f00-46cd-b0be-3c2ac1396845
> info is {'status': 'OK', 'domain': '0c02a758-4295-4199-97de-b041744b3b15',
> 'voltype': 'LEAF', 'description': '', 'parent':
> '0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', 'format': 'COW', 'generation': 0,
> 'image': '6a887015-67cd-4f7b-b709-eef97142258d', 'ctime': '1499894539',
> 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize':
> '1073741824', 'children': [], 'pool': '', 'capacity': '107374182400',
> 'uuid': u'5921ba71-0f00-46cd-b0be-3c2ac1396845', 'truesize': '1073741824',
> 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}} (volume:272)
> 2017-07-12 14:22:36,186-0700 INFO  (jsonrpc/5) [vdsm.api] FINISH
> getVolumeInfo return={'info': {'status': 'OK', 'domain':
> '0c02a758-4295-4199-97de-b041744b3b15', 'voltype': 'LEAF', 'description':
> '', 'parent': '0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', 'format': 'COW',
> 'generation': 0, 'image': '6a887015-67cd-4f7b-b709-eef97142258d', 'ctime':
> '1499894539', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0',
> 'apparentsize': '1073741824', 'children': [], 'pool': '', 'capacity':
> '107374182400', 'uuid': u'5921ba71-0f00-46cd-b0be-3c2ac1396845', 'truesize':
> '1073741824', 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}}}
> from=::ffff:10.4.64.7,59664, flow_id=e94eebf8-75dc-407a-8916-f4ff632f843e
> (api:52)
> 2017-07-12 14:24:24,854-0700 INFO  (jsonrpc/1) [vdsm.api] START
> deleteVolume(sdUUID=u'0c02a758-4295-4199-97de-b041744b3b15',
> spUUID=u'00000001-0001-0001-0001-000000000311',
> imgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d',
> volumes=[u'5921ba71-0f00-46cd-b0be-3c2ac1396845'], postZero=u'false',
> force=u'false', discard=False) from=::ffff:10.4.64.7,60016,
> flow_id=c5e4bda4-9cd3-461d-8164-51d5614b995e (api:46)
> 2017-07-12 14:24:25,010-0700 INFO  (tasks/7) [storage.Volume] Request to
> delete LV 5921ba71-0f00-46cd-b0be-3c2ac1396845 of image
> 6a887015-67cd-4f7b-b709-eef97142258d in VG
> 0c02a758-4295-4199-97de-b041744b3b15  (blockVolume:579)
> 2017-07-12 14:24:25,130-0700 INFO  (tasks/7) [storage.VolumeManifest]
> sdUUID=0c02a758-4295-4199-97de-b041744b3b15
> imgUUID=6a887015-67cd-4f7b-b709-eef97142258d volUUID =
> 5921ba71-0f00-46cd-b0be-3c2ac1396845 legality = ILLEGAL  (volume:398)
> 2017-07-12 14:24:38,881-0700 INFO  (jsonrpc/2) [vdsm.api] START
> getVolumeInfo(sdUUID=u'0c02a758-4295-4199-97de-b041744b3b15',
> spUUID=u'00000001-0001-0001-0001-000000000311',
> imgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d',
> volUUID=u'5921ba71-0f00-46cd-b0be-3c2ac1396845', options=None)
> from=::ffff:10.4.64.7,59664, flow_id=c5e4bda4-9cd3-461d-8164-51d5614b995e
> (api:46)
> 2017-07-12 14:24:49,911-0700 INFO  (jsonrpc/1) [vdsm.api] START
> getVolumeInfo(sdUUID=u'0c02a758-4295-4199-97de-b041744b3b15',
> spUUID=u'00000001-0001-0001-0001-000000000311',
> imgUUID=u'6a887015-67cd-4f7b-b709-eef97142258d',
> volUUID=u'0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', options=None)
> from=::ffff:10.4.64.7,59664, flow_id=c5e4bda4-9cd3-461d-8164-51d5614b995e
> (api:46)
> 2017-07-12 14:24:49,912-0700 INFO  (jsonrpc/1) [storage.VolumeManifest] Info
> request: sdUUID=0c02a758-4295-4199-97de-b041744b3b15
> imgUUID=6a887015-67cd-4f7b-b709-eef97142258d volUUID =
> 0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae  (volume:238)
> 2017-07-12 14:24:50,036-0700 INFO  (jsonrpc/1) [storage.VolumeManifest]
> 0c02a758-4295-4199-97de-b041744b3b15/6a887015-67cd-4f7b-b709-eef97142258d/0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae
> info is {'status': 'OK', 'domain': '0c02a758-4295-4199-97de-b041744b3b15',
> 'voltype': 'LEAF', 'description': '', 'parent':
> '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'generation': 0,
> 'image': '6a887015-67cd-4f7b-b709-eef97142258d', 'ctime': '1499885619',
> 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize':
> '110729625600', 'children': [], 'pool': '', 'capacity': '107374182400',
> 'uuid': u'0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', 'truesize': '110729625600',
> 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}} (volume:272)
> 2017-07-12 14:24:50,037-0700 INFO  (jsonrpc/1) [vdsm.api] FINISH
> getVolumeInfo return={'info': {'status': 'OK', 'domain':
> '0c02a758-4295-4199-97de-b041744b3b15', 'voltype': 'LEAF', 'description':
> '', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW',
> 'generation': 0, 'image': '6a887015-67cd-4f7b-b709-eef97142258d', 'ctime':
> '1499885619', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0',
> 'apparentsize': '110729625600', 'children': [], 'pool': '', 'capacity':
> '107374182400', 'uuid': u'0c3de1a8-ac18-4d7b-b348-3b097bf0a0ae', 'truesize':
> '110729625600', 'type': 'SPARSE', 'lease': {'owners': [], 'version': None}}}
> from=::ffff:10.4.64.7,59664, flow_id=c5e4bda4-9cd3-461d-8164-51d5614b995e
> (api:52)
>
> HELP, Right now I am starting to think Block Storage and oVIRT = BAD!
>
>
>
>
> --
>
> Devin Acosta
> Red Hat Certified Architect, LinuxStack
>
>
>
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
>