Bug 809728

Summary:

[ovirt] [engine-core] VM chain corruption when suspending vm and taking live snapshot

Product:

[Retired] oVirt

Reporter:

Haim <hateya>

Component:

ovirt-engine-core

Assignee:

lpeer <lpeer>

Status:

CLOSED WONTFIX

QA Contact:

Severity:

high

Docs Contact:

Priority:

unspecified

Version:

unspecified

CC:

abaron, acathrow, amureini, dyasny, fsimonce, hateya, iheim, knesenko, mgoldboi, yeylon, ykaul

Target Milestone:

---

Target Release:

3.3.4

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

storage

Fixed In Version:

Doc Type:

Bug Fix

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2012-12-12 07:33:34 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

Storage

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
engine log.	none

Description Haim 2012-04-04 08:31:37 UTC

Description of problem:

- vm is running 
- suspend (hibernate) vm && take snapshot
- vm is suspended 
- restore vm, get the following error:


Thread-242::ERROR::2012-04-04 11:20:40,821::image::344::Storage.Image::(getChain) There is no leaf in the image 540d59cc-744e-4d1a-8dc4-f0c436b180be
Thread-242::ERROR::2012-04-04 11:20:40,821::task::853::TaskManager.Task::(_setError) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 861, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2667, in prepareImage
    imgVolumes = img.prepare(sdUUID, imgUUID, volUUID)
  File "/usr/share/vdsm/storage/image.py", line 374, in prepare
    chain = self.getChain(sdUUID, imgUUID, volUUID)
  File "/usr/share/vdsm/storage/image.py", line 345, in getChain
    raise se.ImageIsNotLegalChain(imgUUID)
