For the record, pstehlik helped me to "fix"/workaround the problem.

We did (roughly)  following:
* Check that disks are in state OK (not "locked"), i.e. only the VM state is stuck.

* Run /usr/share/ovirt-engine/scripts/dbutils/taskcleaner.sh -d engine -u engine
  Result was "(0 rows)"

* Open database on ovirt-engine:
  $ psql -d engine -U postgres

* Check which VMs are in state 15:
  SELECT vm_guid, status FROM vm_dynamic WHERE status = 15;

* Change state of the VMs to 0:
  UPDATE vm_dynamic SET status = 0 WHERE status = 15;

* COMMIT;

Now both VMs can start and revert to the snapshot works.

Yair, if you can please check the NPE in async tasks...seems the code is not there anymore in 3.3 so I suppose you did something about it:)

Is this 100% reproducible ?

No, it not 100% reproducible. It happens from time to time. One VM got stuck after ~ 12 reverts and the other after ~ 50 reverts.
Today it happened again with another set of machines. I let VMs in the stuck state so someone can investigate it.

This never happend with RHEV-M 3.2.0 and happened twice in the first week after upgrade to RHEV-M 3.2.3, so it seems like a regression. Feel free to ping me, I can provide you access to hypervisors.

A lot of refactoring has gone into Aync Task handling in 3.3. The code that is throwing the exception is now located in in CommandAsyncTask. I took a look a the code and the cause of the exception seems to be linked to handling end of commands by entity id. This has been refactored to be handled by command id in 3.3 so the above should not happen in 3.3.

(In reply to Petr Spacek from comment #1)
> For the record, pstehlik helped me to "fix"/workaround the problem.
> 
> We did (roughly)  following:
> * Check that disks are in state OK (not "locked"), i.e. only the VM state is
> stuck.
> 
> * Run /usr/share/ovirt-engine/scripts/dbutils/taskcleaner.sh -d engine -u
> engine
>   Result was "(0 rows)"
> 
> * Open database on ovirt-engine:
>   $ psql -d engine -U postgres
> 
> * Check which VMs are in state 15:
>   SELECT vm_guid, status FROM vm_dynamic WHERE status = 15;
> 
> * Change state of the VMs to 0:
>   UPDATE vm_dynamic SET status = 0 WHERE status = 15;
> 
> * COMMIT;
> 
> Now both VMs can start and revert to the snapshot works.

just a btw you should be able to use the unlock_entity utility instead of hacking the db.

Thank you. I use /usr/share/ovirt-engine/dbscripts/unlock_entity.sh -t vm -i $vmname , but I have to run it at least once a day.

I followed the following steps but am unable to reproduce the issue in 3.2.z and current master


1. Created two VMs and installed Fedora 18 on them
2. Create snapshot for each VM
3. Used command below to restore VMs from snapshot

curl -v -X POST -d @snapshot.xml -u admin@internal:letmein! -H "Accept: application/xml" -H "Content-Type: application/xml" http://127.0.0.1:8700/api/vms/xxxx/snapshots/xxxx/restore

where snapshot.xml is

<action>
</action>

4. I executed the above command simultaneously on the two VMs 500 times using shell script.

It took a few hours to run but every invocation of restore command completed successfully with out exceptions and the image is in OK status.

Please let me know if I a missing anything.

Looking at the log files this issue seems to be similar to the issue described in BZ 1015638.

Is seems fine, but it is a race condition, you know ...

Our workflow is like this:
1) Create VMs, install OS, create snapshot (you did that)
2) Run VM
3) Do some changes in the VM
4) Shutdown VM
5) Revert VM to the snapshort
6) Go to step (2)

All this (except point 1) is done by script, so revent follows the shutdown in very short time and so on.

Our hypervisor hosts 20-30 VMs at the same time.

Thank you for your time.

Petr,
Can you please describe your setup,
Specifically DCs/Clusters/Hosts
Storage ?
Did this happen also on other DCs?
Did this happen always on the same VMs ?
 

Ravi can you please verify check in the attached logs:
- Storage related issues during the described action
- whether the SPM changed during the revert ?
- were there any missing/disappearing tasks in engine (related to the actions 
  above).

Sure.

1 DC:
- IDM_LAB
1 cluster:
- IDM_LAB, compatibility version 3.2
2 hosts in the cluster:
- belka (RHEL 6.4.z - with lastest released updates)
- laika (RHEL 6.4.z - with lastest released updates)
4 storage domains:
- belka-vm1 - iSCSI
- laika-vm1 - iSCSI
- export - NFS
- iso-laika - NFS

We have only one DC, so I can't say if it would happen on the other DC or not.

It seems that it happens randomly on all VMs, but we do snapshot-revert only on subset of all VMs (on ~ 12 VMs from ~ 120 of total VMs).

As far as I remember it happened only with VMs from storage laika-vm1, but this is not very representative information. Only one VM from the whole subset is hosted on storage domain belka-vm1.

It seems that host on which VM was running before snapshot-revert operation doesn't make any difference.

Let me know if you want any other information.

Correcion: Today it happened again with VM stored on storage domain belka-vm1, so both storage domains are affected.

From the engine log file there is no storage related exceptions, spm re-election and no disappearing tasks.

Below are the exceptions from the log files attached. There is a 'Device or resource busy' exception thrown on vdsm just before an exception is thrown on the engine. Not sure what is causing the resource busy exception. Was there any recent change in network topology involving the hosts and the iSCSI storage?

Looking at the engine exception this looks like a race condition where the engine task is cleared before startPolling is called leading to NPE as described in this patch http://gerrit.ovirt.org/#/c/20183/

Exception in engine log

2013-10-17 12:20:04,032 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8702-7) [RestoreSnapshot] BaseAsyncTask::StartPollingTask: Starting to poll task b3d523c5-0762-4152-a04b-378d6cae39d3.
2013-10-17 12:20:04,053 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-7) Operation Failed: java.lang.NullPointerException: javax.ejb.EJBException: java.lang.NullPointerException
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInNoTx(CMTTxInterceptor.java:191) [jboss-as-ejb3.jar:7.2.1.Final-redhat-10]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:237) [jboss-as-ejb3.jar:7.2.1.Final-redhat-10]



Exception in vdsm log

Thread-2680::DEBUG::2013-10-17 12:20:00,627::task::579::TaskManager.Task::(_updateState) Task=`2753fc4f-a752-4f0c-b034-8ad05e317d79`::moving from state preparing -> state finished
Thread-2680::DEBUG::2013-10-17 12:20:00,628::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2680::DEBUG::2013-10-17 12:20:00,628::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2680::DEBUG::2013-10-17 12:20:00,628::task::974::TaskManager.Task::(_decref) Task=`2753fc4f-a752-4f0c-b034-8ad05e317d79`::ref 0 aborting False
89dae60e-0ca2-4023-b879-87736b81e29f::DEBUG::2013-10-17 12:20:00,913::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  device-mapper: remove ioctl on  failed: Device or resource busy\n  Unable to deactivate 8f72fe93--70a7--44cc--8566--7eec0c4bffea-925f6d7d--4feb--44d5--b352--ee19ed726a57 (253:25)\n'; <rc> = 5
89dae60e-0ca2-4023-b879-87736b81e29f::DEBUG::2013-10-17 12:20:00,928::lvm::501::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
89dae60e-0ca2-4023-b879-87736b81e29f::DEBUG::2013-10-17 12:20:00,928::lvm::513::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
89dae60e-0ca2-4023-b879-87736b81e29f::WARNING::2013-10-17 12:20:00,928::resourceFactories::61::Storage.ResourcesFactories::(close) Failure deactivate LV 8f72fe93-70a7-44cc-8566-7eec0c4bffea/925f6d7d-4feb-44d5-b352-ee19ed726a57 (Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  device-mapper: remove ioctl on  failed: Device or resource busy\', \'  device-mapper: remove ioctl on  failed: Device or resource busy\', Unable to deactivate 8f72fe93--70a7--44cc--8566--7eec0c4bffea-925f6d7d--4feb--44d5--b352--ee19ed726a57 (253:25)\']\\n8f72fe93-70a7-44cc-8566-7eec0c4bffea/[\'925f6d7d-4feb-44d5-b352-ee19ed726a57\']",)',))
89dae60e-0ca2-4023-b879-87736b81e29f::DEBUG::2013-10-17 12:20:00,929::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource '8f72fe93-70a7-44cc-8566-7eec0c4bffea_lvmActivationNS.925f6d7d-4feb-44d5-b352-ee19ed726a57', Clearing records.

