You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users-cn@cloudstack.apache.org by 虚无缥缈 <83...@qq.com> on 2014/04/03 10:18:14 UTC
系统vm起不来，请帮忙分析原因。
主存储，二级存储，在manager和agent端都测试正常使用。
3个桥接网卡，cloudbr3存储，cloudbr1管理，cloudbr2 guest、pubic（trunk），vconfig配置vlan，配置ip也可以通，说明所有网卡都是正常的，但是就是报错啊！
2014-04-03 16:09:50,081 DEBUG [agent.transport.Request] (AgentManager-Handler-14:null) Seq 10-1606352922: Processing: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":185,"name":"v-185-VM","type":"ConsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy host=192.168.151.100 port=8250 name=v-185-VM premium=true zone=1 pod=1 guid=Proxy.185 proxy_vm=185 disable_rp_filter=true eth2ip=192.168.152.21 eth2mask=255.255.255.0 gateway=192.168.152.1 eth0ip=169.254.2.254 eth0mask=255.255.0.0 eth1ip=192.168.151.201 eth1mask=255.255.255.0 mgmtcidr=192.168.151.0/24 localgw=192.168.151.1 internaldns1=202.106.0.20 dns1=192.168.6.253","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"bcab87c3383e11cd","vncAddr":"192.168.151.116","params":{},"uuid":"984e724f-049b-410d-90ac-5d2882538478","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"fba539ff-1550-4f83-bacd-c57609dba993","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fdb4113a-6141-4381-b3f8-3084b51f7840","id":2,"poolType":"SharedMountPoint","host":"localhost","path":"/gluster_client_mnt","port":0}},"name":"ROOT-185","size":0,"path":"79f0afde-8f4d-4169-aaf9-62cf9b9ef9b5","volumeId":185,"vmName":"v-185-VM","accountId":1,"format":"QCOW2","id":185,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"f10c76fa-b8cf-4f95-867a-e1a0014ba723","ip":"192.168.152.21","netmask":"255.255.255.0","gateway":"192.168.152.1","mac":"06:44:92:00:00:6b","dns1":"192.168.6.253","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://152","isolationUri":"vlan://152","isSecurityGroupEnabled":false,"name":"cloudbr3"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"3fad9b8f-673a-4712-960c-ea2b6e34d1c2","ip":"169.254.2.254","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:fe","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"0e4f1a51-1783-419f-9191-81ccde132f61","ip":"192.168.151.201","netmask":"255.255.255.0","gateway":"192.168.151.1","mac":"06:2b:0c:00:00:34","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"cloudbr2"}]},"result":false,"details":"Unable to read from monitor: Connection reset by peer","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2014-04-03 16:09:50,081 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-14:null) Seq 10-1606352923: Sending now. is current sequence.
2014-04-03 16:09:50,082 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 10-1606352922: Received: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, { StartAnswer, Answer } }
2014-04-03 16:09:50,085 INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to start VM on Host[-10-Routing] due to Unable to read from monitor: Connection reset by peer
2014-04-03 16:09:50,118 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-185-VM] in Starting state
2014-04-03 16:09:50,121 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 10-1606352924: Waiting for Seq 1606352923 Scheduling: { Cmd , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"v-185-VM","wait":0}}] }
2014-04-03 16:09:50,205 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2014-04-03 16:09:50,219 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-04-03 16:09:50,221 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-04-03 16:09:50,344 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 10-1606352923: Processing: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-04-03 16:09:50,344 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 10-1606352924: Sending now. is current sequence.
2014-04-03 16:09:50,345 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 10-1606352923: Received: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, { StopAnswer } }
2014-04-03 16:09:50,346 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2014-04-03 16:09:50,347 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
2014-04-03 16:09:50,349 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2014-04-03 16:09:50,360 DEBUG [network.guru.ControlNetworkGuru] (secstorage-1:null) Released nic: NicProfile[761-192-null-null-null
2014-04-03 16:09:50,369 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=c53b6bf3-67d7-44f6-a5ad-fc79d183d1a5, instance=762
2014-04-03 16:09:50,370 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[762-192-null-null-null
2014-04-03 16:09:50,418 DEBUG [network.guru.StorageNetworkGuru] (secstorage-1:null) Release an storage ip 192.168.150.192
2014-04-03 16:09:50,421 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully released network resources for the vm VM[SecondaryStorageVm|s-192-VM]
2014-04-03 16:09:50,421 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-192-VM] in Starting state
2014-04-03 16:09:50,425 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Root volume is ready, need to place VM in volume's cluster
2014-04-03 16:09:50,425 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Vol[192|vm=192|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2014-04-03 16:09:50,426 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: [10]
2014-04-03 16:09:50,428 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_3d58adeb@77d7226
2014-04-03 16:09:50,428 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 268435456
2014-04-03 16:09:50,428 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2014-04-03 16:09:50,428 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching resources only under specified Cluster: 1
2014-04-03 16:09:50,435 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Checking resources in Cluster: 1 under Pod: 1
2014-04-03 16:09:50,435 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2014-04-03 16:09:50,440 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-10-Routing]]
2014-04-03 16:09:50,444 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-10-Routing]]
2014-04-03 16:09:50,444 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=256
2014-04-03 16:09:50,444 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host name: agent116.hc360.com, hostId: 10 is in avoid set, skipping this and trying other available hosts
2014-04-03 16:09:50,444 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2014-04-03 16:09:50,444 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) No suitable hosts found
2014-04-03 16:09:50,445 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) No suitable hosts found under this Cluster: 1
2014-04-03 16:09:50,449 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-04-03 16:09:50,449 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching resources only under specified Cluster: 1
2014-04-03 16:09:50,450 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) The specified cluster is in avoid set, returning.
2014-04-03 16:09:50,451 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: [1], hosts: [10]
2014-04-03 16:09:50,453 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_3d58adeb@77d7226
2014-04-03 16:09:50,453 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 268435456
2014-04-03 16:09:50,453 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
2014-04-03 16:09:50,453 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching resources only under specified Pod: 1
2014-04-03 16:09:50,453 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2014-04-03 16:09:50,457 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Removing from the clusterId list these clusters from avoid set: [1]
2014-04-03 16:09:50,457 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2014-04-03 16:09:50,473 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 10
2014-04-03 16:09:50,481 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 47976 and CPU after applying overprovisioning: 47976
2014-04-03 16:09:50,481 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total RAM: 101395537920 and RAM after applying overprovisioning: 101395537920
2014-04-03 16:09:50,481 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release cpu from host: 10, old used: 1000,reserved: 0, actual total: 47976, total with overprovisioning: 47976; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-04-03 16:09:50,481 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 10, old used: 1342177280,reserved: 0, total: 101395537920; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-04-03 16:09:50,489 WARN [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-192-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
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:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-04-03 16:09:50,491 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 192, will recycle it and start a new one
2014-04-03 16:09:50,494 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is already stopped: VM[SecondaryStorageVm|s-192-VM]
2014-04-03 16:09:50,499 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2014-04-03 08:09:50 GMT
2014-04-03 16:09:50,500 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2014-04-03 08:09:50 GMT
2014-04-03 16:09:50,519 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Stopped to Expunging with event: ExpungeOperationvm's original host id: null new host id: null host id before state transition: null
2014-04-03 16:09:50,521 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Destroying vm VM[SecondaryStorageVm|s-192-VM]
2014-04-03 16:09:50,521 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up NICS
2014-04-03 16:09:50,522 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Cleaning network for vm: 192
2014-04-03 16:09:50,538 DEBUG [network.guru.PublicNetworkGuru] (secstorage-1:null) public network deallocate network: networkId: 200, ip: 192.168.152.20
2014-04-03 16:09:50,545 DEBUG [network.guru.PublicNetworkGuru] (secstorage-1:null) Deallocated nic: NicProfile[760-192-null-null-null
2014-04-03 16:09:50,548 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=760
2014-04-03 16:09:50,550 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Revoving nic secondary ip entry ...
2014-04-03 16:09:50,557 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=761
2014-04-03 16:09:50,558 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Revoving nic secondary ip entry ...
2014-04-03 16:09:50,587 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=762
2014-04-03 16:09:50,589 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Revoving nic secondary ip entry ...
2014-04-03 16:09:50,604 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 10-1606352924: Processing: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-04-03 16:09:50,604 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-1:null) Seq 10-1606352924: No more commands found
2014-04-03 16:09:50,604 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 10-1606352924: Received: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 110, { StopAnswer } }
2014-04-03 16:09:50,604 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Removed nic id=763
2014-04-03 16:09:50,606 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Revoving nic secondary ip entry ...
2014-04-03 16:09:50,609 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Cleaning storage for vm: 192
2014-04-03 16:09:50,619 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[734-185-null-null-null
2014-04-03 16:09:50,656 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=b4af8187-dba0-4e12-99c6-2704f97116e8, instance=735
2014-04-03 16:09:50,657 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[735-185-null-null-null
2014-04-03 16:09:50,660 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-185-VM]
2014-04-03 16:09:50,660 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-185-VM] in Starting state
2014-04-03 16:09:50,664 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
2014-04-03 16:09:50,664 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[185|vm=185|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2014-04-03 16:09:50,666 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: [10]
2014-04-03 16:09:50,667 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_3d58adeb@77d7226
2014-04-03 16:09:50,668 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
2014-04-03 16:09:50,668 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
2014-04-03 16:09:50,668 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2014-04-03 16:09:50,675 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
2014-04-03 16:09:50,675 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2014-04-03 16:09:50,680 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-10-Routing]]
2014-04-03 16:09:50,683 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-10-Routing]]
2014-04-03 16:09:50,684 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
2014-04-03 16:09:50,684 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host name: agent116.hc360.com, hostId: 10 is in avoid set, skipping this and trying other available hosts
2014-04-03 16:09:50,684 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2014-04-03 16:09:50,684 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable hosts found
2014-04-03 16:09:50,684 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable hosts found under this Cluster: 1
2014-04-03 16:09:50,694 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-04-03 16:09:50,695 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
2014-04-03 16:09:50,696 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) The specified cluster is in avoid set, returning.
2014-04-03 16:09:50,698 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: [1], hosts: [10]
2014-04-03 16:09:50,703 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 10-1606352925: Sending { Cmd , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b89a43ad-e6d5-4681-afeb-312ed4f076ba","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fdb4113a-6141-4381-b3f8-3084b51f7840","id":2,"poolType":"SharedMountPoint","host":"localhost","path":"/gluster_client_mnt","port":0}},"name":"ROOT-192","size":0,"path":"d97b7846-4df9-4df3-8107-3e3f29a71e5a","volumeId":192,"vmName":"s-192-VM","accountId":1,"format":"QCOW2","id":192,"hypervisorType":"KVM"}},"wait":0}}] }
2014-04-03 16:09:50,706 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_3d58adeb@77d7226
2014-04-03 16:09:50,706 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 1073741824
2014-04-03 16:09:50,706 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: No
2014-04-03 16:09:50,706 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Pod: 1
2014-04-03 16:09:50,706 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2014-04-03 16:09:50,711 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Removing from the clusterId list these clusters from avoid set: [1]
2014-04-03 16:09:50,711 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2014-04-03 16:09:50,719 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 10
2014-04-03 16:09:50,727 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 47976 and CPU after applying overprovisioning: 47976
2014-04-03 16:09:50,728 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total RAM: 101395537920 and RAM after applying overprovisioning: 101395537920
2014-04-03 16:09:50,728 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 10, old used: 500,reserved: 0, actual total: 47976, total with overprovisioning: 47976; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-04-03 16:09:50,728 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 10, old used: 1073741824,reserved: 0, total: 101395537920; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-04-03 16:09:50,731 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-185-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:928)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1672)
at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157)
at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
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:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-04-03 16:09:50,794 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 10-1606352925: Processing: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-04-03 16:09:50,794 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 10-1606352925: Received: { Ans: , MgmtId: 59716377313896, via: 10, Ver: v1, Flags: 10, { Answer } }
2014-04-03 16:09:50,804 INFO [storage.volume.VolumeServiceImpl] (secstorage-1:null) Volume 192 is not referred anywhere, remove it from volumes table
2014-04-03 16:09:50,828 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-192-VM]
2014-04-03 16:09:50,835 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn