[
https://issues.apache.org/jira/browse/CLOUDSTACK-4975?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Abhinandan Prateek resolved CLOUDSTACK-4975.
--------------------------------------------
Resolution: Won't Fix
> NPE while deleting the volume
> -----------------------------
>
> Key: CLOUDSTACK-4975
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4975
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Storage Controller, VMware
> Affects Versions: 4.2.1
> Reporter: Sailaja Mada
> Assignee: Likitha Shetty
> Priority: Critical
> Fix For: 4.2.1
>
> Attachments: newlogs.rar
>
>
> Steps:
> 1. Configure Adv zone with VMWARE Hypervisor
> 2. Created shared network with ROOT domain as scope
> 3. Created a user account and deployed VM using this shared network
> 4. After VM is up and running , Destroy the VM
> Observation:
> Observed NPE while deleting the volume.
> 2013-10-28 14:24:07,209 INFO [storage.resource.VmwareStorageProcessor]
> (DirectAgent-442:10.102.192.23) Executing resource DestroyCommand:
> {"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"739f096d-1b1d-4c20-895f-c416c95bace5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7e18404c-acd1-3b13-9c9c-bbaf2d28bccd","id":4,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newdixonps3","port":2049}},"name":"ROOT-205","size":2147483648,"path":"ROOT-205","volumeId":217,"vmName":"i-6-205-userinstance","accountId":6,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[7e18404cacd13b139c9cbbaf2d28bccd]
>
> i-6-205-userinstance/ROOT-205.vmdk\"]}","format":"OVA","id":217,"hypervisorType":"VMware"}},"wait":0}
> 2013-10-28 14:24:07,343 INFO [storage.resource.VmwareStorageProcessor]
> (DirectAgent-442:10.102.192.23) Destroy root volume and VM itself. vmName
> i-6-205-userinstance
> 2013-10-28 14:24:07,376 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
> ===START=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950771190
> 2013-10-28 14:24:07,383 DEBUG [vmware.mo.VirtualMachineMO]
> (DirectAgent-442:10.102.192.23) Retrieved 1 networks with key : 2
> 2013-10-28 14:24:07,414 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
> ===END=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950771190
> 2013-10-28 14:24:10,374 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
> ===START=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950774191
> 2013-10-28 14:24:10,398 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
> ===END=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950774191
> 2013-10-28 14:24:12,978 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) SeqA 3-66860: Processing Seq 3-66860: { Cmd ,
> MgmtId: -1, via: 3, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2013-10-28 14:24:12,984 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) SeqA 3-66860: Sending Seq 3-66860: { Ans: ,
> MgmtId: 187767034175903, via: 3, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-10-28 14:24:13,371 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-375:null) Ping from 5
> 2013-10-28 14:24:13,585 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
> ===START=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950777196
> 2013-10-28 14:24:13,606 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
> ===END=== 10.104.255.45 -- GET
> command=queryAsyncJobResult&jobId=805d2fd9-ce54-49db-a2a0-3479c0eeee84&response=json&sessionkey=t%2FFTuAD%2Fvg3MVIIB7VszPAxZw40%3D&_=1382950777196
> 2013-10-28 14:24:23,403 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (UserVm-Scavenger-1:null) Stopped called on VM[User|newuser1f5instance1] but
> the state is Expunging
> 2013-10-28 14:24:23,412 DEBUG [cloud.capacity.CapacityManagerImpl]
> (UserVm-Scavenger-1:null) VM state transitted from :Expunging to Expunging
> with event: ExpungeOperationvm's original host id: 1 new host id: null host
> id before state transition: null
> 2013-10-28 14:24:23,412 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (UserVm-Scavenger-1:null) Destroying vm VM[User|newuser1f5instance1]
> 2013-10-28 14:24:23,412 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (UserVm-Scavenger-1:null) Cleaning up NICS
> 2013-10-28 14:24:23,414 DEBUG [cloud.network.NetworkManagerImpl]
> (UserVm-Scavenger-1:null) Cleaning network for vm: 205
> 2013-10-28 14:24:23,417 DEBUG [cloud.storage.VolumeManagerImpl]
> (UserVm-Scavenger-1:null) Cleaning storage for vm: 205
> 2013-10-28 14:24:23,419 DEBUG [cloud.storage.VolumeManagerImpl]
> (UserVm-Scavenger-1:null) Skipping destroy for the volume
> Vol[217|vm=205|ROOT] as its in state Expunging
> 2013-10-28 14:24:23,451 DEBUG [agent.transport.Request]
> (UserVm-Scavenger-1:null) Seq 1-1580729924: Sending { Cmd , MgmtId:
> 187767034175903, via: 1, Ver: v1, Flags: 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"739f096d-1b1d-4c20-895f-c416c95bace5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7e18404c-acd1-3b13-9c9c-bbaf2d28bccd","id":4,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newdixonps3","port":2049}},"name":"ROOT-205","size":2147483648,"path":"ROOT-205","volumeId":217,"vmName":"i-6-205-userinstance","accountId":6,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[7e18404cacd13b139c9cbbaf2d28bccd]
>
> i-6-205-userinstance/ROOT-205.vmdk\"]}","format":"OVA","id":217,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-10-28 14:24:23,452 DEBUG [agent.transport.Request]
> (UserVm-Scavenger-1:null) Seq 1-1580729924: Executing: { Cmd , MgmtId:
> 187767034175903, via: 1, Ver: v1, Flags: 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"739f096d-1b1d-4c20-895f-c416c95bace5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7e18404c-acd1-3b13-9c9c-bbaf2d28bccd","id":4,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newdixonps3","port":2049}},"name":"ROOT-205","size":2147483648,"path":"ROOT-205","volumeId":217,"vmName":"i-6-205-userinstance","accountId":6,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[7e18404cacd13b139c9cbbaf2d28bccd]
>
> i-6-205-userinstance/ROOT-205.vmdk\"]}","format":"OVA","id":217,"hypervisorType":"VMware"}},"wait":0}}]
> }
> 2013-10-28 14:24:23,452 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-375:null) Seq 1-1580729924: Executing request
> 2013-10-28 14:24:23,452 INFO [storage.resource.VmwareStorageProcessor]
> (DirectAgent-375:10.102.192.23) Executing resource DestroyCommand:
> {"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"739f096d-1b1d-4c20-895f-c416c95bace5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7e18404c-acd1-3b13-9c9c-bbaf2d28bccd","id":4,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newdixonps3","port":2049}},"name":"ROOT-205","size":2147483648,"path":"ROOT-205","volumeId":217,"vmName":"i-6-205-userinstance","accountId":6,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[7e18404cacd13b139c9cbbaf2d28bccd]
>
> i-6-205-userinstance/ROOT-205.vmdk\"]}","format":"OVA","id":217,"hypervisorType":"VMware"}},"wait":0}
> 2013-10-28 14:24:23,572 INFO [storage.resource.VmwareStorageProcessor]
> (DirectAgent-375:10.102.192.23) Destroy root volume and VM itself. vmName
> i-6-205-userinstance
> 2013-10-28 14:24:23,605 DEBUG [vmware.mo.VirtualMachineMO]
> (DirectAgent-375:10.102.192.23) Retrieved 1 networks with key : 2
> 2013-10-28 14:24:25,165 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-442:null) Seq 1-1580729923: Response Received:
> 2013-10-28 14:24:25,166 DEBUG [agent.transport.Request]
> (DirectAgent-442:null) Seq 1-1580729923: Processing: { Ans: , MgmtId:
> 187767034175903, via: 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"details":"Success","wait":0}}]
> }
> 2013-10-28 14:24:25,166 DEBUG [agent.transport.Request]
> (Job-Executor-101:job-95 = [ 805d2fd9-ce54-49db-a2a0-3479c0eeee84 ]) Seq
> 1-1580729923: Received: { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1,
> Flags: 10, { Answer } }
> 2013-10-28 14:24:25,178 INFO [storage.volume.VolumeServiceImpl]
> (Job-Executor-101:job-95 = [ 805d2fd9-ce54-49db-a2a0-3479c0eeee84 ]) Volume
> 217 is not referred anywhere, remove it from volumes table
> 2013-10-28 14:24:25,189 ERROR [storage.resource.VmwareStorageProcessor]
> (DirectAgent-375:10.102.192.23) delete volume failed due to Exception:
> javax.xml.ws.soap.SOAPFaultException
> Message: The object has already been deleted or has not been completely
> created
> javax.xml.ws.soap.SOAPFaultException: The object has already been deleted or
> has not been completely created
> at
> com.sun.xml.internal.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:178)
> at
> com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:119)
> at
> com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108)
> at
> com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78)
> at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:107)
> at $Proxy91.destroyTask(Unknown Source)
> at com.cloud.hypervisor.vmware.mo.BaseMO.destroy(BaseMO.java:73)
> at
> com.cloud.storage.resource.VmwareStorageProcessor.deleteVolume(VmwareStorageProcessor.java:1508)
> at
> com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:114)
> at
> com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:53)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:559)
> at
> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> 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-10-28 14:24:25,195 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-375:null) Seq 1-1580729924: Response Received:
> 2013-10-28 14:24:25,195 DEBUG [agent.transport.Request]
> (DirectAgent-375:null) Seq 1-1580729924: Processing: { Ans: , MgmtId:
> 187767034175903, via: 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":false,"details":"delete volume
> failed due to Exception: javax.xml.ws.soap.SOAPFaultException\nMessage: The
> object has already been deleted or has not been completely
> created\n","wait":0}}] }
> 2013-10-28 14:24:25,196 DEBUG [agent.transport.Request]
> (UserVm-Scavenger-1:null) Seq 1-1580729924: Received: { Ans: , MgmtId:
> 187767034175903, via: 1, Ver: v1, Flags: 10, { Answer } }
> 2013-10-28 14:24:25,197 DEBUG [storage.volume.VolumeObject]
> (UserVm-Scavenger-1:null) Failed to update state
> java.lang.NullPointerException
> at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:99)
> at
> org.apache.cloudstack.storage.volume.VolumeObject.stateTransit(VolumeObject.java:153)
> at
> org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:288)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.deleteVolumeCallback(VolumeServiceImpl.java:311)
> at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
> at
> org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
> at
> org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
> at
> org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.deleteAsync(CloudStackPrimaryDataStoreDriverImpl.java:177)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:293)
> at
> com.cloud.storage.VolumeManagerImpl.cleanupVolumes(VolumeManagerImpl.java:2180)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceExpunge(VirtualMachineManagerImpl.java:479)
> at com.cloud.vm.UserVmManagerImpl.expunge(UserVmManagerImpl.java:1598)
> at
> com.cloud.vm.UserVmManagerImpl$ExpungeTask.run(UserVmManagerImpl.java:1767)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> 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-10-28 14:24:25,199 DEBUG [storage.volume.VolumeServiceImpl]
> (UserVm-Scavenger-1:null) ignore delete volume status update failure, it will
> be picked up by storage clean up thread later
> java.lang.NullPointerException
> at
> org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:294)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.deleteVolumeCallback(VolumeServiceImpl.java:311)
> at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
> at
> org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
> at
> org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
> at
> org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.deleteAsync(CloudStackPrimaryDataStoreDriverImpl.java:177)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:293)
> at
> com.cloud.storage.VolumeManagerImpl.cleanupVolumes(VolumeManagerImpl.java:2180)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceExpunge(VirtualMachineManagerImpl.java:479)
> at com.cloud.vm.UserVmManagerImpl.expunge(UserVmManagerImpl.java:1598)
> at
> com.cloud.vm.UserVmManagerImpl$ExpungeTask.run(UserVmManagerImpl.java:1767)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> 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-10-28 14:24:25,206 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-101:job-95 = [ 805d2fd9-ce54-49db-a2a0-3479c0eeee84 ]) Expunged
> VM[User|newuser1f5instance1]
> 2013-10-28 14:24:25,210 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (UserVm-Scavenger-1:null) Expunged VM[User|newuser1f5instance1]
--
This message was sent by Atlassian JIRA
(v6.1#6144)
