cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Abhinandan Prateek (JIRA)" <j...@apache.org>
Subject [jira] [Resolved] (CLOUDSTACK-4975) NPE while deleting the volume
Date Wed, 30 Oct 2013 04:36:25 GMT

     [ 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)

Mime
View raw message