Description of problem: When a VM had multiple snapshots, the removal of them failed with engine error: 018-05-30 14:54:57,199+03 ERROR [org.ovirt.engine.core.bll.snapshots.ColdMergeSnapshotSingleDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [8b8b24c6-88cc-45e2-b808-a9699df3f8d8] Command 'ColdMergeSnapshotSingleDisk' id 'c43075d4-0305-4fad-8140-fc5243226fd9' failed executing step 'PREPARE_MERGE' 2018-05-30 14:54:57,199+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [8b8b24c6-88cc-45e2-b808-a9699df3f8d8] Command 'ColdMergeSnapshotSingleDisk' id: 'c43075d4-0305-4fad-8140-fc5243226fd9' child commands '[6b67db9b-f83f-4256-8157-16612cdb0828]' executions were completed, status 'FAILED' 2018-05-30 14:54:58,217+03 ERROR [org.ovirt.engine.core.bll.snapshots.ColdMergeSnapshotSingleDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-80) [8b8b24c6-88cc-45e2-b808-a9699df3f8d8] Ending command 'org.ovirt.engine.core.bll.snapshots.ColdMergeSnapshotSingleDiskCommand' with failure. There are also multiple tracebacks in vdsm log. Version-Release number of selected component (if applicable): ovirt-engine-4.2.4-0.1.el7.noarch vdsm-4.20.28-1.el7ev.x86_64 How reproducible: Unknown Steps to Reproduce: Unknown, I randomly played with a specific VM with snapshots, and didn't manage to reproduce. The main thing is: 1. Create a VM. 2. Start the VM. 3. Create a few snapshots with memory. 4. Shutdown the VM. 5. Remove a snapshot. Since the first failure occurred, I couldn't remove any snapshot the VM had. Actual results: Actions ends with failure, can't remove snapshots. Expected results: Remove of the snapshot task end successfully. Additional info: engine=# select * from images; image_guid | creation_date | size | it_guid | parentid | imagestatus | lastmodified | vm_snapshot_id | volume_type | volume_format | image_group_id | _create_date | _update_date | active | volume_classification | qcow_compat --------------------------------------+------------------------+-------------+--------------------------------------+--------------------------------------+-------------+----------------------------+------------ --------------------------+-------------+---------------+--------------------------------------+-------------------------------+-------------------------------+--------+-----------------------+------------- 00000000-0000-0000-0000-000000000000 | 2008-04-01 00:00:00+03 | 85899345920 | 00000000-0000-0000-0000-000000000000 | | 0 | 2008-04-01 00:00:00+03 | | 2 | 4 | | 2018-03-05 12:09:22.573641+02 | | t | 0 | 1 14ecdb70-fdc7-461b-87c5-817cb4774831 | 2018-05-09 14:57:11+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 2018-05-30 14:23:19.004+03 | 5712768a-c9 96-47e8-bd8b-9f1e160f6419 | 2 | 4 | 5992a95a-3ab2-4f9e-adbc-879e308d1bdd | 2018-05-09 14:57:10.206912+03 | 2018-05-30 14:48:58.399926+03 | f | 1 | 2 cb717fda-9352-48be-95b3-c12ecc6ec554 | 2018-03-05 14:51:51+02 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 75a67d0e-2dc6-4359-a60e-2cd2fc065760 | 2018-03-05 14:51:49.378477+02 | 2018-03-05 14:52:05.305678+02 | t | 0 | 0 be2350e8-af31-4411-be3d-e6f2500d5164 | 2018-03-05 14:51:49+02 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 0984aa4d-0784-4a83-b8b9-c5239f964f1d | 2018-03-05 14:51:47.777722+02 | 2018-03-05 14:52:06.499386+02 | t | 0 | 0 ddfc6e75-0286-4ee2-9a83-a3014fa04f6c | 2018-03-05 14:51:50+02 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | fd1e67a4-9688-4d42-a8ef-3d99c91ef1a7 | 2018-03-05 14:51:48.234657+02 | 2018-03-05 14:52:06.689738+02 | t | 0 | 0 c3a39c3e-3d6e-4b16-b67c-2546fda9f99e | 2018-03-05 14:51:51+02 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 65b5c075-7721-4cf3-b42f-f446c3665a0a | 2018-03-05 14:51:50.108119+02 | 2018-03-05 14:52:10.307561+02 | t | 0 | 0 f00bd6cf-5dbb-4106-a280-fda670f12db5 | 2018-05-30 14:28:09+03 | 10240 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 69b39533-8093-4c90-b900-ecb1a6ea7da6 | 2018-05-30 14:28:08.418656+03 | 2018-05-30 14:28:11.069951+03 | t | 0 | 0 2e0bfc3a-b183-4a8a-9f00-92ba85a70d7a | 2018-05-30 14:28:08+03 | 1358954496 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 2 | 5 | 99a478b8-a5de-4efb-a58d-91e8ba55d463 | 2018-05-30 14:28:08.116906+03 | 2018-05-30 14:28:11.160617+03 | t | 0 | 0 b8e4cba0-2923-4d2c-a324-9387f6016883 | 2018-05-09 14:57:54+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 1970-01-01 02:00:00+02 | e0cac149-2c b4-4463-8418-522af3552757 | 2 | 4 | 8cb11e33-03b3-4afb-84aa-cff87936eb91 | 2018-05-09 14:57:53.806332+03 | 2018-05-16 15:57:35.997263+03 | t | 0 | 2 a36a9263-840b-4908-961a-0ab781157c8e | 2018-03-05 13:35:43+02 | 10737418240 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | aac6d5bb-bc a8-4cad-bce3-a3be28d79b0a | 2 | 4 | 35d0d1a4-d9de-4e96-81cc-30e45a4bcd6b | 2018-03-05 13:34:05.480244+02 | 2018-05-09 14:56:07.693793+03 | t | 0 | 2 6823a341-c09f-419c-ae3e-6d623fff6b6f | 2018-05-09 14:57:35+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 1970-01-01 02:00:00+02 | 39ee33ea-70 bb-4188-b745-d6c1288559cd | 2 | 4 | 9bce00f8-d5bd-40d5-8d7c-a92948ceba9a | 2018-05-09 14:57:35.370863+03 | 2018-05-09 14:57:42.622501+03 | t | 0 | 2 e1bd3341-1d5f-44a9-b404-ded14121cf1d | 2018-05-30 14:40:26+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | 9c5b4e9f-4048-40cf-9245-2823a42e9d0c | 1 | 1970-01-01 02:00:00+02 | c11c8ec1-d2 19-4ea6-9290-d95760de6125 | 2 | 4 | 5992a95a-3ab2-4f9e-adbc-879e308d1bdd | 2018-05-30 14:40:26.204072+03 | 2018-05-30 14:46:55.407692+03 | t | 0 | 2 9c5b4e9f-4048-40cf-9245-2823a42e9d0c | 2018-05-30 14:40:10+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | b3a028ad-e159-4d93-8eaf-772c7a2d66c3 | 1 | 2018-05-30 14:40:26.203+03 | b5acb9b9-8f 87-47ed-be75-123a78fb160e | 2 | 4 | 5992a95a-3ab2-4f9e-adbc-879e308d1bdd | 2018-05-30 14:40:09.510885+03 | 2018-05-30 14:40:26.204072+03 | f | 1 | 2 b3a028ad-e159-4d93-8eaf-772c7a2d66c3 | 2018-05-30 14:24:01+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | 14ecdb70-fdc7-461b-87c5-817cb4774831 | 1 | 2018-05-30 14:40:09.51+03 | ffc72cf6-4a 64-46bf-a56e-2d8039f7a83c | 2 | 4 | 5992a95a-3ab2-4f9e-adbc-879e308d1bdd | 2018-05-30 14:24:00.512368+03 | 2018-05-30 14:48:58.399926+03 | f | 1 | 2 177b8c71-2399-40e0-9fe9-e5118b050d8b | 2018-05-09 14:57:18+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 1970-01-01 02:00:00+02 | cba64004-69 7d-466f-96a2-fa8b8f3ac9ae | 2 | 4 | 3fa64875-3bd3-451b-bac4-f617726f1c9d | 2018-05-09 14:57:17.583434+03 | 2018-05-09 14:57:25.92848+03 | t | 0 | 2 a4cccd1b-fd8e-461d-ba83-7a1425365508 | 2018-05-09 14:57:27+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 1970-01-01 02:00:00+02 | b9d97559-8f 77-4edd-895c-eccc2325a85d | 2 | 4 | 5678b112-83b0-4266-afa0-cbdf4dead6ec | 2018-05-09 14:57:26.784664+03 | 2018-05-09 14:57:34.854156+03 | t | 0 | 2 25de19cb-79a1-4160-ad1b-1a2356a84c56 | 2018-05-09 14:57:41+03 | 10737418240 | a36a9263-840b-4908-961a-0ab781157c8e | a36a9263-840b-4908-961a-0ab781157c8e | 1 | 1970-01-01 02:00:00+02 | a4cb0568-f7 d6-4521-83f9-24393d07b504 | 2 | 4 | 370d84f1-5aed-4dcb-98de-7694e36db93f | 2018-05-09 14:57:41.084839+03 | 2018-05-09 14:57:56.612211+03 | t | 0 | 2 bc2c419f-ee70-4514-9fbb-e8760767adc0 | 2018-05-09 15:49:50+03 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | f43240bc-79ae-41f5-81e4-a5013684d3f6 | 2018-05-09 15:49:46.900362+03 | 2018-05-09 15:49:56.493763+03 | t | 0 | 0 9ed56cd0-fcf4-464c-8a4b-74d5edfbb17b | 2018-05-09 15:49:50+03 | 134217728 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 95192935-c76e-40a8-9cd2-8092f62a5c90 | 2018-05-09 15:49:47.328596+03 | 2018-05-09 15:49:57.741056+03 | t | 0 | 0 fe14f8ee-f6e1-4704-8870-23784d58050e | 2018-05-30 14:40:27+03 | 10240 | 00000000-0000-0000-0000-000000000000 | 00000000-0000-0000-0000-000000000000 | 1 | 1970-01-01 02:00:00+02 | | 1 | 5 | 17ff82e1-e577-49c3-a787-12c5511ed40f | 2018-05-30 14:40:26.72065+03 | 2018-05-30 14:40:35.48036+03 | t | 0 | 0 (20 rows)
Link to the logs(sosreport of the engine and host): https://drive.google.com/file/d/1gAOu1eAlGS5rN0Xad19XRBVUn7G3VhVO/view?usp=sharing Timing of actions are around: 2018-05-30 14:20:49,014 to 2018-05-30 14:56:00
Benny, you're this week's QE contact, please have a look if we can gather any info from the logs to help us get to the root cause, if not please close as insufficient data
I can't download the file from drive (not sure why). Liran, can you please attach the engine.log and vdsm.log to the bugzilla?
Created attachment 1450410 [details] logs
Merge failed with: 2018-05-30 14:54:52,274+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-69) [] BaseAsyncTask::logEndTaskFailure: Task '536b0bac-3486-42a8-9d9a-afc61a35889b' (Parent Command 'PrepareMerge', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Volume does not exist: ('b3a028ad-e159-4d93-8eaf-772c7a2d66c3',), code = 201', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Volume does not exist: ('b3a028ad-e159-4d93-8eaf-772c7a2d66c3',), code = 201' This volume was already removed previously: 2018-05-30 14:41:03,574+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (default task-26) [snapshots_syncAction_108cb8f2-9194-4] START, DestroyImageVDSCommand( DestroyImageVDSCommandParameters:{storagePoolId='c73ab90f-ae2e-4289-bfd5-076a20c1501f', ignoreFailoverLimit='false', storageDomainId='5e11dd92-ca27-4440-9d7c-c7090b9b2b00', imageGroupId='5992a95a-3ab2-4f9e-adbc-879e308d1bdd', imageId='00000000-0000-0000-0000-000000000000', imageList='[e1bd3341-1d5f-44a9-b404-ded14121cf1d, 9c5b4e9f-4048-40cf-9245-2823a42e9d0c, b3a028ad-e159-4d93-8eaf-772c7a2d66c3]', postZero='false', force='true'}), log id: 1ae0a86b 2018-05-30 14:41:03,683+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (default task-26) [snapshots_syncAction_108cb8f2-9194-4] FINISH, DestroyImageVDSCommand, log id: 1ae0a86b But it looks like it remained in the database because of the transaction timeout: 2018-05-30 14:46:03,042+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-05-30 14:46:03,042+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (Transaction Reaper Worker 0) [] Transaction rolled-back for command 'org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand'. 2018-05-30 14:46:03,044+03 INFO [org.ovirt.engine.core.bll.tasks.CommandCoordinatorImpl] (EE-ManagedThreadFactory-engine-Thread-40514) [] Rollback for command 'org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand' 2018-05-30 14:46:03,045+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engine-Thread-40514) [] Attempting to cancel task '15fec7d2-9895-49fe-8c3f-5505eeb1d2e1'. 2018-05-30 14:46:03,045+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-40514) [] SPMAsyncTask::StopTask: Attempting to stop task '15fec7d2-9895-49fe-8c3f-5505eeb1d2e1' (Parent Command 'RestoreFromSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'). 2018-05-30 14:46:03,045+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-40514) [] SPMAsyncTask::StopTask: Error during stopping task '15fec7d2-9895-49fe-8c3f-5505eeb1d2e1': 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-05-30 14:46:03,199+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-26) [57fa1593] BaseAsyncTask::startPollingTask: Starting to poll task 'f1024c2e-d2f5-4614-8315-90f7dc121ee8'. 2018-05-30 14:46:03,200+03 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (default task-26) [57fa1593] Lock freed to object 'EngineLock:{exclusiveLocks='[a4f40357-e36c-4ed9-9861-f31c4d205b4e=DISK]', sharedLocks=''}' 2018-05-30 14:46:03,249+03 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (default task-26) [2cf06dbd] Lock Acquired to object 'EngineLock:{exclusiveLocks='[17ff82e1-e577-49c3-a787-12c5511ed40f=DISK]', sharedLocks=''}' 2018-05-30 14:46:03,279+03 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (default task-26) [2cf06dbd] Transaction was aborted in 'org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand' 2018-05-30 14:46:03,342+03 ERROR [org.ovirt.engine.core.bll.job.ExecutionHandler] (default task-26) [2cf06dbd] 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@4de633e[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@74d09258 connection handles=0 lastReturned=1527680763281 lastValidated=1527680425383 lastCheckedOut=1527680763272 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@d640930 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@6dde0b10[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@4d8e6a1c[connectionListener=4de633e connectionManager=52a0c82e warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:619) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:684) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:716) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:766) [spring-jdbc.jar:4.3.9.RELEASE] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.executeCallInternal(PostgresDbEngineDialect.java:152) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.doExecute(PostgresDbEngineDialect.java:118) [dal.jar:] at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:198) [spring-jdbc.jar:4.3.9.RELEASE] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:135) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadList(SimpleJdbcCallsHandler.java:105) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeRead(SimpleJdbcCallsHandler.java:97) [dal.jar:] at org.ovirt.engine.core.dao.JobDaoImpl.checkIfJobHasTasks(JobDaoImpl.java:149) [dal.jar:] at org.ovirt.engine.core.bll.job.ExecutionHandler.checkIfJobHasTasks(ExecutionHandler.java:893) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1368) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:400) [bll.jar:] at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:468) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:450) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:656) [bll.jar:] at sun.reflect.GeneratedMethodAccessor1051.invoke(Unknown Source) [:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:78) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101) at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:255) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:381) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:64) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609) at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198) at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81) at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view4.runInternalAction(Unknown Source) [bll.jar:] at sun.reflect.GeneratedMethodAccessor1050.invoke(Unknown Source) [:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:433) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:133) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:67) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:100) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$2049259618$Proxy$_$$_Weld$EnterpriseProxy$.runInternalAction(Unknown Source) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInternalAction(CommandBase.java:2318) [bll.jar:] at org.ovirt.engine.core.bll.VmCommand.removeMemoryDisks(VmCommand.java:309) [bll.jar:] at org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand.removeSnapshotsFromDB(RestoreAllSnapshotsCommand.java:371) [bll.jar:] at org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand.executeVmCommand(RestoreAllSnapshotsCommand.java:181) [bll.jar:] at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:161) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1133) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1285) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1934) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1345) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:400) [bll.jar:] at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:468) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:450) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:403) [bll.jar:] at sun.reflect.GeneratedMethodAccessor575.invoke(Unknown Source) [:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:92) [wildfly-weld-ejb-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.interceptorChainCompleted(WeldInvocationContextImpl.java:124) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:143) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:] at sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source) [:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.invokeNext(WeldInvocationContextImpl.java:109) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:141) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.InterceptorImpl.intercept(InterceptorImpl.java:113) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:82) [wildfly-weld-ejb-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.as.weld.interceptors.EjbComponentInterceptorSupport.delegateInterception(EjbComponentInterceptorSupport.java:60) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:76) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101) at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.ovirt.engine.core.bll.interceptors.CorrelationIdTrackerInterceptor.aroundInvoke(CorrelationIdTrackerInterceptor.java:13) [bll.jar:] at sun.reflect.GeneratedMethodAccessor75.invoke(Unknown Source) [:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:264) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:379) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.1.2.GA-redhat-1.jar:7.1.2.GA-redhat-1] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609) at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198) at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81) at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view3.runAction(Unknown Source) [common.jar:] at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:250) at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:80) at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:121) at org.ovirt.engine.api.restapi.resource.BackendSnapshotResource.restore(BackendSnapshotResource.java:89) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_171] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_171] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1] at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74) at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:81) at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:64) at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:274) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:209) at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:221) at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImplSetup(RequestDispatcherImpl.java:147) at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:111) at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:180) at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:98) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:117) at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:72) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.RestApiSessionMgmtFilter.doFilter(RestApiSessionMgmtFilter.java:78) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.EnforceAuthFilter.doFilter(EnforceAuthFilter.java:42) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SsoRestApiNegotiationFilter.doFilter(SsoRestApiNegotiationFilter.java:84) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SsoRestApiAuthFilter.doFilter(SsoRestApiAuthFilter.java:47) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SessionValidationFilter.doFilter(SessionValidationFilter.java:59) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.RestApiSessionValidationFilter.doFilter(RestApiSessionValidationFilter.java:35) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:111) at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:102) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.utils.servlet.CORSSupportFilter.doFilter(CORSSupportFilter.java:284) [utils.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:64) at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:53) at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) at io.undertow.servlet.handlers.security.ServletSecurityConstraintHandler.handleRequest(ServletSecurityConstraintHandler.java:59) at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:330) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_171] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_171] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_171] Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@4de633e[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@74d09258 connection handles=0 lastReturned=1527680763281 lastValidated=1527680425383 lastCheckedOut=1527680763272 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@d640930 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@6dde0b10[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@4d8e6a1c[connectionListener=4de633e connectionManager=52a0c82e warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:146) at org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64) at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77) [spring-jdbc.jar:4.3.9.RELEASE] ... 284 more Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@4de633e[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@74d09258 connection handles=0 lastReturned=1527680763281 lastValidated=1527680425383 lastCheckedOut=1527680763272 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@d640930 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@6dde0b10[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@4d8e6a1c[connectionListener=4de633e connectionManager=52a0c82e warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:975) at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:792) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138) ... 287 more Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:561) at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:970) ... 289 more Caused by: java.lang.IllegalStateException: Transaction Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a23a1f4:317f6484:5b0cffca:24c10 status: ActionStatus.ABORTED >, owner=Local transaction context for provider JBoss JTA transaction provider) is not active STATUS_ROLLEDBACK at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:296) at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:554) ... 290 more 2018-05-30 14:46:03,380+03 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (default task-26) [2cf06dbd] Lock freed to object 'EngineLock:{exclusiveLocks='[17ff82e1-e577-49c3-a787-12c5511ed40f=DISK]', sharedLocks=''}' 2018-05-30 14:46:03,381+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-26) [2cf06dbd] Failed to remove memory of snapshot 'b5acb9b9-8f87-47ed-be75-123a78fb160e' 2018-05-30 14:46:03,404+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-26) [2cf06dbd] 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@4de633e[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@74d09258 connection handles=0 lastReturned=1527680763381 lastValidated=1527680425383 lastCheckedOut=1527680763374 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@d640930 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@6dde0b10[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@4d8e6a1c[connectionListener=4de633e connectionManager=52a0c82e warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] 2018-05-30 14:46:03,404+03 ERROR [org.ovirt.engine.core.bll.snapshots.RestoreAllSnapshotsCommand] (default task-26) [2cf06dbd] 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@4de633e[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@74d09258 connection handles=0 lastReturned=1527680763381 lastValidated=1527680425383 lastCheckedOut=1527680763374 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@d640930 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@6dde0b10[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@4d8e6a1c[connectionListener=4de633e connectionManager=52a0c82e warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:1070) [spring-jdbc.jar:4.3.9.RELEASE] at [...] 2018-05-30 14:46:03,474+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-26) [2cf06dbd] EVENT_ID: USER_COMMIT_RESTORE_FROM_SNAPSHOT_FINISH_FAILURE(96), Failed to commit Snapshot-Preview for VM golden_env_mixed_virtio_0. 2018-05-30 14:46:03,493+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-26) [] Operation Failed: [Internal Engine Error] 2018-05-30 14:46:07,884+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-44) [snapshots_syncAction_108cb8f2-9194-4] Command 'RestoreAllSnapshots' (id: 'cc9a6d07-b862-4a8f-927c-b1e513a50227') waiting on child command id: '1361ccfb-7f90-452d-8a6b-bc872affe818' type:'RestoreFromSnapshot' to complete
OK, so we know where the bug is?
(In reply to Tal Nisan from comment #6) > OK, so we know where the bug is? The delete took a very long time so, the fix would probably running DestroyImage in RestoreFromSnapshotCommand outside of the transaction
Created attachment 1450813 [details] server log
This bug has not been marked as blocker for oVirt 4.3.0. Since we are releasing it tomorrow, January 29th, this bug has been re-targeted to 4.3.1.
Eyal, as the fix of this issue is to suppress DestroyImage from RestoreFromSnapshotCommand transaction. As I understand the fix the verification should do: 1) Run the same scenario as provided in the initial description and see it works. 2) Check out engine logs and make sure the RestoreFromSnapshotCommand does include DestroyImage command. 3) Check DestroyImage happens after RestoreFromSnapshotCommand finishes. Please, ack/Nack.
(In reply to Avihai from comment #10) > Eyal, as the fix of this issue is to suppress DestroyImage from > RestoreFromSnapshotCommand transaction. > > As I understand the fix the verification should do: > > 1) Run the same scenario as provided in the initial description and see it > works. > 2) Check out engine logs and make sure the RestoreFromSnapshotCommand does > include DestroyImage command. No, the change will not be visible in the logs, the transaction is referred to the DB and not the execution order of the command. > 3) Check DestroyImage happens after RestoreFromSnapshotCommand finishes. Same. > > Please, ack/Nack. You need to verify the flow works fine while you simulating a transaction timeout. DB transaction timeout interval can be set to 1 minute (instead of 5 minutes) using - /subsystem=transactions:write-attribute(name=default-timeout,value=60) Then, you need to add a sleep in the VDSM that will hold the transaction open, in this case in the delete verb in the vdsm api.
(In reply to Eyal Shenitzky from comment #11) > (In reply to Avihai from comment #10) > > Eyal, as the fix of this issue is to suppress DestroyImage from > > RestoreFromSnapshotCommand transaction. > > > > As I understand the fix the verification should do: > > > > 1) Run the same scenario as provided in the initial description and see it > > works. > > 2) Check out engine logs and make sure the RestoreFromSnapshotCommand does > > include DestroyImage command. > > No, the change will not be visible in the logs, the transaction is referred > to the DB and not the execution order of the command. > > > 3) Check DestroyImage happens after RestoreFromSnapshotCommand finishes. > > Same. > > > > > Please, ack/Nack. > > You need to verify the flow works fine while you simulating a transaction > timeout. Which flow is that ? the original scenario? > DB transaction timeout interval can be set to 1 minute (instead of 5 > minutes) using - OK, I'll tweak this parameter to get to transaction timeout state. How can I know I hit this state ? will delete snapshot fail? > > /subsystem=transactions:write-attribute(name=default-timeout,value=60) > > Then, you need to add a sleep in the VDSM that will hold the transaction > open, in this case in the delete verb in the vdsm api. How much sleep, more than 60 seconds I assume? I'm guessing you are referring to: /usr/lib/python2.7/site-packages/vdsm/API.py ? By "delete verb" do you mean (line 896 at vdsm-4.30.22-1.el7ev.x86_64): def delete(self, postZero, force, discard=False): return self._irs.deleteVolume(self._sdUUID, self._spUUID, self._imgUUID, [self._UUID], postZero, force, discard)
After I logged in to DB shell to engine DB(psql -d engine) , I executed : /subsystem=transactions:write-attribute(name=default-timeout,value=60) I did not see any output, how can I check indeed the value changed ?
(In reply to Avihai from comment #13) > After I logged in to DB shell to engine DB(psql -d engine) , I executed : > /subsystem=transactions:write-attribute(name=default-timeout,value=60) > > I did not see any output, how can I check indeed the value changed ? This command is meant to run in jboss-cli, you could also browse to the engine with port 8706, then configuration then transaction and configure the timeout The transaction timeout reduction is optional, to make it more convenient to reproduce by waiting a bit over a minute instead of over 5 minutes. The sleep should go to either fileSD.py#purgeImage or blockSD#purgeImage (depending on the storage type), you can do both just in case, and I would set it to 90 seconds to be safe Note: it should be similar to the steps used here[1] [1] - https://bugzilla.redhat.com/1638540
Verified on vdsm-4.30.22-1.el7ev.x86_64 Thanks to Benny's help I reached the coveted scenario for verification: Both undo and snapshot delete(cold merge) was tested passing the transaction timeout and operations were successful. Details: 1) Create VM with disks and several snapshots 2) On engine - Change transaction timeout to 60 sec connecting to jboss CLI: /opt/rh/eap7/root/usr/share/wildfly/bin/jboss-cli.sh --controller=127.0.0.1:8706 --connect --user=user Set timeout to 60 sec (default is 300) [standalone.0.1:8706 /] /subsystem=transactions:write-attribute(name=default-timeout,value=60) 3) Leave just one host for use of ease(rest of the host on maintenance) 4) Connect to the host and add 90 second sleep and restart vdsmd . I worked with file disks so I used: /usr/lib/python2.7/site-packages/vdsm/storage/fileVolume.py#Delete def delete(self, postZero, force, discard): ................................................... self.log.info("SLEEPING FOR 90 seconds") import time;time.sleep(90) 5) preview one of the snapshot 6) undo one of the snapshot Result: undo took ~2 minutes(after checking I hit the sleep in the log) which passed the transaction timeout -> verification must 2019-07-03 17:02:39,969+0300 INFO (tasks/8) [storage.Volume] SLEEPING FOR 90 seconds (fileVolume:568) Undo operation completed successfully. I also tested deleting one of the snapshots to check merge scenatio and also here SLEEP was hit which passed the transaction timeout and still operation suceeded.
This bugzilla is included in oVirt 4.3.5 release, published on July 30th 2019. Since the problem described in this bug report should be resolved in oVirt 4.3.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.