Bug 1316853 - Cloning a VM from a cloned cinder disk results in a locked image status
Summary: Cloning a VM from a cloned cinder disk results in a locked image status
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: Frontend.WebAdmin
Version: 3.6.3.3
Hardware: Unspecified
OS: Unspecified
medium
high
Target Milestone: ovirt-3.6.6
: 3.6.6
Assignee: Maor
QA Contact: Aharon Canan
URL:
Whiteboard:
: 1316851 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-03-11 10:11 UTC by Darryl Bond
Modified: 2016-06-27 07:37 UTC (History)
10 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2016-05-30 10:54:20 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-3.6.z+
ylavi: planning_ack+
tnisan: devel_ack+
rule-engine: testing_ack+

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1293644 0 unspecified CLOSED commands with mixed children types (CoCo/AsyncTasks) don't converge 2021-02-22 00:41:40 UTC
oVirt gerrit 56305 0 master MERGED core: Add cinder call back for AddVmFromSnapshot. 2016-04-20 19:17:12 UTC
oVirt gerrit 56440 0 ovirt-engine-3.6 MERGED core: Add cinder call back for AddVmFromSnapshot. 2016-04-21 09:11:41 UTC

Internal Links: 1293644

Description Darryl Bond 2016-03-11 10:11:43 UTC 
Description of problem:
A VM cloned from a ceph cinder snapshot stays in the Image Locked status forever


Version-Release number of selected component (if applicable):
oVirt Engine Version: 3.6.3.4-1.el7.centos

How reproducible: Very


Steps to Reproduce:
1. Create a snapshot from a Cinder VM
2. Clone the snapshot to a new VM
3. Attempt to run the VM

Actual results:
VM status remains 'Image Locked' forever. VM cannot start, 'Run' menu is greyed out.

Expected results:
VM starts successfully


Additional info:
This used to work when I last tested it on 3.6.0
Comment 1 Darryl Bond 2016-03-11 10:21:27 UTC 
An engine restart unlocks the image and it can be run.
I restarted the engine by running engine-setup and there was a gluster update queued.
Comment 2 Maor 2016-03-13 09:54:10 UTC 
Hi Darryl, 
can you please attach the engine and cinder logs.

Thanks,
Maor
Comment 3 Darryl Bond 2016-03-14 09:49:30 UTC 
Cloned from a snapshot: 
Volume is still locked (according to the GUI) 5 minutes later

Engine log

2016-03-14 19:41:56,124 INFO  [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-3) [373a5697] Lock Acquired to object 'EngineLock:{exclusiveLocks='[83b1e131-f190-488c-a4a0-bbcf1c4ec3e4=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>, Fromreality2=<VM_NAME, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
2016-03-14 19:42:02,096 INFO  [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-3) [] Running command: AddVmFromSnapshotCommand internal: false. Entities affected :  ID: 00000002-0002-0002-0002-000000000061 Type: VdsGroupsAction group CREATE_VM with role type USER,  ID: d3bb0bc0-4b7a-413a-a348-00ec408f018d Type: StorageAction group CREATE_DISK with role type USER,  ID: 00000002-0002-0002-0002-000000000061 Type: VdsGroupsAction group CHANGE_VM_CUSTOM_PROPERTIES with role type ADMIN,  ID: 83b1e131-f190-488c-a4a0-bbcf1c4ec3e4 Type: VMAction group CREATE_VM with role type USER
2016-03-14 19:42:02,416 INFO  [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-3) [] Locking VM(id = 'dfde7fb9-93da-4c39-b309-cbdfa37a0c03') with compensation.
2016-03-14 19:42:02,422 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-3) [] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{runAsync='true', vmId='dfde7fb9-93da-4c39-b309-cbdfa37a0c03', status='ImageLocked', exitStatus='Normal'}), log id: 1d508313
2016-03-14 19:42:02,430 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-3) [] FINISH, SetVmStatusVDSCommand, log id: 1d508313
2016-03-14 19:42:02,468 INFO  [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-3) [] Lock freed to object 'EngineLock:{exclusiveLocks='[83b1e131-f190-488c-a4a0-bbcf1c4ec3e4=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>, Fromreality2=<VM_NAME, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
2016-03-14 19:42:02,717 INFO  [org.ovirt.engine.core.bll.storage.CloneCinderDisksCommand] (pool-7-thread-1) [48df8629] Running command: CloneCinderDisksCommand internal: true.
2016-03-14 19:42:02,865 INFO  [org.ovirt.engine.core.bll.storage.CloneSingleCinderDiskCommand] (pool-7-thread-2) [4f68ff15] Running command: CloneSingleCinderDiskCommand internal: true. 
Entities affected :  ID: d3bb0bc0-4b7a-413a-a348-00ec408f018d Type: StorageAction group CONFIGURE_VM_STORAGE with role type USER
2016-03-14 19:42:06,482 INFO  [org.ovirt.engine.core.bll.AddGraphicsDeviceCommand] (default task-3) [6d771882] Running command: AddGraphicsDeviceCommand internal: true. Entities affected :  ID: dfde7fb9-93da-4c39-b309-cbdfa37a0c03 Type: VMAction group EDIT_VM_PROPERTIES with role type USER
2016-03-14 19:42:06,672 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-3) [6d771882] Correlation ID: 373a5697, Job ID: 0722b05a-6357-4f22-ae53-f9e37ca991c2, Call Stack: null, Custom Event ID: -1, Message: VM Fromreality2 was created by dbond@gps.
2016-03-14 19:42:10,476 INFO  [org.ovirt.engine.core.bll.storage.CloneCinderDisksCommandCallback] (DefaultQuartzScheduler_Worker-56) [48df8629] All CloneCinderDisksCommandCallback commands have completed, status 'SUCCEEDED'
2016-03-14 19:42:11,513 INFO  [org.ovirt.engine.core.bll.storage.CloneSingleCinderDiskCommand] (DefaultQuartzScheduler_Worker-98) [] Ending command 'org.ovirt.engine.core.bll.storage.CloneSingleCinderDiskCommand' successfully.
2016-03-14 19:42:11,545 INFO  [org.ovirt.engine.core.bll.storage.CloneCinderDisksCommand] (DefaultQuartzScheduler_Worker-98) [48df8629] Ending command 'org.ovirt.engine.core.bll.storage.CloneCinderDisksCommand' successfully.


Cinder 
cat volume.log
2016-03-14 19:42:06.213 4389 INFO cinder.volume.flows.manager.create_volume [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Volume 1db11353-c233-4c84-ba42-a0e33c66c6ac: being created as snap with specification: {'status': u'creating', 'volume_size': 8, 'volume_name': u'volume-1db11353-c233-4c84-ba42-a0e33c66c6ac', 'snapshot_id': u'b1197478-201b-4678-b658-9931c6f3baa0'}
2016-03-14 19:42:07.141 4389 INFO cinder.volume.flows.manager.create_volume [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Volume volume-1db11353-c233-4c84-ba42-a0e33c66c6ac (1db11353-c233-4c84-ba42-a0e33c66c6ac): created successfully
2016-03-14 19:42:07.150 4389 INFO cinder.volume.manager [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Created volume successfully.


cat api.log
2016-03-14 19:42:01.932 4312 INFO cinder.api.openstack.wsgi [req-f7d1dc71-0c79-477b-95dc-0bb13e66187e 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] GET http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/limits
2016-03-14 19:42:02.021 4312 INFO cinder.api.openstack.wsgi [req-6d96f281-90ff-4a44-a018-6327cebf0a04 - - - - -] http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/limits returned with HTTP 200
2016-03-14 19:42:02.022 4312 INFO eventlet.wsgi.server [req-6d96f281-90ff-4a44-a018-6327cebf0a04 - - - - -] 10.4.14.53 - - [14/Mar/2016 19:42:02] "GET /v2/675b5da21dc546b290ece9ab5430cc37//limits HTTP/1.1" 200 589 3.699379
2016-03-14 19:42:04.883 4313 INFO cinder.api.openstack.wsgi [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] POST http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/volumes
2016-03-14 19:42:04.972 4313 INFO cinder.volume.api [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Snapshot retrieved successfully.
2016-03-14 19:42:04.973 4313 INFO cinder.api.v2.volumes [req-42b26a0f-51ab-4c37-a37e-1fbefbc860a4 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Create volume of 8 GB
2016-03-14 19:42:04.986 4313 INFO cinder.volume.api [req-f2cc7872-3f8d-4d27-8a89-d2424df78f77 - - - - -] Availability Zones retrieved successfully.
2016-03-14 19:42:05.835 4313 INFO cinder.volume.api [req-7a0c4603-d763-4283-8248-72fef80a8acb - - - - -] Volume created successfully.
2016-03-14 19:42:05.837 4313 INFO cinder.api.openstack.wsgi [req-7a0c4603-d763-4283-8248-72fef80a8acb - - - - -] http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/volumes returned with HTTP 202
2016-03-14 19:42:05.841 4313 INFO eventlet.wsgi.server [req-7a0c4603-d763-4283-8248-72fef80a8acb - - - - -] 10.4.14.53 - - [14/Mar/2016 19:42:05] "POST /v2/675b5da21dc546b290ece9ab5430cc37//volumes HTTP/1.1" 202 1098 1.196832
2016-03-14 19:42:09.774 4313 INFO cinder.api.openstack.wsgi [req-d843f8a2-62ef-47df-9fd7-4a109f444152 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] GET http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/volumes/1db11353-c233-4c84-ba42-a0e33c66c6ac
2016-03-14 19:42:10.155 4313 INFO cinder.volume.api [req-d843f8a2-62ef-47df-9fd7-4a109f444152 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] Volume info retrieved successfully.
2016-03-14 19:42:10.382 4313 INFO cinder.api.openstack.wsgi [req-d843f8a2-62ef-47df-9fd7-4a109f444152 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] http://ovirtcinder:8776/v2/675b5da21dc546b290ece9ab5430cc37/volumes/1db11353-c233-4c84-ba42-a0e33c66c6ac returned with HTTP 200
2016-03-14 19:42:10.384 4313 INFO eventlet.wsgi.server [req-d843f8a2-62ef-47df-9fd7-4a109f444152 7ac5c54795c9406dbf4df153f09e4d29 675b5da21dc546b290ece9ab5430cc37 - - -] 10.4.14.53 - - [14/Mar/2016 19:42:10] "GET /v2/675b5da21dc546b290ece9ab5430cc37//volumes/1db11353-c233-4c84-ba42-a0e33c66c6ac HTTP/1.1" 200 1385 0.784611
Comment 4 Darryl Bond 2016-03-23 21:07:19 UTC 
*** Bug 1316851 has been marked as a duplicate of this bug. ***
Comment 5 Allon Mureinik 2016-04-14 09:04:26 UTC 
Maor/Daniel - isn't this a private case of bug 1293644?
Comment 6 Darryl Bond 2016-04-14 21:26:45 UTC 
Maybe, but 
/usr/share/ovirt-engine/setup/dbutils/unlock_entity.sh -s $ENGINE_DB_HOST -u $ENGINE_DB_USER -d $ENGINE_DB_DATABASE -t vm VM_name
Removes the lock and the Vm can be started.
Comment 7 Aharon Canan 2016-05-05 08:42:39 UTC 
Do we really want to fix cinder bugs in zstream? 
Is it tech preview feature for 3.6 ...
Comment 8 Yaniv Lavi 2016-05-05 09:03:52 UTC 
(In reply to Aharon Canan from comment #7)
> Do we really want to fix cinder bugs in zstream? 
> Is it tech preview feature for 3.6 ...

Yes, we have people using it in oVirt and we fix bugs even for tech previews.
Comment 9 Ori Gofen 2016-05-19 16:32:08 UTC 
Verified
Comment 10 Darryl Bond 2016-05-20 04:35:25 UTC 
Interesting test case on 3.5.5:
1. Create VM with cinder disk
2. Stop and snapshot (1)
3. Add another cinder disk
4. Snapshot VM with extra disk (2)
5. Boot the VM and confirm extra disk exists then shut down
6. Snapshot the VM without the extra disk (3) with the snapshot dialog
7. Delete snapshot 2
8. Delete the extra disk
Outcome: Disk remains locked even though there is no snapshot existing that uses it.
Hopefully the fix covers this case as well.
Note You need to log in before you can comment on or make changes to this bug.