cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Wido den Hollander (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-4292) ceph:destroyedvm failed with ArrayIndexexception while expunging
Date Wed, 14 Aug 2013 11:41:51 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-4292?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Wido den Hollander updated CLOUDSTACK-4292:
-------------------------------------------

    Assignee: Wido den Hollander
    
> ceph:destroyedvm failed with ArrayIndexexception while expunging
> ----------------------------------------------------------------
>
>                 Key: CLOUDSTACK-4292
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4292
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: Management Server
>    Affects Versions: 4.2.0
>            Reporter: sadhu suresh
>            Assignee: Wido den Hollander
>            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 offeing 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 management side noticed
warning
> (UserVm-Scavenger-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@23
> Management log:
> *******************
> 2013-08-13 13:32:10,906 DEBUG [agent.transport.Request] (AgentManager-Handler-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,"details":"","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] (RouterMonitor-1:null)
Details from executing class com.cloud.agent.api.NetworkUsageCommand:
> 2013-08-13 13:32:10,907 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null)
Recieved and Sent bytes are both 0. Not updating user_statistics
> 2013-08-13 13:32:11,532 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask: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] (SnapshotPollTask: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-Scavenger-1:null)
Found 1 vms to expunge.
> 2013-08-13 13:32:14,031 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserVm-Scavenger-1:null)
Stopped called on VM[User|VM11] but the state is Destroyed
> 2013-08-13 13:32:14,134 DEBUG [cloud.capacity.CapacityManagerImpl] (UserVm-Scavenger-1:null)
VM state transitted from :Destroyed to Expunging with event: ExpungeOperationvm's original
host id: 7 new host id: null host id before state transition: null
> 2013-08-13 13:32:14,134 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserVm-Scavenger-1:null)
Destroying vm VM[User|VM11]
> 2013-08-13 13:32:14,141 DEBUG [cloud.vm.VirtualMachineManagerImpl] (UserVm-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-Scavenger-1:null)
Service SecurityGroup is not supported in the network id=214
> 2013-08-13 13:32:14,161 DEBUG [cloud.network.NetworkManagerImpl] (UserVm-Scavenger-1:null)
Removed nic id=114
> 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-Scavenger-1:null)
Cleaning storage for vm: 56
> 2013-08-13 13:32:14,179 DEBUG [cloud.storage.VolumeManagerImpl] (UserVm-Scavenger-1:null)
Detaching Vol[75|vm=56|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.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eca53a6a-0ba9-4776-aee8-b92a92f9abc9","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"8e7c6fb5-c4d7-38f9-9cb1-d34d3bba4957","id":20,"poolType":"RBD","host":"10.147.41.3","path":"cloudstack","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"}},"wait":0}}]
}
> 2013-08-13 13:32:14,779 DEBUG [agent.transport.Request] (AgentManager-Handler-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.Structure.toArray(Structure.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.hypervisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDisk(LibvirtStorageAdaptor.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.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:53)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat
java.util.concurrent.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.ObjectInDataStoreManagerImpl] (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] (UserVm-Scavenger-1:null)
Expunged VM[User|VM11]
> 2013-08-13 13:32:14,919 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-1:null)
Starting cleaning up vm VM[User|VM11] resources...
> 2013-08-13 13:32:14,930 DEBUG [network.firewall.FirewallManagerImpl] (UserVm-Scavenger-1:null)
No firewall rules are found for vm id=56
> 2013-08-13 13:32:14,930 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-1:null)
Firewall rules are removed successfully as a part of vm id=56 expunge
> 2013-08-13 13:32:14,935 DEBUG [network.rules.RulesManagerImpl] (UserVm-Scavenger-1:null)
No port forwarding rules are found for vm id=56
> 2013-08-13 13:32:14,935 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-1:null)
Port forwarding rules are removed successfully as a part of vm id=56 expunge
> 2013-08-13 13:32:14,938 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-1:null)
Removed vm id=56 from all load balancers as a part of expunge process
> 2013-08-13 13:32:14,940 DEBUG [cloud.vm.UserVmManagerImpl] (UserVm-Scavenger-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] (AgentManager-Handler-14:null)
SeqA 10-13543: Processing Seq 10-13543:  { Cmd , MgmtId: -1, via: 10, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":39,"_loadInfo":"{\n  \"connections\":
[]\n}","wait":0}}] }
> 2013-08-13 13:32:18,498 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null)
SeqA 10-13543: Sending Seq 10-13543:  { Ans: , MgmtId: 7296881000534, via: 10, Ver: v1, Flags:
100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-13 13:32:20,696 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-155:null)
Ping from 4
> 2013-08-13 13:32:21,111 DEBUG [network.lb.LBHealthCheckManagerImpl] (LBHealthCheck-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] (LBHealthCheck-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] (DirectAgent-26:null)
Ping from 1
> 2013-08-13 13:32:25,298 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-155:null)
Ping from 5
> 2013-08-13 13:32:26,555 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-426:null)
Seq 1-826605573: Executing request
> 2013-08-13 13:32:26,610 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null)
Ping from 10
> 2013-08-13 13:32:26,746 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-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-426:null) Seq
1-826605573: Unable to find listener.
> 2013-08-13 13:32:28,493 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null)
SeqA 10-13545: Processing Seq 10-13545:  { Cmd , MgmtId: -1, via: 10, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":39,"_loadInfo":"{\n  \"connections\":
[]\n}","wait":0}}] }
> 2013-08-13 13:32:28,506 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null)
SeqA 10-13545: Sending Seq 10-13545:  { Ans: , MgmtId: 7296881000534, via: 10, Ver: v1, Flags:
100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2013-08-13 13:32:29,387 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null)
Ping from 7
> 2013-08-13 13:32:33,518 DEBUG [cloud.server.StatsCollector] (StatsCollector-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] (AgentManager-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:null) Keys Processing:
1
> 2013-08-13 17:34:01,048 TRACE [utils.nio.NioConnection] (Agent-Selector:null) Reading
from: Socket[addr=/10.147.59.110,port=8250,localport=47605]
> 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:null) 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, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"eca53a6a-0ba9-4776-aee8-b92a92f9abc9","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"8e7c6fb5-c4d7-38f9-9cb1-d34d3bba4957","id":20,"poolType":"RBD","host":"10.147.41.3","path":"cloudstack","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.DeleteCommand
> 2013-08-13 17:34:01,376 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null)
Unprotecting and Removing RBD snapshots of image 6789/2c57ebf6-8ae7-4c73-8365-6b4b6f7e3ffd
prior to removing the image
> 2013-08-13 17:34:01,383 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-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.deletePhysicalDisk(LibvirtStorageAdaptor.java:719)
>         at com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.deletePhysicalDisk(LibvirtStoragePool.java:128)
>         at com.cloud.hypervisor.kvm.storage.KVMStorageProcessor.deleteVolume(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.executeRequest(LibvirtComputingResource.java:1284)
>         at com.cloud.agent.Agent.processRequest(Agent.java:525)
>         at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
>         at com.cloud.utils.nio.Task.run(Task.java:83)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.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.lang.ArrayIndexOutOfBoundsException:
0\n\tat com.sun.jna.Structure.toArray(Structure.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.hypervisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDisk(LibvirtStorageAdaptor.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.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:53)\n\tat
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","contextMap":{},"wait":0}}]
}
> 2013-08-13 17:34:01,408 TRACE [utils.nio.Link] (agentRequest-Handler-4:null) Sending
packet of length 1425
> 2013-08-13 17:34:01,408 TRACE [utils.nio.NioConnection] (Agent-Selector:null) Keys Processing:
0

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message