| Summary: | NullPointerException when copying template disk to storage domain | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Raz Tamir <ratamir> | ||||
| Component: | BLL.Storage | Assignee: | Liron Aravot <laravot> | ||||
| Status: | CLOSED WORKSFORME | QA Contact: | Aharon Canan <acanan> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | high | ||||||
| Version: | 3.6.2.6 | CC: | amureini, bugs, ratamir, tnisan, ylavi | ||||
| Target Milestone: | ovirt-3.6.5 | Keywords: | Automation | ||||
| Target Release: | --- | Flags: | amureini:
ovirt-3.6.z?
ylavi: exception? ylavi: planning_ack+ amureini: devel_ack+ rule-engine: testing_ack? |
||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2016-03-09 11:34:18 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: | |||||
| Attachments: |
|
||||||
Hi, Inspecting the log I've noticed the in this case the scenario was 1. Import image from glance as template 2. Copy the template disk to other SD I've tested the scenario on the 3.6 branch (which 3.6.5 will be based on) and failed to reproduce the issue. I've tested it with copy of "regular" template disk and failed to reproduce as well. I've look for the patch that solved the issue (it seems to be a VmDevice issue but didn't find it on brief look - so first lets inspect if this is relevant. Raz, is there any other info you can share that'll help us reproduce the issue? As for now, closing as work for me. It seems that it was fixed by some other change |
Created attachment 1119137 [details] engine and vdsm logs Description of problem: When copying a templated disk to storage domain, a NullPointerException raised but the disk is successfully copied from engine.log: 2016-01-28 14:36:13,052 INFO [org.ovirt.engine.core.bll.MoveOrCopyDiskCommand] (ajp-/127.0.0.1:8702-11) [disks_syncAction_a937bf47-3eb6-4022] Running command: MoveOrCopyDiskCommand internal: false. Entities affected : ID: f0969223-959a-4b87-a12d-810ed49c5fcb Type: DiskAction group CONFIGURE_DISK_STORAGE with role type USER, ID: b7ecccb7-6588-4a47-95b5-ecbef1896a2c Type: StorageAction group CREATE_DISK with role type USER 2016-01-28 14:36:13,061 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] Running command: CopyImageGroupCommand internal: true. Entities affected : ID: b7ecccb7-6588-4a47-95b5-ecbef1896a2c Type: Storage 2016-01-28 14:36:13,080 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{runAsync='true', storagePoolId='d2144d19-e41b-4fad-b904-1ad871b2b4b9', ignoreFailoverLimit='false', storageDomainId='fad01b68-b161-41aa-8efa-ac9f78eb5b18', imageGroupId='f0969223-959a-4b87-a12d-810ed49c5fcb', imageId='80f2767a-30c6-4d55-ab31-32754cf2ab95', dstImageGroupId='f0969223-959a-4b87-a12d-810ed49c5fcb', vmId='00000000-0000-0000-0000-000000000000', dstImageId='80f2767a-30c6-4d55-ab31-32754cf2ab95', imageDescription='', dstStorageDomainId='b7ecccb7-6588-4a47-95b5-ecbef1896a2c', copyVolumeType='SharedVol', volumeFormat='COW', preallocate='Sparse', postZero='false', force='false'}), log id: 308a4ae8 2016-01-28 14:36:13,081 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] -- executeIrsBrokerCommand: calling 'copyImage' with two new parameters: description and UUID. Parameters: 2016-01-28 14:36:13,081 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ sdUUID=fad01b68-b161-41aa-8efa-ac9f78eb5b18 2016-01-28 14:36:13,081 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ spUUID=d2144d19-e41b-4fad-b904-1ad871b2b4b9 2016-01-28 14:36:13,081 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ vmGUID=00000000-0000-0000-0000-000000000000 2016-01-28 14:36:13,081 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ srcImageGUID=f0969223-959a-4b87-a12d-810ed49c5fcb 2016-01-28 14:36:13,082 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ srcVolUUID=80f2767a-30c6-4d55-ab31-32754cf2ab95 2016-01-28 14:36:13,082 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ dstImageGUID=f0969223-959a-4b87-a12d-810ed49c5fcb 2016-01-28 14:36:13,082 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ dstVolUUID=80f2767a-30c6-4d55-ab31-32754cf2ab95 2016-01-28 14:36:13,082 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ descr= 2016-01-28 14:36:13,082 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] ++ dstSdUUID=b7ecccb7-6588-4a47-95b5-ecbef1896a2c 2016-01-28 14:36:14,049 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8702-11) [25fdcf81] FINISH, CopyImageVDSCommand, return: cee0fcb0-d17a-4c5e-9f1f-21104981973d, log id: 308a4ae8 2016-01-28 14:36:14,052 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (ajp-/127.0.0.1:8702-11) [25fdcf81] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '9832b159-85a7-4c9c-be85-61ab25516178' 2016-01-28 14:36:14,052 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (ajp-/127.0.0.1:8702-11) [25fdcf81] CommandMultiAsyncTasks::AttachTask: Attaching task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d' to command '9832b159-85a7-4c9c-be85-61ab25516178'. 2016-01-28 14:36:14,065 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (ajp-/127.0.0.1:8702-11) [25fdcf81] Adding task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d' (Parent Command 'MoveOrCopyDisk', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2016-01-28 14:36:14,089 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-11) [25fdcf81] Correlation ID: disks_syncAction_a937bf47-3eb6-4022, Job ID: 1ef04594-365c-4e45-8256-448e557a219c, Call Stack: null, Custom Event ID: -1, Message: User admin@internal is copying disk golden_mixed_virtio_template to domain test_gluster_1. 2016-01-28 14:36:14,089 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (ajp-/127.0.0.1:8702-11) [25fdcf81] BaseAsyncTask::startPollingTask: Starting to poll task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d'. 2016-01-28 14:36:16,609 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-33) [] Polling and updating Async Tasks: 6 tasks, 1 tasks to poll now 2016-01-28 14:36:18,481 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-33) [] SPMAsyncTask::PollTask: Polling task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d' (Parent Command 'MoveOrCopyDisk', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'running'. 2016-01-28 14:36:18,481 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-33) [] Finished polling Tasks, will poll again in 10 seconds. 2016-01-28 14:39:33,182 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-98) [] SPMAsyncTask::PollTask: Polling task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d' (Parent Command 'MoveOrCopyDisk', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2016-01-28 14:39:33,187 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-98) [] BaseAsyncTask::onTaskEndSuccess: Task 'cee0fcb0-d17a-4c5e-9f1f-21104981973d' (Parent Command 'MoveOrCopyDisk', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2016-01-28 14:39:33,191 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-98) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '9832b159-85a7-4c9c-be85-61ab25516178' has ended -> executing 'endAction' 2016-01-28 14:39:33,191 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-98) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '9832b159-85a7-4c9c-be85-61ab25516178'): calling endAction '. 2016-01-28 14:39:33,191 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-35) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'MoveOrCopyDisk', executionIndex: '0' 2016-01-28 14:39:33,209 INFO [org.ovirt.engine.core.bll.MoveOrCopyDiskCommand] (org.ovirt.thread.pool-7-thread-35) [disks_syncAction_a937bf47-3eb6-4022] Ending command 'org.ovirt.engine.core.bll.MoveOrCopyDiskCommand' successfully. 2016-01-28 14:39:33,220 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (org.ovirt.thread.pool-7-thread-35) [25fdcf81] Ending command 'org.ovirt.engine.core.bll.CopyImageGroupCommand' successfully. 2016-01-28 14:39:33,224 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-7-thread-35) [25fdcf81] START, GetImageInfoVDSCommand( GetImageInfoVDSCommandParameters:{runAsync='true', storagePoolId='d2144d19-e41b-4fad-b904-1ad871b2b4b9', ignoreFailoverLimit='false', storageDomainId='fad01b68-b161-41aa-8efa-ac9f78eb5b18', imageGroupId='f0969223-959a-4b87-a12d-810ed49c5fcb', imageId='80f2767a-30c6-4d55-ab31-32754cf2ab95'}), log id: 2a7ad46c 2016-01-28 14:39:33,747 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-7-thread-35) [25fdcf81] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@1c060a85, log id: 2a7ad46c 2016-01-28 14:39:33,755 INFO [org.ovirt.engine.core.bll.MoveOrCopyDiskCommand] (org.ovirt.thread.pool-7-thread-35) [] Lock freed to object 'EngineLock:{exclusiveLocks='[f0969223-959a-4b87-a12d-810ed49c5fcb=<DISK, ACTION_TYPE_FAILED_DISK_IS_BEING_MIGRATED$DiskName golden_mixed_virtio_template>]', sharedLocks='[ddc4d108-c8b1-4c2e-9186-372e613dad9f=<TEMPLATE, ACTION_TYPE_FAILED_DISK_IS_BEING_MIGRATED$DiskName golden_mixed_virtio_template>]'}' 2016-01-28 14:39:33,756 WARN [org.ovirt.engine.core.compat.backendcompat.TypeCompat] (org.ovirt.thread.pool-7-thread-35) [] Unable to get value of property: 'diskAlias' for class org.ovirt.engine.core.bll.MoveOrCopyDiskCommand: null 2016-01-28 14:39:33,765 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-35) [] Correlation ID: disks_syncAction_a937bf47-3eb6-4022, Job ID: 1ef04594-365c-4e45-8256-448e557a219c, Call Stack: null, Custom Event ID: -1, Message: User admin@internal finished copying disk <UNKNOWN> to domain test_gluster_1. 2016-01-28 14:39:33,765 ERROR [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-35) [] [within thread]: endAction for action type MoveOrCopyDisk threw an exception.: java.lang.NullPointerException at org.ovirt.engine.core.bll.MoveOrCopyDiskCommand.isTemplate(MoveOrCopyDiskCommand.java:424) [bll.jar:] at org.ovirt.engine.core.bll.MoveOrCopyDiskCommand.incrementDbGenerationForRelatedEntities(MoveOrCopyDiskCommand.java:313) [bll.jar:] at org.ovirt.engine.core.bll.MoveOrCopyDiskCommand.endSuccessfully(MoveOrCopyDiskCommand.java:306) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:651) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:595) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1984) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:524) [bll.jar:] at org.ovirt.engine.core.bll.tasks.DecoratedCommand.endAction(DecoratedCommand.java:17) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CoCoAsyncTaskHelper.endAction(CoCoAsyncTaskHelper.java:359) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCoordinatorImpl.endAction(CommandCoordinatorImpl.java:415) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandAsyncTask.endCommandAction(CommandAsyncTask.java:168) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandAsyncTask.access$000(CommandAsyncTask.java:30) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandAsyncTask$1.run(CommandAsyncTask.java:111) [bll.jar:] at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92) [utils.jar:] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_91] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_91] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_91] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_91] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_91] 2016-01-28 14:39:33,766 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-35) [] CommandAsyncTask::HandleEndActionResult: endAction for action type 'MoveOrCopyDisk' threw an unrecoverable RuntimeException the task will be cleared. Version-Release number of selected component (if applicable): rhevm-3.6.2.6-0.1.el6.noarch vdsm-4.17.18-0.el7ev.noarch How reproducible: 100% Steps to Reproduce: 1. Copy template disk to other SD 2. 3. Actual results: Expected results: The operation should finish without 'NullPointerException' Additional info: