Bug 1467099
| Summary: | Creation of template from a VM with snapshot may remotely fail | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Raz Tamir <ratamir> | ||||||||
| Component: | BLL.Storage | Assignee: | Elad <ebenahar> | ||||||||
| Status: | CLOSED WORKSFORME | QA Contact: | Elad <ebenahar> | ||||||||
| Severity: | low | Docs Contact: | |||||||||
| Priority: | low | ||||||||||
| Version: | 4.1.3.5 | CC: | bugs, ebenahar, frolland | ||||||||
| Target Milestone: | ovirt-4.3.1 | Keywords: | Automation, Reopened | ||||||||
| Target Release: | --- | Flags: | ylavi:
ovirt-4.3+
|
||||||||
| Hardware: | Unspecified | ||||||||||
| OS: | Unspecified | ||||||||||
| Whiteboard: | |||||||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||||||
| Doc Text: | Story Points: | --- | |||||||||
| Clone Of: | Environment: | ||||||||||
| Last Closed: | 2019-02-04 09:30:57 UTC | Type: | Bug | ||||||||
| Regression: | --- | Mount Type: | --- | ||||||||
| Documentation: | --- | CRM: | |||||||||
| Verified Versions: | Category: | --- | |||||||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||
| Embargoed: | |||||||||||
| Attachments: |
|
||||||||||
Tentatively targeting to 4.2 since we don't have a reproducer. If we have a reliable reproducer, we should consider retargetting. Neither dev nor QE can reproduce this, and the stacktrace comes from the Quartz implementation that has since been removed. I'm closing this bug, but please reopen if you can reproduce it. Created attachment 1406942 [details]
logs-11.3.18
Reproduced in our 4.1 automation run (test case 5297 of detach attach test plan).
rhevm-4.1.10.2-0.1.el7.noarch
vdsm-4.19.49-1.el7ev.x86_64
Steps:
- Create VM from template as thin copy
- Create a template from that VM
2018-03-08 09:14:38,815+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-2) [templates_create_45cbe44b-5163-4c9c] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{
runAsync='true', storagePoolId='ca981dbd-e265-4d9d-9eca-c123b58f82ec', ignoreFailoverLimit='false', storageDomainId='a04e6fc9-acf6-48fa-91f8-1014895726a6', imageGroupId='fcbfa9ff-7926-40fa-a813-288e045a668c', im
ageId='b093f4be-f7df-4272-aff9-4bd27f9d850e', dstImageGroupId='e78ea419-be84-45d9-a97f-3c7205de9219', vmId='2ff67edd-6196-476b-9533-d77ba3bd702b', dstImageId='156d72a7-88a8-4fb4-af38-c835ad7af34a', imageDescript
ion='{"DiskAlias":"vm_from_temp_Disk_0","DiskDescription":"rhel7.4_rhv4.1_guest_disk (d00010f)"}', dstStorageDomainId='a04e6fc9-acf6-48fa-91f8-1014895726a6', copyVolumeType='SharedVol', volumeFormat='COW', preal
locate='Sparse', postZero='false', discard='false', force='false'}), log id: 4fa6c7f3
2018-03-08 09:15:43,027+02 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (DefaultQuartzScheduler1) [templates_create_45cbe44b-5163-4c9c] Exception: java.util.ConcurrentModificationException
at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909) [rt.jar:1.8.0_161]
at java.util.ArrayList$Itr.next(ArrayList.java:859) [rt.jar:1.8.0_161]
at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:36) [bll.jar:]
at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:114) [bll.jar:]
at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source) [:1.8.0_161]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_161]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_161]
at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83) [scheduler.jar:]
at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55) [scheduler.jar:]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_161]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_161]
2018-03-08 09:15:44,051+02 ERROR [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler8) [templates_create_45cbe44b-5163-4c9c] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateCommand' with failure.
Created attachment 1422917 [details]
engine.log
Reproduced also on latest 4.2.3 - ovirt-engine-4.2.3-0.1
2018-04-14 10:54:45,648+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [templates_create_b1f16c0b-056f-43f0] Error invoking callback method
'doPolling' for 'ACTIVE' command '8bf58a4b-b610-4edb-a92e-7355d779e503'
2018-04-14 10:54:45,648+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-49) [templates_create_b1f16c0b-056f-43f0] Exception: java.util.ConcurrentModificationException
at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909) [rt.jar:1.8.0_161]
at java.util.ArrayList$Itr.next(ArrayList.java:859) [rt.jar:1.8.0_161]
at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:41) [bll.jar:]
at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:145) [bll.jar:]
at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106) [bll.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_161]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_161]
at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_161]
at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
at org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
2018-04-14 10:54:45,650+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-10592) [templates_create_b1f16c0b-056f-43f0] BaseAsyncTask::removeTaskFromDB: Removed task '99673483-01e1-4af7-9273-798d77169724' from DataBase
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. reopen if occurs again |
Created attachment 1293676 [details] engine.log Description of problem: Happened in our automation tier 3. * Couldn't reproduce * Creation of template from VM with snapshot failed From engine.log: 2017-06-30 16:16:22,672+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateAllTemplateDisks' completed, handling the result. 2017-06-30 16:16:22,672+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateAllTemplateDisks' succeeded, clearing tasks. 2017-06-30 16:16:22,672+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'de0b270c-d885-4b95-bbae-b73ec3c75404' 2017-06-30 16:16:22,676+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='8be71a8d-4e55-4c18-a66b-c66c3027cb7b', ignoreFailoverLimit='false', taskId='de0b270c-d885-4b95-bbae-b73ec3c75404'}), log id: 5d9fcc20 2017-06-30 16:16:22,690+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] START, HSMClearTaskVDSCommand(HostName = host_mixed_1, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='9686dd2d-ee47-4c7b-ad23-6d5ffd5bfabd', taskId='de0b270c-d885-4b95-bbae-b73ec3c75404'}), log id: 38590886 2017-06-30 16:16:23,641+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] FINISH, HSMClearTaskVDSCommand, log id: 38590886 2017-06-30 16:16:23,641+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] FINISH, SPMClearTaskVDSCommand, log id: 5d9fcc20 2017-06-30 16:16:23,670+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] BaseAsyncTask::removeTaskFromDB: Removed task 'de0b270c-d885-4b95-bbae-b73ec3c75404' from DataBase 2017-06-30 16:16:23,670+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-33) [templates_create_f0ca58db-31d2-43da] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity '2daf903a-a2de-4b6a-b1f5-871689fee9b5' 2017-06-30 16:16:23,739+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (DefaultQuartzScheduler9) [templates_create_f0ca58db-31d2-43da] Error invoking callback method 'doPolling' for 'ACTIVE' command '57f232c4-e1b8-44f1-92f3-c000e27a8c78' 2017-06-30 16:16:23,740+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (DefaultQuartzScheduler9) [templates_create_f0ca58db-31d2-43da] Exception: java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:901) [rt.jar:1.8.0_131] at java.util.ArrayList$Itr.next(ArrayList.java:851) [rt.jar:1.8.0_131] at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:36) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:114) [bll.jar:] at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source) [:1.8.0_131] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_131] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_131] at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83) [scheduler.jar:] at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55) [scheduler.jar:] at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_131] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_131] 2017-06-30 16:16:24,836+03 ERROR [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler6) [templates_create_f0ca58db-31d2-43da] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateCommand' with failure. 2017-06-30 16:16:24,848+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (DefaultQuartzScheduler6) [templates_create_f0ca58db-31d2-43da] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{runAsync='true', vmId='b7acb00a-c321-44e2-85b6-f19b3aed8a59', status='Down', exitStatus='Normal'}), log id: 5ba67092 2017-06-30 16:16:24,853+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (DefaultQuartzScheduler6) [templates_create_f0ca58db-31d2-43da] FINISH, SetVmStatusVDSCommand, log id: 5ba67092 2017-06-30 16:16:24,865+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateCommand] (DefaultQuartzScheduler6) [templates_create_f0ca58db-31d2-43da] Lock freed to object 'EngineLock:{exclusiveLocks='[5b347ca9-40f1-4f31-b441-af1421cfbd75=DISK, 11607_template_preallocated=TEMPLATE_NAME, 7efb0d4f-72f0-4f18-8d83-be1ec5c10403=TEMPLATE]', sharedLocks='[b7acb00a-c321-44e2-85b6-f19b3aed8a59=VM]'}' 2017-06-30 16:16:24,883+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler6) [templates_create_f0ca58db-31d2-43da] EVENT_ID: USER_ADD_VM_TEMPLATE_CREATE_TEMPLATE_FAILURE(1,322), Correlation ID: templates_create_f0ca58db-31d2-43da, Job ID: 03cbf7b0-be18-4543-a3a5-33e89b06715a, Call Stack: null, Custom Event ID: -1, Message: Failed to create Template 11607_template_preallocated or its disks from VM vm_prealloc_disk_image_11607. Version-Release number of selected component (if applicable): ovirt-engine-4.1.3.5-0.1.el7.noarch vdsm-4.19.20-1.el7ev.x86_64 How reproducible: Only once in our automation Steps to Reproduce: 1. Create a VM with 1 raw preallocated disk and size 64GB 2. Create a snapshot 3. Create a template Actual results: Template creation failed Expected results: Additional info: