Sailaja Mada created CLOUDSTACK-4975:
----------------------------------------
Summary: 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
Priority: Critical
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)