(In reply to Ravi Nori from comment #20)
> Was there any recent change in network topology involving the hosts and the iSCSI storage?

The network and topology is the same for several months. As I said in bug description, the problem appeared first time after upgrade 3.2.3-0.43.el6ev. We fully upgraded both hypervisors at the same time, so everything is not latest RHE 6.4.z bits.

Hmm, one of VMs got stuck again (second time today) and I noticed that there are some stuck stasks on one of hypervisor:

# /usr/share/ovirt-engine/scripts/dbutils/taskcleaner.sh 
-[ RECORD 1 ]+-------------------------------------
task_id      | b59205fd-9e44-4425-963b-62bb62cf7b1a
task_type    | 4
status       | 2
started_at   | 2013-11-05 23:22:47.883+01
result       | 0
command_type | 224
command_id   | ab0874e4-9731-4ffa-a4ab-1116f21e13f5
step_id      | ccd812d8-f3ab-4b5a-bbfc-bea3a8cf66c4
dc           | 6163a491-b652-453d-9574-630503175cbe
-[ RECORD 2 ]+-------------------------------------
task_id      | bc52458a-0ecc-48b5-8a54-ca740d1a7f61
task_type    | 4
status       | 2
started_at   | 2013-11-05 22:09:45.909+01
result       | 0
command_type | 224
command_id   | a273d5f0-94eb-4610-9253-f333009ec757
step_id      | 0eda080e-0929-49b2-886f-6d8bbc0d4587
dc           | 6163a491-b652-453d-9574-630503175cbe
-[ RECORD 3 ]+-------------------------------------
task_id      | 4564c75a-22e4-4859-8b70-f4dca87ca6dc
task_type    | 4
status       | 2
started_at   | 2013-11-06 12:05:32.018+01
result       | 0
command_type | 224
command_id   | 0331b710-19e8-4e13-8ace-e164f11f8e07
step_id      | fe114cf1-62bf-4631-9b78-65ed63a44ced
dc           | 6163a491-b652-453d-9574-630503175cbe
-[ RECORD 4 ]+-------------------------------------
task_id      | bdd42c87-694f-4c77-9eb8-489245589d4d
task_type    | 4
status       | 2
started_at   | 2013-11-04 23:22:39.925+01
result       | 0
command_type | 224
command_id   | f6325304-27a5-431b-9737-c9cf3dd7d447
step_id      | 1721c866-fb42-42ac-b3b6-1737f14b46a8
dc           | 6163a491-b652-453d-9574-630503175cbe

[root@laika ~]# vdsClient -s localhost getAllTasksStatuses
{'status': {'message': 'OK', 'code': 0}, 'allTasksStatus': {'4564c75a-22e4-4859-8b70-f4dca87ca6dc': {'message': '1 jobs completed successfully', 'code': 0, 'taskID': '4564c75a-22e4-4859-8b70-f4dca87ca6dc', 'taskResult': 'success', 'taskState': 'finished'}, 'b59205fd-9e44-4425-963b-62bb62cf7b1a': {'message': '1 jobs completed successfully', 'code': 0, 'taskID': 'b59205fd-9e44-4425-963b-62bb62cf7b1a', 'taskResult': 'success', 'taskState': 'finished'}, 'bc52458a-0ecc-48b5-8a54-ca740d1a7f61': {'message': '1 jobs completed successfully', 'code': 0, 'taskID': 'bc52458a-0ecc-48b5-8a54-ca740d1a7f61', 'taskResult': 'success', 'taskState': 'finished'}}}

Eduardo, Saggi,

Can you please take a look into the vdsm error in comment #20.

- What could be the problem in this specific use case ?
- What are the implications on the task itself ? could it disappear from 
  reported tasks ()by vdsm) ?

