Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 27B1E1075E for ; Mon, 28 Oct 2013 15:12:45 +0000 (UTC) Received: (qmail 91610 invoked by uid 500); 28 Oct 2013 15:12:42 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 91495 invoked by uid 500); 28 Oct 2013 15:12:39 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 91485 invoked by uid 500); 28 Oct 2013 15:12:38 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 91452 invoked by uid 99); 28 Oct 2013 15:12:35 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 28 Oct 2013 15:12:35 +0000 Date: Mon, 28 Oct 2013 15:12:35 +0000 (UTC) From: "Abhinandan Prateek (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-4975) NPE while deleting the volume MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-4975?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Abhinandan Prateek updated CLOUDSTACK-4975: ------------------------------------------- Assignee: Likitha Shetty > 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)