[
https://issues.apache.org/jira/browse/CLOUDSTACK-4363?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13743050#comment-13743050
]
Kelven Yang commented on CLOUDSTACK-4363:
-----------------------------------------
This NPE itself has nothing related to changes made in CLOUDSTACK-3237. It
happens in the code path when cleaning up a failed operation at
imageStore.delete
Answer answer = this.copyObject(srcData, objOnImageStore);
if (answer == null || !answer.getResult()) {
if (answer != null) {
s_logger.debug("copy to image store failed: " +
answer.getDetails());
}
objOnImageStore.processEvent(Event.OperationFailed);
imageStore.delete(objOnImageStore);
return answer;
}
Edison, please fix the error handling process to make it safe for runtime NPE,
since CopyObject operation failure can be caused both by runtime situation (for
example, out of storage space) or program logic error(bug), for whatever the
reason, the high-level error handling (cleanup) process needs to take it
gracefully.
manassavelori,
to determine why CopyObject failed on VMware, I need logs from SSVM for further
investigation, if you find the log, file a separated bug that contains real
VMware resource failure logs.
> [VMware]Migration of data volume is throwing NPE
> -------------------------------------------------
>
> Key: CLOUDSTACK-4363
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4363
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Storage Controller
> Affects Versions: 4.2.0
> Reporter: manasaveloori
> Assignee: Kelven Yang
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: management-server.log
>
>
> Steps:
> 1. Have a CS 4.2 with VMware host.
> 2. Have primary- 1 local and 2 shared(NFS) and secondary-NFS.
> 3. Create a shared data volume.
> 4. Migrate it to either shared primary or local primary.
> Observation.
> Migration of the volume is failing with NPE:
> 2013-08-16 19:13:13,754 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
> ===START=== 10.252.192.69 -- GET
> command=migrateVolume&storageid=9c5838f1-4874-4dea-b396-d318f56ff192&volumeid=53059246-e850-480a-9315-9fa647c9b17d&response=json&sessionkey=x3AM9LcYvZ%2FzkGJ8%2BLR2uNIPzOs%3D&_=1376641214226
> 2013-08-16 19:13:14,719 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-5:null) submit async job-33 = [
> 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ], details: AsyncJobVO {id:33, userId:
> 2, accountId: 2, sessionKey: null, instanceType: None, instanceId: null, cmd:
> org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd,
> cmdOriginator: null, cmdInfo:
> {"response":"json","sessionkey":"x3AM9LcYvZ/zkGJ8+LR2uNIPzOs\u003d","cmdEventType":"VOLUME.MIGRATE","ctxUserId":"2","storageid":"9c5838f1-4874-4dea-b396-d318f56ff192","httpmethod":"GET","volumeid":"53059246-e850-480a-9315-9fa647c9b17d","_":"1376641214226","ctxAccountId":"2","ctxStartEventId":"106"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 7067804893289,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-16 19:13:14,723 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
> ===END=== 10.252.192.69 -- GET
> command=migrateVolume&storageid=9c5838f1-4874-4dea-b396-d318f56ff192&volumeid=53059246-e850-480a-9315-9fa647c9b17d&response=json&sessionkey=x3AM9LcYvZ%2FzkGJ8%2BLR2uNIPzOs%3D&_=1376641214226
> 2013-08-16 19:13:14,727 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Executing
> org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd for job-33 = [
> 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]
> 2013-08-16 19:13:14,780 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-5:null) SeqA 2-786: Processing Seq 2-786: { Cmd ,
> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2013-08-16 19:13:14,799 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-5:null) SeqA 2-786: Sending Seq 2-786: { Ans: ,
> MgmtId: 7067804893289, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-16 19:13:14,835 DEBUG [storage.motion.AncientDataMotionStrategy]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) copyAsync
> inspecting src type VOLUME copyAsync inspecting dest type VOLUME
> 2013-08-16 19:13:14,845 DEBUG [cache.allocator.StorageCacheRandomAllocator]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Can't
> find staging storage in zone: 1
> 2013-08-16 19:13:14,973 DEBUG [agent.transport.Request]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Seq
> 3-173277305: Sending { Cmd , MgmtId: 7067804893289, via: 3, Ver: v1, Flags:
> 100011,
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"53059246-e850-480a-9315-9fa647c9b17d","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"f672eae0-b400-3767-808f-b787a5c04d5f","id":2,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/manasa/primaryVMw","port":2049}},"name":"shared","size":5368709120,"path":"1d3265f1faa2452e860d13bcd05c9ec7","volumeId":9,"accountId":2,"format":"OVA","id":9,"hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"53059246-e850-480a-9315-9fa647c9b17d","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/manasa/secondaryVMw","_role":"Image"}},"name":"shared","size":5368709120,"path":"volumes/2/9","volumeId":9,"accountId":2,"format":"OVA","id":9,"hypervisorType":"VMware"}},"executeInSequence":false,"wait":10800}}]
> }
> 2013-08-16 19:13:16,331 DEBUG [agent.transport.Request]
> (AgentManager-Handler-7:null) Seq 3-173277305: Processing: { Ans: , MgmtId:
> 7067804893289, via: 3, Ver: v1, Flags: 10,
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"copy
> volume from primary to secondary failed due to exception: Exception:
> java.lang.NullPointerException\nMessage: null\n","wait":0}}] }
> 2013-08-16 19:13:16,331 DEBUG [agent.transport.Request]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Seq
> 3-173277305: Received: { Ans: , MgmtId: 7067804893289, via: 3, Ver: v1,
> Flags: 10, { CopyCmdAnswer } }
> 2013-08-16 19:13:16,338 DEBUG [storage.motion.AncientDataMotionStrategy]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) copy to
> image store failed: copy volume from primary to secondary failed due to
> exception: Exception: java.lang.NullPointerException
> Message: null
> 2013-08-16 19:13:16,361 DEBUG [storage.image.BaseImageStoreDriverImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Unable to
> destoy VOLUME: 9
> java.lang.NullPointerException
> at
> org.apache.cloudstack.storage.volume.VolumeObject.getPath(VolumeObject.java:338)
> at
> org.apache.cloudstack.storage.to.VolumeObjectTO.<init>(VolumeObjectTO.java:53)
> at
> org.apache.cloudstack.storage.volume.VolumeObject.getTO(VolumeObject.java:460)
> at
> org.apache.cloudstack.storage.image.BaseImageStoreDriverImpl.deleteAsync(BaseImageStoreDriverImpl.java:237)
> at
> org.apache.cloudstack.storage.image.store.ImageStoreImpl.delete(ImageStoreImpl.java:148)
> at
> org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyVolumeBetweenPools(AncientDataMotionStrategy.java:323)
> at
> org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:406)
> at
> org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:55)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:790)
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2239)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2228)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd.execute(MigrateVolumeCmd.java:103)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-08-16 19:13:16,365 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-33:job-33 = [
> 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Volume 9 is not found on image store
> 1, so no need to delete
> 2013-08-16 19:13:16,379 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-33:job-33 = [
> 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Unsupported data object (VOLUME,
> org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@4b78a0af), no
> need to delete from object in store ref table
> 2013-08-16 19:13:16,394 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-33:job-33 = [
> 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Unsupported data object (VOLUME,
> org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@3af189a6), no
> need to delete from object in store ref table
> 2013-08-16 19:13:16,491 DEBUG [agent.transport.Request]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Seq
> 1-473956798: Sending { Cmd , MgmtId: 7067804893289, via: 1, Ver: v1, Flags:
> 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a35ac140-b3a6-4aa7-a84b-950bf3f51789","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9c5838f1-4874-4dea-b396-d318f56ff192","id":1,"poolType":"LVM","host":"10.147.40.25","path":"datastore-11514","port":0}},"name":"shared","size":5368709120,"path":"1d3265f1faa2452e860d13bcd05c9ec7","volumeId":10,"accountId":2,"id":10,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-08-16 19:13:16,492 DEBUG [agent.transport.Request]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Seq
> 1-473956798: Executing: { Cmd , MgmtId: 7067804893289, via: 1, Ver: v1,
> Flags: 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a35ac140-b3a6-4aa7-a84b-950bf3f51789","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9c5838f1-4874-4dea-b396-d318f56ff192","id":1,"poolType":"LVM","host":"10.147.40.25","path":"datastore-11514","port":0}},"name":"shared","size":5368709120,"path":"1d3265f1faa2452e860d13bcd05c9ec7","volumeId":10,"accountId":2,"id":10,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-08-16 19:13:16,492 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-114:null) Seq 1-473956798: Executing request
> 2013-08-16 19:13:16,503 INFO [storage.resource.VmwareStorageProcessor]
> (DirectAgent-114:10.147.40.25) Executing resource DestroyCommand:
> {"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a35ac140-b3a6-4aa7-a84b-950bf3f51789","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"9c5838f1-4874-4dea-b396-d318f56ff192","id":1,"poolType":"LVM","host":"10.147.40.25","path":"datastore-11514","port":0}},"name":"shared","size":5368709120,"path":"1d3265f1faa2452e860d13bcd05c9ec7","volumeId":10,"accountId":2,"id":10,"hypervisorType":"VMware"}},"wait":0}
> 2013-08-16 19:13:16,625 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk on [datastore1]
> 2013-08-16 19:13:16,649 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk does not exist on datastore
> 2013-08-16 19:13:16,654 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk on [datastore1]
> 2013-08-16 19:13:16,676 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk does not exist on datastore
> 2013-08-16 19:13:16,676 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Searching file
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk in [datastore1]
> 2013-08-16 19:13:16,706 WARN [storage.resource.VmwareStorageLayoutHelper]
> (DirectAgent-114:10.147.40.25) Unable to locate VMDK file:
> 1d3265f1faa2452e860d13bcd05c9ec7.vmdk
> 2013-08-16 19:13:16,711 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk on [datastore1]
> 2013-08-16 19:13:16,733 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk does not exist on datastore
> 2013-08-16 19:13:16,737 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk on [datastore1]
> 2013-08-16 19:13:16,761 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk does not exist on datastore
> 2013-08-16 19:13:16,761 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Searching file
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk in [datastore1]
> 2013-08-16 19:13:16,790 WARN [storage.resource.VmwareStorageLayoutHelper]
> (DirectAgent-114:10.147.40.25) Unable to locate VMDK file:
> 1d3265f1faa2452e860d13bcd05c9ec7-flat.vmdk
> 2013-08-16 19:13:16,794 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk on [datastore1]
> 2013-08-16 19:13:16,814 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk does not exist on datastore
> 2013-08-16 19:13:16,818 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Search file
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk on [datastore1]
> 2013-08-16 19:13:16,841 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) File [datastore1]
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk does not exist on datastore
> 2013-08-16 19:13:16,842 INFO [vmware.mo.DatastoreMO]
> (DirectAgent-114:10.147.40.25) Searching file
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk in [datastore1]
> 2013-08-16 19:13:16,867 WARN [storage.resource.VmwareStorageLayoutHelper]
> (DirectAgent-114:10.147.40.25) Unable to locate VMDK file:
> 1d3265f1faa2452e860d13bcd05c9ec7-delta.vmdk
> 2013-08-16 19:13:16,868 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-114:null) Seq 1-473956798: Response Received:
> 2013-08-16 19:13:16,869 DEBUG [agent.transport.Request]
> (DirectAgent-114:null) Seq 1-473956798: Processing: { Ans: , MgmtId:
> 7067804893289, via: 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"details":"Success","wait":0}}]
> }
> 2013-08-16 19:13:16,869 DEBUG [agent.transport.Request]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Seq
> 1-473956798: Received: { Ans: , MgmtId: 7067804893289, via: 1, Ver: v1,
> Flags: 10, { Answer } }
> 2013-08-16 19:13:16,888 INFO [storage.volume.VolumeServiceImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Volume 10
> is not referred anywhere, remove it from volumes table
> 2013-08-16 19:13:16,902 ERROR [cloud.storage.VolumeManagerImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) migrate
> volume failed:copy volume from primary to secondary failed due to exception:
> Exception: java.lang.NullPointerException
> Message: null
> 2013-08-16 19:13:16,904 DEBUG [cloud.storage.VolumeManagerImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Failed to
> migrate volume:
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
> unreachable: migrate volume failed: copy volume from primary to secondary
> failed due to exception: Exception: java.lang.NullPointerException
> Message: null
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2244)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2228)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd.execute(MigrateVolumeCmd.java:103)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-08-16 19:13:16,908 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-33:job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ]) Complete
> async job-33 = [ 44dc9aa6-1655-4bfd-9252-f96cbc6b55eb ], jobStatus: 2,
> resultCode: 530, result: Error Code: 530 Error text: Failed to migrate volume
> Attaching the MS logs
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