Hi guys,

it is more than two weeks from last update. Can I help you in any way?

Today I noticed that VDSM on the hypervisors spits some suspicious messages:

Nov 20 10:42:47 belka vdsm vm.Vm WARNING vmId=`695360f0-36f0-41d5-aae0-7707753985e8`::Unknown type found, device: '{'device': u'spicevmc', 'alias': u'channel2', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}' found
Nov 20 10:52:05 belka vdsm vm.Vm WARNING vmId=`7e2b0467-72c9-49ca-9778-969e6d414060`::_readPauseCode unsupported by libvirt vm
Nov 20 10:52:27 belka <BF><11>vdsm vm.Vm ERROR vmId=`7e2b0467-72c9-49ca-9778-969e6d414060`::Unknown message type fqdn

vmId 7e2b0467-72c9-49ca-9778-969e6d414060 == VM name pviktori-z-ci-f19-test4

VDSM and libvirt are on latest and greatest versions from RHEL-6.4.z.

(In reply to Barak from comment #23)
> Eduardo, Saggi,
> 
> Can you please take a look into the vdsm error in comment #20.
> 
> - What could be the problem in this specific use case ?
> - What are the implications on the task itself ? could it disappear from 
>   reported tasks ()by vdsm) ?

12:20:00,913::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  device-mapper: remove ioctl on  failed: Device or resource busy\n  Unable to deactivate 8f72fe93--70a7--44cc--8566--7eec0c4bffea-925f6d7d--4feb--44d5--b352--ee19ed726a57 (253:25)\n'; <rc> = 5


The volume 8f72fe93-70a7-44cc-8566-7eec0c4bffea/925f6d7d-4feb-44d5-b352-ee19ed726a57 is still open when is deactivated, failing the operation.
Need to ellucidate which process is holding an open fd on it.
The failed deactivation is forgiven, but this is a different error.

(In reply to Petr Spacek from comment #16)
> Is seems fine, but it is a race condition, you know ...
> 
> Our workflow is like this:
> 1) Create VMs, install OS, create snapshot (you did that)
> 2) Run VM
> 3) Do some changes in the VM
> 4) Shutdown VM
> 5) Revert VM to the snapshort

When you say revert vm from snapshot , 
- does it involve deletion of snapshot ? does it include post zero ?
- Or preview ?


> 6) Go to step (2)
> 
> All this (except point 1) is done by script, so revent follows the shutdown
> in very short time and so on.

meaning using the rest API ?
Can you post the script ?


> 
> Our hypervisor hosts 20-30 VMs at the same time.
> 
> Thank you for your time.

Created attachment 826726 [details]
python reset-vm-to-snapshot pviktori-z-ci-host1 remote-host

We use attached script for reverts. It would be best to check the script, I could mangle RHEV-M terminology.

The script author has nick "pviktori", so please direct any questions about the script to him.

We call the script like "python reset-vm-to-snapshot.py pviktori-z-ci-host1 remote-host".

The deactivation error means that a process has an open FD to the volume so it can't be deactivated.

The underlying issue is the same as the issue in BZ 1015638

We are running into a Race Condition when restoring VM from snapshot and the fix for the above mentioned bug fixes the issue reported.

*** This bug has been marked as a duplicate of bug 1015638 ***

I confirm that rhevm-3.2.5-0.49.el6ev.src.rpm fixed the problem for us, so yes - it is really a duplicate.