cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Likitha Shetty (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CLOUDSTACK-4975) NPE while deleting the volume
Date Tue, 29 Oct 2013 10:38:30 GMT

    [ https://issues.apache.org/jira/browse/CLOUDSTACK-4975?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13807863#comment-13807863
] 

Likitha Shetty commented on CLOUDSTACK-4975:
--------------------------------------------

In the reported issue an NPE is thrown during the ROOT volume deletion of a VM because -
There are 2 jobs that are running in parallel. First one is the account cleanup job that deletes
the account including all its resources. Second one is the VM expunge task that runs periodically
to expunge any VM that has been destroyed or is in an expunging state.
In this case both the jobs are trying to cleanup the same VM simultaneously. When the second
job is trying to cleanup the ROOT volume of VM 205, since the volume has not yet been expunged
it makes a call to the hypervisor host to delete the volume. But in the mean time the host
has already deleted the volume because of the expunge request made by the first job. And this
results in an NPE during state transition being made by the second job.

But both jobs exit successfully 

2013-10-28 14:24:25,572 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-101:job-95 =
[ 805d2fd9-ce54-49db-a2a0-3479c0eeee84 ]) Done executing org.apache.cloudstack.api.command.admin.account.DeleteAccountCmd
for job-95 = [ 805d2fd9-ce54-49db-a2a0-3479c0eeee84 ]

2013-10-28 14:24:25,306 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-1:null) Successfully
cleaned up vm VM[User|newuser1f5instance1] resources as a part of expunge process

> 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