ImageIsNotLegalChain: Image is not a legal chain: ('540d59cc-744e-4d1a-8dc4-f0c436b180be',)
Thread-242::DEBUG::2012-04-04 11:20:40,823::task::872::TaskManager.Task::(_run) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::Task._run: 72372de9-f077-4630-b3e2-117a8ecf2383 ('610da315-59ee-4058-ba7e-f81df40bfbad', '552256b8-3266-4930-9d
13-f9c7ff636f35', '540d59cc-744e-4d1a-8dc4-f0c436b180be', '33306a6a-bcc3-4ada-b621-64c0550ece93') {} failed - stopping task
Thread-242::DEBUG::2012-04-04 11:20:40,823::task::1199::TaskManager.Task::(stop) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::stopping in state preparing (force False)
Thread-242::DEBUG::2012-04-04 11:20:40,823::task::978::TaskManager.Task::(_decref) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::ref 1 aborting True
Thread-242::INFO::2012-04-04 11:20:40,824::task::1157::TaskManager.Task::(prepare) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::aborting: Task is aborted: 'Image is not a legal chain' - code 262
Thread-242::DEBUG::2012-04-04 11:20:40,824::task::1162::TaskManager.Task::(prepare) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::Prepare: aborted: Image is not a legal chain
Thread-242::DEBUG::2012-04-04 11:20:40,825::task::978::TaskManager.Task::(_decref) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::ref 0 aborting True
Thread-242::DEBUG::2012-04-04 11:20:40,825::task::913::TaskManager.Task::(_doAbort) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::Task._doAbort: force False
Thread-242::DEBUG::2012-04-04 11:20:40,826::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-242::DEBUG::2012-04-04 11:20:40,826::task::588::TaskManager.Task::(_updateState) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::moving from state preparing -> state aborting
Thread-242::DEBUG::2012-04-04 11:20:40,826::task::537::TaskManager.Task::(__state_aborting) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::_aborting: recover policy none
Thread-242::DEBUG::2012-04-04 11:20:40,827::task::588::TaskManager.Task::(_updateState) Task=`72372de9-f077-4630-b3e2-117a8ecf2383`::moving from state aborting -> state failed
Thread-242::DEBUG::2012-04-04 11:20:40,827::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.610da315-59ee-4058-ba7e-f81df40bfbad': < ResourceRef 'Storage.610da315-59ee-4058-ba7e
-f81df40bfbad', isValid: 'True' obj: 'None'>}
Thread-242::DEBUG::2012-04-04 11:20:40,828::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-242::DEBUG::2012-04-04 11:20:40,828::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.610da315-59ee-4058-ba7e-f81df40bfbad'
Thread-242::DEBUG::2012-04-04 11:20:40,829::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.610da315-59ee-4058-ba7e-f81df40bfbad' (0 active users)
Thread-242::DEBUG::2012-04-04 11:20:40,829::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.610da315-59ee-4058-ba7e-f81df40bfbad' is free, finding out if anyone is waiting for it.
Thread-242::DEBUG::2012-04-04 11:20:40,830::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.610da315-59ee-4058-ba7e-f81df40bfbad', Clearing records.
Thread-242::ERROR::2012-04-04 11:20:40,830::dispatcher::89::Storage.Dispatcher.Protect::(run) {'status': {'message': "Image is not a legal chain: ('540d59cc-744e-4d1a-8dc4-f0c436b180be',)", 'code': 262}}
Thread-242::DEBUG::2012-04-04 11:20:40,831::vm::577::vm.Vm::(_startUnderlyingVm) vmId=`9be88ad9-aff9-48a4-b425-9e6c940dc845`::_ongoingCreations released
Thread-242::ERROR::2012-04-04 11:20:40,831::vm::601::vm.Vm::(_startUnderlyingVm) vmId=`9be88ad9-aff9-48a4-b425-9e6c940dc845`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 567, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/libvirtvm.py", line 1250, in _run
    self.preparePaths(devices[vm.DISK_DEVICES])
  File "/usr/share/vdsm/vm.py", line 613, in preparePaths
    drive['path'] = self.cif.prepareVolumePath(drive, self.id)
  File "/usr/share/vdsm/clientIF.py", line 179, in prepareVolumePath
    raise vm.VolumeError(drive)
VolumeError: Bad volume specification {'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'needExtend': False, 'index': 0, 'iface': 'virtio', 'apparentsize': '1073741824', 'specPa
rams': {'deviceId': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}, 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b180be', 'readonly': 'False', 'truesize': '1073741824', 'type': 'disk', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'reqsize'
: '0', 'format': 'cow', 'poolID': '552256b8-3266-4930-9d13-f9c7ff636f35', 'device': 'disk', 'path': '/rhev/data-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4d1a-8dc4-f0c436b180be
/33306a6a-bcc3-4ada-b621-64c0550ece93', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vda', 'bootOrder': u'1', 'volumeID': '33306a6a-bcc3-4ada-b621-64c0550ece93', 'alias': u'virtio-disk0', 'volumeChain': [{'path': u'/rhev/dat
a-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4d1a-8dc4-f0c436b180be/a77ed95a-c87d-488d-a797-428126ae42da', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'volumeID': 'a77ed
95a-c87d-488d-a797-428126ae42da', 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}, {'path': '/rhev/data-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4d1a-8dc4-f0c436b180be/3330
6a6a-bcc3-4ada-b621-64c0550ece93', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'volumeID': '33306a6a-bcc3-4ada-b621-64c0550ece93', 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}]}
Thread-242::DEBUG::2012-04-04 11:20:40,836::vm::919::vm.Vm::(setDownStatus) vmId=`9be88ad9-aff9-48a4-b425-9e6c940dc845`::Changed state to Down: Bad volume specification {'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000
', u'type': u'pci', u'function': u'0x0'}, 'needExtend': False, 'index': 0, 'iface': 'virtio', 'apparentsize': '1073741824', 'specParams': {'deviceId': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}, 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b1
80be', 'readonly': 'False', 'truesize': '1073741824', 'type': 'disk', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'reqsize': '0', 'format': 'cow', 'poolID': '552256b8-3266-4930-9d13-f9c7ff636f35', 'device': 'disk', 'path': '/rhe
v/data-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4d1a-8dc4-f0c436b180be/33306a6a-bcc3-4ada-b621-64c0550ece93', 'propagateErrors': 'off', 'optional': 'false', 'name': u'vda', 'b
ootOrder': u'1', 'volumeID': '33306a6a-bcc3-4ada-b621-64c0550ece93', 'alias': u'virtio-disk0', 'volumeChain': [{'path': u'/rhev/data-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4
d1a-8dc4-f0c436b180be/a77ed95a-c87d-488d-a797-428126ae42da', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'volumeID': 'a77ed95a-c87d-488d-a797-428126ae42da', 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}, {'path': '/rhev/dat
a-center/552256b8-3266-4930-9d13-f9c7ff636f35/610da315-59ee-4058-ba7e-f81df40bfbad/images/540d59cc-744e-4d1a-8dc4-f0c436b180be/33306a6a-bcc3-4ada-b621-64c0550ece93', 'domainID': '610da315-59ee-4058-ba7e-f81df40bfbad', 'volumeID': '33306a6a-bcc3-4ada-b621-64c0550ece93', 'imageID': '540d59cc-744e-4d1a-8dc4-f0c436b180be'}]}


please block such attempts.

Comment 1 Haim 2012-04-04 08:34:58 UTC

Created attachment 575063 [details]
engine log.

Comment 2 Itamar Heim 2012-12-12 07:33:34 UTC

Closing old bugs. If this issue is still relevant/important in current version, please re-open the bug.