+++ This bug was initially created as a clone of Bug #1264677 +++
Description of problem:
This bug was initially found during cinder/ceph manual testing and was opened to storage as a cinder bug (bz #1252958) but didn't reproduce on ovirt-master-3.6 build on fedora21.
The best way to reproduce this bug is to create a template from a vm with a cinder disk(ceph backend) on a rhevm engine (over rhel6.6/7), the operation gets stuck and then fails on timed out.
This happens only on RHEVM builds on rhel6.6/6.7 (jboss eap 6.4.z), rhevm's code is exactly the same as oVirt and the behaviour differs when the code reaches:
" buildCinderChildCommandParameters(cinderDisks, getVmSnapshotId()),
cloneContextAndDetachFromParent(),
CINDERStorageHelper.getStorageEntities(cinderDisks));
try {
>>>>>>>>>>> VdcReturnValueBase vdcReturnValueBase = future.get();
if (vdcReturnValueBase.getSucceeded()) {
Map<Guid, Guid> diskImageMap = vdcReturnValueBase.getActionReturnValue();
srcDeviceIdToTargetDeviceIdMapping.putAll(diskImageMap);
} else {"
the part when it calls future.get() java concurrent interface.
Version-Release number of selected component (if applicable):
rhevm 3.6-13
How reproducible:
100%
Steps to Reproduce:
1.create a template from a vm with a cinder disk
Actual results:
operation fails after it gets timed out
Expected results:
operation successful
Additional info:
* attachments are found at bz #1252958
--- Additional comment from Daniel Erez on 2015-09-20 10:40:53 EDT ---
Hi Ravi,
The mentioned code is located at 'AddVmTemplateCommand -> addVmTemplateCinderDisks()', and is invoked from within a transaction. Perhaps there's an issue with Future's get() and transactions on JBoss EAP?
Thanks!
--- Additional comment from Piotr Kliczewski on 2015-09-20 12:41:40 EDT ---
Please provide engine log with debug level and corresponding vdsm log.
--- Additional comment from Oved Ourfali on 2015-09-20 12:59:45 EDT ---
Also, please describe the flow, as I see future objects being used there both to get a return value from running async engine commands, and probably also VDSM ones.
Also, please verify you run using the exact same version (engine+vdsm), both in jboss EAP and wildfly versions, as I find it hard to believe it is related to that.
--- Additional comment from Daniel Erez on 2015-09-20 13:13:33 EDT ---
(In reply to Oved Ourfali from comment #3)
> Also, please describe the flow, as I see future objects being used there
> both to get a return value from running async engine commands, and probably
> also VDSM ones.
>
The relevant flow consists of a VM with a single Cinder disk (i.e. no VDSM tasks, only CoCo). The flow is as follows: AddVmTemplateCommand -> executeCommand() -> addVmTemplateCinderDisks method (inside a transaction) -> Future 'VdcActionType.CloneCinderDisks' -> stuck on future.get().
> Also, please verify you run using the exact same version (engine+vdsm), both
> in jboss EAP and wildfly versions, as I find it hard to believe it is
> related to that.
It was just a guess.. As the same scenario works correctly in oVirt stable (and not in RHEV 3.6 beta), so it could be any other difference (DB version/jboss/java/etc).
@Ori - can you please attach the logs with debug level.. (https://bugzilla.redhat.com/show_bug.cgi?id=1264677#c2)
--- Additional comment from Oved Ourfali on 2015-09-20 13:22:20 EDT ---
But there was no difference between latest upstream and downstream builds?
Also, we will also need a cinder instance to work with. Can you send its details offline?
--- Additional comment from Moti Asayag on 2015-09-20 13:40:36 EDT ---
By examining the log, it is shown that the duration of the command exceeds 10 minutes:
Start:
2015-08-30 15:54:41,331 INFO [org.ovirt.engine.core.bll.AddVmTemplateCommand] (ajp-/127.0.0.1:8702-9) [4566b62d] Running command: AddVmTemplateCommand internal: false. Entities affected : ID: 00000001-0001-0001-0001-00000000033a Type: StoragePoolAction group CREATE_TEMPLATE with role type USER
End:
2015-08-30 16:04:42,758 ERROR [org.ovirt.engine.core.bll.AddVmTemplateCommand] (ajp-/127.0.0.1:8702-9) [] Command 'org.ovirt.engine.core.bll.AddVmTemplateCommand' failed: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction
...
Caused by: javax.resource.ResourceException: IJ000459: Transaction is not active:
And this makes sense since the default timeout of engine's transaction is 600 seconds:
<coordinator-environment default-timeout="600"/>
I think it makes perfect sense to re-shape that command and exclude the template/disks creation part from the transaction in AddVmTemplateCommand.executeCommand().
It might be that on the environment where the scenario worked - the command didn't face the transaction timeout (better connectivity/smaller disk or other reason for not hitting timeout).
--- Additional comment from Daniel Erez on 2015-09-20 13:52 EDT ---
--- Additional comment from Daniel Erez on 2015-09-20 13:52 EDT ---
--- Additional comment from Daniel Erez on 2015-09-20 13:53:37 EDT ---
Attached are logs from my env.
--- Additional comment from Daniel Erez on 2015-09-20 13:57:36 EDT ---
(In reply to Moti Asayag from comment #6)
> By examining the log, it is shown that the duration of the command exceeds
> 10 minutes:
>
> Start:
> 2015-08-30 15:54:41,331 INFO
> [org.ovirt.engine.core.bll.AddVmTemplateCommand] (ajp-/127.0.0.1:8702-9)
> [4566b62d] Running command: AddVmTemplateCommand internal: false. Entities
> affected : ID: 00000001-0001-0001-0001-00000000033a Type: StoragePoolAction
> group CREATE_TEMPLATE with role type USER
>
>
> End:
>
> 2015-08-30 16:04:42,758 ERROR
> [org.ovirt.engine.core.bll.AddVmTemplateCommand] (ajp-/127.0.0.1:8702-9) []
> Command 'org.ovirt.engine.core.bll.AddVmTemplateCommand' failed: Could not
> get JDBC Connection; nested exception is java.sql.SQLException:
> javax.resource.ResourceException: IJ000460: Error checking for a transaction
> ...
> Caused by: javax.resource.ResourceException: IJ000459: Transaction is not
> active:
>
>
> And this makes sense since the default timeout of engine's transaction is
> 600 seconds:
> <coordinator-environment default-timeout="600"/>
>
> I think it makes perfect sense to re-shape that command and exclude the
> template/disks creation part from the transaction in
> AddVmTemplateCommand.executeCommand().
>
> It might be that on the environment where the scenario worked - the command
> didn't face the transaction timeout (better connectivity/smaller disk or
> other reason for not hitting timeout).
Yeah, thought about that as well. However, the timeout repeats constantly on multiple rhev environments. Whereas, works constantly on multiple oVirt envs...
--- Additional comment from Daniel Erez on 2015-09-20 14:05:06 EDT ---
(In reply to Oved Ourfali from comment #5)
> But there was no difference between latest upstream and downstream builds?
>
> Also, we will also need a cinder instance to work with. Can you send its
> details offline?
Sure, I'll send it offline by request. Ori has one as well if needed.
--- Additional comment from Oved Ourfali on 2015-09-20 14:15:51 EDT ---
Based on Moti's comment, and offline discussion, moving to storage to consider applying Moti's suggestion, and check whether it solves the issue.
(In reply to Oved Ourfali from comment #1)
> Daniel - please run your development environment with wildfly, and then with
> EAP, and report back on your findings.
Same issue in oVirt (with wildfly) on el6. So the problem is somewhere else.
The described scenario was debugged and raised a lock on db access as a result of the following:
Thread A ---- Transaction 1 open
|
Thread B ------ Transaction 2 open
Thread A (AddVmTemplate) opens new transaction. Within that transaction, it submit an async command (by coco):
1. Suspend current transaction
2. Save command (internally attempts to suspend transaction again)
3. Resume transaction
4. Submit command to Thread B
5. Block on Thread B
Thread B is locked on DB (on command_entities table). The lock ends while the open transaction of Thread A is timed-out.
By excluding the submission of thread B from the transaction - the issue was solved.