Bug 1588698 - Commit snapshot-preview fails with Error while executing action Revert to snapshot: Internal engine error
Summary: Commit snapshot-preview fails with Error while executing action Revert to sna...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: Backend.Core
Version: 4.2.4.1
Hardware: x86_64
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.2.5
: ---
Assignee: Eyal Shenitzky
QA Contact: Shir Fishbain
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-06-07 18:08 UTC by Shir Fishbain
Modified: 2018-07-31 15:29 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-07-31 15:29:27 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.2+


Attachments (Terms of Use)
Attachments (1.72 MB, application/zip)
2018-06-07 18:08 UTC, Shir Fishbain
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 92364 0 master MERGED core: fix DB deadlock while commiting a snapshot 2018-07-02 07:43:57 UTC
oVirt gerrit 92729 0 ovirt-engine-4.2 MERGED core: fix DB deadlock while commiting a snapshot 2018-07-02 10:09:07 UTC

Description Shir Fishbain 2018-06-07 18:08:13 UTC
Created attachment 1448809 [details]
Attachments

Description of problem:
When trying to perform a commit to a snapshot preview we get the following error message in web admin:
"Error while executing action Revert to snapshot: Internal engine error".
Events tab (image attached) shows that the commit failed and around 20 seconds later it shows that the operation succeeds. 
The VM remains in preview-snapshot mode and Undo and Commit operations are still available.
The volumes outputs for every step (looks legit).

Version-Release number of selected component (if applicable):
4.2.4.1-0.1.e

How reproducible:
100%

Steps to Reproduce:
1. Create a VM from a template, and attach a pre-allocated disk to it.
2. Create a snapshot.
3. Start VM and create a live snapshot.
4. Stop the VM.
5. Preview first snapshot
6. Commit the first snapshot

Actual results:
1. Error in web admin:
"Error while executing action Revert to snapshot: Internal engine error".
2. Events tab shows that the commit failed and around 20 seconds later it shows that the operation succeeds. 
Jun 7, 2018, 5:23:53 PM Committing a Snapshot-Preview for VM ShirVM2 has been completed.
Jun 7, 2018, 5:23:37 PM Failed to commit Snapshot-Preview for VM ShirVM2.
3. The VM remains in preview-snapshot mode and Undo and Commit operations are still available.
4. The following errors in the engine.log:
engine log after first commit attempt:

2018-06-07 17:23:36,934+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreFromSnapshotCommand] (Transaction Reaper Worker 0) [] Transaction rolled-back for command 'org.ovirt.engine.core.bll.snapshots.RestoreFromSnapshotCommand'.

2018-06-07 17:23:36,936+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-106601) [] SPMAsyncTask::StopTask: Error during stopping task 'd9995602-7176-4050-8092-26b8627d727a': WFLYWELD0039: Singleton not set for ModuleClassLoader for Module "org.jboss.as.transactions" from local module loader @7b1d7fff (finder: local module finder @299a06ac (roots: /usr/share/ovirt-engine/modules/common,/usr/share/ovirt-engine-extension-aaa-jdbc/modules,/usr/share/ovirt-engine-extension-aaa-ldap/modules,/opt/rh/eap7/root/usr/share/wildfly/modules,/opt/rh/eap7/root/usr/share/wildfly/modules/system/layers/base)). This means that you are trying to access a weld deployment with a Thread Context ClassLoader that is not associated with the deployment.

2018-06-07 17:23:37,080+03 ERROR [org.ovirt.engine.core.bll.job.ExecutionHandler] (default task-7) [287beb16] Exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@3f6ef092[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@4b0322bc connection handles=0 lastReturned=1528381417046 lastValidated=1528381113950 lastCheckedOut=1528381116930 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1f2510bd mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@727ab8a2[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@b669e9e[connectionListener=3f6ef092 connectionManager=6912e60f warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null]

2018-06-07 17:23:37,185+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-7) [287beb16] Failed to remove memory of snapshot '7e404501-dfbb-4067-92ae-aca7dd80d239'

2018-06-07 17:23:37,203+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-7) [287beb16] Command 'org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand' failed: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@3f6ef092[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@4b0322bc connection handles=0 lastReturned=1528381417185 lastValidated=1528381113950 lastCheckedOut=1528381116930 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1f2510bd mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@727ab8a2[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@b669e9e[connectionListener=3f6ef092 connectionManager=6912e60f warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null]

2018-06-07 17:23:37,324+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-7) [287beb16] EVENT_ID: USER_COMMIT_RESTORE_FROM_SNAPSHOT_FINISH_FAILURE(96), Failed to commit Snapshot-Preview for VM ShirVM2.

2018-06-07 17:23:53,069+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-70) [a0d5f6ce-c0ef-4d63-afb7-70da55c93a70] Ending command 'org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand' with failure.

Second commit attempt causes the following:
2018-06-07 19:05:37,507+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-16) [cb9004dd-9150-415f-ad84-091750bbda23] Command 'org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand' failed: null

2018-06-07 19:05:37,507+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-16) [cb9004dd-9150-415f-ad84-091750bbda23] Exception: java.lang.NullPointerException


Expected results:
For the commit to succeed without any errors.

Additional info:
When performing the same scenario and writing to the disks there are no errors and the commit operation succeeds.

Comment 1 Eyal Shenitzky 2018-06-14 08:47:48 UTC
More specific steps to reproduce:

1) Create a VM with a disk (file/block-base)
2) Create a snapshot 
3) Run the VM
4) Create live snapshot with memory
5) Stop the VM
6) Preview the first snapshot from step 2
7) Commit the snapshot

Comment 2 Shir Fishbain 2018-07-08 14:11:36 UTC
There are no errors and the commit operation succeeds.
4.2.5.1_SNAPSHOT-72.g1639ffa.0.scratch.master.el7ev

Comment 3 Sandro Bonazzola 2018-07-31 15:29:27 UTC
This bugzilla is included in oVirt 4.2.5 release, published on July 30th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.5 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.