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 7D289F962 for ; Tue, 13 Aug 2013 12:45:51 +0000 (UTC) Received: (qmail 10970 invoked by uid 500); 13 Aug 2013 12:45:50 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 10946 invoked by uid 500); 13 Aug 2013 12:45:50 -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 10927 invoked by uid 500); 13 Aug 2013 12:45:50 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 10919 invoked by uid 99); 13 Aug 2013 12:45:50 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 13 Aug 2013 12:45:50 +0000 Date: Tue, 13 Aug 2013 12:45:50 +0000 (UTC) From: "sadhu suresh (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-4292) ceph:destroyedvm failed with ArrayIndexexception while expunging MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-4292?page=3Dcom.atl= assian.jira.plugin.system.issuetabpanels:all-tabpanel ] sadhu suresh updated CLOUDSTACK-4292: ------------------------------------- Attachment: management-server.rar management log =20 > ceph:destroyedvm failed with ArrayIndexexception while expunging > ---------------------------------------------------------------- > > Key: CLOUDSTACK-4292 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-429= 2 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Management Server > Affects Versions: 4.2.0 > Reporter: sadhu suresh > Priority: Critical > Attachments: management-server.rar > > > delete volume is faling while expunging the VM in case of Ceph enabled VM= where as VM deployed on NFS its successful. > steps: > 1.deploy a VM with data disk in ceph enabled cluster(create compute offei= ng with ceph details and use this offering) > 2.Once its successful ,destroy the instance > Actual result: > Noticed exception while expunging the volume on Agent side and on managem= ent side noticed warning > (UserVm-Scavenger-1:null) Unsupported data object (VOLUME, org.apache.clo= udstack.storage.datastore.PrimaryDataStoreImpl@23 > Management log: > ******************* > 2013-08-13 13:32:10,906 DEBUG [agent.transport.Request] (AgentManager-Han= dler-12:null) Seq 7-1066224215: Processing: { Ans: , MgmtId: 7296881000534= , via: 7, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"= routerName":"r-49-VM","bytesSent":0,"bytesReceived":0,"result":true,"detail= s":"","wait":0}}] } > 2013-08-13 13:32:10,907 DEBUG [agent.transport.Request] (RouterMonitor-1:= null) Seq 7-1066224215: Received: { Ans: , MgmtId: 7296881000534, via: 7, = Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-08-13 13:32:10,907 DEBUG [agent.manager.AgentManagerImpl] (RouterMon= itor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageC= ommand: > 2013-08-13 13:32:10,907 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not upd= ating user_statistics > 2013-08-13 13:32:11,532 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (S= napshotPollTask:null) Snapshot scheduler.poll is being called at 2013-08-13= 17:32:11 GMT > 2013-08-13 13:32:11,534 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (S= napshotPollTask:null) Got 0 snapshots to be executed at 2013-08-13 17:32:11= GMT > 2013-08-13 13:32:14,031 INFO [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Found 1 vms to expunge. > 2013-08-13 13:32:14,031 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserV= m-Scavenger-1:null) Stopped called on VM[User|VM11] but the state is Destro= yed > 2013-08-13 13:32:14,134 DEBUG [cloud.capacity.CapacityManagerImpl] (UserV= m-Scavenger-1:null) VM state transitted from :Destroyed to Expunging with e= vent: ExpungeOperationvm's original host id: 7 new host id: null host id be= fore state transition: null > 2013-08-13 13:32:14,134 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserV= m-Scavenger-1:null) Destroying vm VM[User|VM11] > 2013-08-13 13:32:14,141 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserV= m-Scavenger-1:null) Cleaning up NICS > 2013-08-13 13:32:14,141 DEBUG [cloud.network.NetworkManagerImpl] (UserVm-= Scavenger-1:null) Cleaning network for vm: 56 > 2013-08-13 13:32:14,150 DEBUG [cloud.network.NetworkModelImpl] (UserVm-Sc= avenger-1:null) Service SecurityGroup is not supported in the network id=3D= 214 > 2013-08-13 13:32:14,161 DEBUG [cloud.network.NetworkManagerImpl] (UserVm-= Scavenger-1:null) Removed nic id=3D114 > 2013-08-13 13:32:14,163 DEBUG [cloud.network.NetworkManagerImpl] (UserVm-= Scavenger-1:null) Revoving nic secondary ip entry ... > 2013-08-13 13:32:14,166 DEBUG [cloud.storage.VolumeManagerImpl] (UserVm-S= cavenger-1:null) Cleaning storage for vm: 56 > 2013-08-13 13:32:14,179 DEBUG [cloud.storage.VolumeManagerImpl] (UserVm-S= cavenger-1:null) Detaching Vol[75|vm=3D56|DATADISK] > 2013-08-13 13:32:14,414 DEBUG [agent.transport.Request] (UserVm-Scavenger= -1:null) Seq 7-1066224216: Sending { Cmd , MgmtId: 7296881000534, via: 7, = Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteComm= and":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"ec= a53a6a-0ba9-4776-aee8-b92a92f9abc9","volumeType":"ROOT","dataStore":{"org.a= pache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"8e7c6fb5-c4d7-38f9= -9cb1-d34d3bba4957","id":20,"poolType":"RBD","host":"10.147.41.3","path":"c= loudstack","port":6789}},"name":"ROOT-56","size":8589934592,"path":"2c57ebf= 6-8ae7-4c73-8365-6b4b6f7e3ffd","volumeId":69,"vmName":"i-2-56-VM","accountI= d":2,"format":"QCOW2","id":69,"hypervisorType":"KVM"}},"wait":0}}] } > 2013-08-13 13:32:14,779 DEBUG [agent.transport.Request] (AgentManager-Han= dler-4:null) Seq 7-1066224216: Processing: { Ans: , MgmtId: 7296881000534,= via: 7, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false= ,"details":"java.lang.ArrayIndexOutOfBoundsException: 0\n\tat com.sun.jna.S= tructure.toArray(Structure.java:1042)\n\tat com.sun.jna.Structure.toArray(S= tructure.java:1065)\n\tat com.ceph.rbd.RbdImage.snapList(Unknown Source)\n\= tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDi= sk(LibvirtStorageAdaptor.java:719)\n\tat com.cloud.hypervisor.kvm.storage.L= ibvirtStoragePool.deletePhysicalDisk(LibvirtStoragePool.java:128)\n\tat com= .cloud.hypervisor.kvm.storage.KVMStorageProcessor.deleteVolume(KVMStoragePr= ocessor.java:936)\n\tat com.cloud.storage.resource.StorageSubsystemCommandH= andlerBase.execute(StorageSubsystemCommandHandlerBase.java:114)\n\tat com.c= loud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageComma= nds(StorageSubsystemCommandHandlerBase.java:53)\n\tat com.cloud.hypervisor.= kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResour= ce.java:1284)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\= tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat = com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.Threa= dPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concu= rrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java= .lang.Thread.run(Thread.java:679)\n","wait":0}}] } > 2013-08-13 13:32:14,779 DEBUG [agent.transport.Request] (UserVm-Scavenger= -1:null) Seq 7-1066224216: Received: { Ans: , MgmtId: 7296881000534, via: = 7, Ver: v1, Flags: 10, { Answer } } > 2013-08-13 13:32:14,887 WARN [storage.datastore.ObjectInDataStoreManager= Impl] (UserVm-Scavenger-1:null) Unsupported data object (VOLUME, org.apache= .cloudstack.storage.datastore.PrimaryDataStoreImpl@237dae26) > 2013-08-13 13:32:14,892 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserV= m-Scavenger-1:null) Expunged VM[User|VM11] > 2013-08-13 13:32:14,919 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Starting cleaning up vm VM[User|VM11] resources... > 2013-08-13 13:32:14,930 DEBUG [network.firewall.FirewallManagerImpl] (Use= rVm-Scavenger-1:null) No firewall rules are found for vm id=3D56 > 2013-08-13 13:32:14,930 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Firewall rules are removed successfully as a part of vm id=3D56= expunge > 2013-08-13 13:32:14,935 DEBUG [network.rules.RulesManagerImpl] (UserVm-Sc= avenger-1:null) No port forwarding rules are found for vm id=3D56 > 2013-08-13 13:32:14,935 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Port forwarding rules are removed successfully as a part of vm = id=3D56 expunge > 2013-08-13 13:32:14,938 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Removed vm id=3D56 from all load balancers as a part of expunge= process > 2013-08-13 13:32:14,940 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scaven= ger-1:null) Successfully cleaned up vm VM[User|VM11] resources as a part of= expunge process > 2013-08-13 13:32:18,492 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-14:null) SeqA 10-13543: Processing Seq 10-13543: { Cmd , MgmtI= d: -1, via: 10, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoad= ReportCommand":{"_proxyVmId":39,"_loadInfo":"{\n \"connections\": []\n}","= wait":0}}] } > 2013-08-13 13:32:18,498 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-14:null) SeqA 10-13543: Sending Seq 10-13543: { Ans: , MgmtId:= 7296881000534, via: 10, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.Age= ntControlAnswer":{"result":true,"wait":0}}] } > 2013-08-13 13:32:20,696 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-155:null) Ping from 4 > 2013-08-13 13:32:21,111 DEBUG [network.lb.LBHealthCheckManagerImpl] (LBHe= althCheck-1:null) LB HealthCheck Manager is running and getting the updates= from LB providers and updating service status > 2013-08-13 13:32:21,168 DEBUG [network.lb.LBHealthCheckManagerImpl] (LBHe= althCheck-1:null) LB HealthCheck Manager is running and getting the updates= from LB providers and updating service status > 2013-08-13 13:32:24,117 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-26:null) Ping from 1 > 2013-08-13 13:32:25,298 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-155:null) Ping from 5 > 2013-08-13 13:32:26,555 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-426:null) Seq 1-826605573: Executing request > 2013-08-13 13:32:26,610 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-5:null) Ping from 10 > 2013-08-13 13:32:26,746 DEBUG [agent.manager.DirectAgentAttache] (DirectA= gent-426:null) Seq 1-826605573: Response Received: > 2013-08-13 13:32:26,746 DEBUG [agent.transport.Request] (DirectAgent-426:= null) Seq 1-826605573: Processing: { Ans: , MgmtId: 7296881000534, via: 1,= Ver: v1, Flags: 10, [{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId= ":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] } > 2013-08-13 13:32:26,747 DEBUG [agent.manager.AgentAttache] (DirectAgent-4= 26:null) Seq 1-826605573: Unable to find listener. > 2013-08-13 13:32:28,493 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-13:null) SeqA 10-13545: Processing Seq 10-13545: { Cmd , MgmtI= d: -1, via: 10, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoad= ReportCommand":{"_proxyVmId":39,"_loadInfo":"{\n \"connections\": []\n}","= wait":0}}] } > 2013-08-13 13:32:28,506 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-13:null) SeqA 10-13545: Sending Seq 10-13545: { Ans: , MgmtId:= 7296881000534, via: 10, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.Age= ntControlAnswer":{"result":true,"wait":0}}] } > 2013-08-13 13:32:29,387 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-8:null) Ping from 7 > 2013-08-13 13:32:33,518 DEBUG [cloud.server.StatsCollector] (StatsCollect= or-3:null) VmStatsCollector is running... > 2013-08-13 13:32:33,599 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 7-1066224217: Received: { Ans: , MgmtId: 7296881000534, via: 7,= Ver: v1, Flags: 10, { GetVmStatsAnswer } } > 2013-08-13 13:32:38,494 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-15:null) SeqA 10-13546: Processing Seq 10-1 > Build:CloudPlatform-4.2-338-rhel6.3.tar.gz > AGENT.log > ************ > 2013-08-13 17:34:01,048 TRACE [utils.nio.NioConnection] (Agent-Selector:n= ull) Keys Processing: 1 > 2013-08-13 17:34:01,048 TRACE [utils.nio.NioConnection] (Agent-Selector:n= ull) Reading from: Socket[addr=3D/10.147.59.110,port=3D8250,localport=3D476= 05] > 2013-08-13 17:34:01,049 TRACE [utils.nio.Link] (Agent-Selector:null) Done= with packet: 623 > 2013-08-13 17:34:01,049 TRACE [utils.nio.NioConnection] (Agent-Selector:n= ull) Keys Done Processing. > 2013-08-13 17:34:01,050 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4= :null) Request:Seq 7-1066224216: { Cmd , MgmtId: 7296881000534, via: 7, Ve= r: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteComman= d":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eca5= 3a6a-0ba9-4776-aee8-b92a92f9abc9","volumeType":"ROOT","dataStore":{"org.apa= che.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"8e7c6fb5-c4d7-38f9-9= cb1-d34d3bba4957","id":20,"poolType":"RBD","host":"10.147.41.3","path":"clo= udstack","port":6789}},"name":"ROOT-56","size":8589934592,"path":"2c57ebf6-= 8ae7-4c73-8365-6b4b6f7e3ffd","volumeId":69,"vmName":"i-2-56-VM","accountId"= :2,"format":"QCOW2","id":69,"hypervisorType":"KVM"}},"contextMap":{},"wait"= :0}}] } > 2013-08-13 17:34:01,050 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4= :null) Processing command: org.apache.cloudstack.storage.command.DeleteComm= and > 2013-08-13 17:34:01,376 INFO [kvm.storage.LibvirtStorageAdaptor] (agentR= equest-Handler-4:null) Unprotecting and Removing RBD snapshots of image 678= 9/2c57ebf6-8ae7-4c73-8365-6b4b6f7e3ffd prior to removing the image > 2013-08-13 17:34:01,383 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentR= equest-Handler-4:null) Succesfully connected to Ceph cluster at 10.147.41.3= :6789 > 2013-08-13 17:34:01,407 WARN [cloud.agent.Agent] (agentRequest-Handler-4= :null) Caught: > java.lang.ArrayIndexOutOfBoundsException: 0 > at com.sun.jna.Structure.toArray(Structure.java:1042) > at com.sun.jna.Structure.toArray(Structure.java:1065) > at com.ceph.rbd.RbdImage.snapList(Unknown Source) > at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.deleteP= hysicalDisk(LibvirtStorageAdaptor.java:719) > at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.deletePhys= icalDisk(LibvirtStoragePool.java:128) > at com.cloud.hypervisor.kvm.storage.KVMStorageProcessor.deleteVol= ume(KVMStorageProcessor.java:936) > at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.= execute(StorageSubsystemCommandHandlerBase.java:114) > at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.= handleStorageCommands(StorageSubsystemCommandHandlerBase.java:53) > at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.exe= cuteRequest(LibvirtComputingResource.java:1284) > at com.cloud.agent.Agent.processRequest(Agent.java:525) > at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:85= 2) > at com.cloud.utils.nio.Task.run(Task.java:83) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1146) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:615) > at java.lang.Thread.run(Thread.java:679) > 2013-08-13 17:34:01,408 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4= :null) Seq 7-1066224216: { Ans: , MgmtId: 7296881000534, via: 7, Ver: v1, = Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"java.l= ang.ArrayIndexOutOfBoundsException: 0\n\tat com.sun.jna.Structure.toArray(S= tructure.java:1042)\n\tat com.sun.jna.Structure.toArray(Structure.java:1065= )\n\tat com.ceph.rbd.RbdImage.snapList(Unknown Source)\n\tat com.cloud.hype= rvisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDisk(LibvirtStorageA= daptor.java:719)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.= deletePhysicalDisk(LibvirtStoragePool.java:128)\n\tat com.cloud.hypervisor.= kvm.storage.KVMStorageProcessor.deleteVolume(KVMStorageProcessor.java:936)\= n\tat com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute= (StorageSubsystemCommandHandlerBase.java:114)\n\tat com.cloud.storage.resou= rce.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsyst= emCommandHandlerBase.java:53)\n\tat com.cloud.hypervisor.kvm.resource.Libvi= rtComputingResource.executeRequest(LibvirtComputingResource.java:1284)\n\ta= t com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agen= t.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.ni= o.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runW= orker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolEx= ecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(T= hread.java:679)\n","contextMap":{},"wait":0}}] } > 2013-08-13 17:34:01,408 TRACE [utils.nio.Link] (agentRequest-Handler-4:nu= ll) Sending packet of length 1425 > 2013-08-13 17:34:01,408 TRACE [utils.nio.NioConnection] (Agent-Selector:n= ull) Keys Processing: 0 -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira