cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ana Paula de Sousa (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-6153) Unable to start a VM on Cloudstack
Date Fri, 21 Feb 2014 21:35:19 GMT

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

Ana Paula de Sousa updated CLOUDSTACK-6153:
-------------------------------------------

    Description: 
When I'm at the UI of cloudstack and I try to add a VM on "System VMs" it gives me a warning saying "fail to start vm", and it makes me unable to test the environment.

The log of the management-server.log gives me:
2014-02-21 18:30:24,867 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 1
2014-02-21 18:30:29,399 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2014-02-21 18:30:29,401 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for recon$
2014-02-21 18:30:29,401 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned b$
2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters alrea$
2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by an$
2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not o$
2014-02-21 18:30:34,699 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2014-02-21 18:30:52,123 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Primary storage is not ready, wait$
2014-02-21 18:30:52,123 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch seco$
2014-02-21 18:30:52,201 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console p$
2014-02-21 18:30:52,201 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capaci$
2014-02-21 18:30:52,205 INFO  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, brin$
2014-02-21 18:30:52,217 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starti$
2014-02-21 18:30:52,217 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state fo$
2014-02-21 18:30:52,263 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and pod$
2014-02-21 18:30:52,264 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, h$
2014-02-21 18:30:52,266 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2014-02-21 18:30:52,267 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters:$
2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algori$
2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and stora$
2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already $
2014-02-21 18:30:52,268 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching all possible resources under this Zone:$
2014-02-21 18:30:52,270 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, $
2014-02-21 18:30:52,272 INFO  [storage.endpoint.DefaultEndPointSelector] (StatsCollector-3:null) No running ssvm is found, so comman$
2014-02-21 18:30:52,279 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking resources in Cluster: 1 un$
2014-02-21 18:30:52,279 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: $
2014-02-21 18:30:52,292 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 h$
2014-02-21 18:30:52,294 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocat$
2014-02-21 18:30:52,294 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz,$
2014-02-21 18:30:52,297 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has$
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CP$
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 29608 , Reque$
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 8356601856 , $
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and$
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU fr$
2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM fr$
2014-02-21 18:30:52,299 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, ad$
2014-02-21 18:30:52,299 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning $
2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking suitable pools for volume $
2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) We need to allocate new storagepool$
2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Calling StoragePoolAllocators to fi$
2014-02-21 18:30:52,300 DEBUG [storage.allocator.LocalStoragePoolAllocator] (consoleproxy-1:null) LocalStoragePoolAllocator trying t$
2014-02-21 18:30:52,300 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) ClusterScopeStoragePoolAllo$
2014-02-21 18:30:52,300 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) Looking for pools in dc: 1 $
2014-02-21 18:30:52,301 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) No storage pools available $
2014-02-21 18:30:52,301 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator] (consoleproxy-1:null) ZoneWideStoragePoolAllocator to$
2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable pools found for volume:$
2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable pools found
2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable storagePools found unde$
2014-02-21 18:30:52,307 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Could not find suitable Deployment $
2014-02-21 18:30:52,307 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching all possible resources under this Zone:$
2014-02-21 18:30:52,308 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, $
2014-02-21 18:30:52,311 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Removing from the clusterId list these clusters f$
2014-02-21 18:30:52,311 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) No clusters found after removing disabled cluster$
2014-02-21 18:30:52,346 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101203: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:30:52,405 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopp$
2014-02-21 18:30:52,410 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start con$
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-1-VM]Scope=interface co$
        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-02-21 18:30:52,767 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats $
2014-02-21 18:30:52,794 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2014-02-21 18:30:52,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:30:52,798 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:30:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2014-02-21 18:30:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:30:52,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:30:53,295 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being call$
2014-02-21 18:30:53,297 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 201$


The agent.log gives me:
2014-02-21 18:08:24,884 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-49:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
2014-02-21 18:08:24,896 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) Received response: Seq 1-49:  { Ans: , MgmtId: 159387626793$
2014-02-21 18:08:50,816 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) Processing command: com.cloud.agent.api.GetStorageSt$
2014-02-21 18:09:03,959 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing command: com.cloud.agent.api.GetHostStats$
2014-02-21 18:09:03,960 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c idle=$(t$
2014-02-21 18:09:04,479 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:04,480 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c freeMem=$
2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c free|gre$
2014-02-21 18:09:04,490 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:24,825 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Executing: /usr/share/cloudstack-common/scr$
2014-02-21 18:09:24,887 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Execution is successful.
2014-02-21 18:09:24,889 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-50:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
2014-02-21 18:09:24,902 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) Received response: Seq 1-50:  { Ans: , MgmtId: 159387626793$

The output of "ifconfig" on my hypervisor is:
br0       Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
          inet end.: 10.16.1.34  Bcast:10.16.255.255  Masc:255.255.0.0
          endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:58025 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:48982 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:71081838 (71.0 MB) TX bytes:6757079 (6.7 MB)

br1       Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
          endereço inet6: fe80::ec24:80ff:fedd:23f9/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:183 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:52722 (52.7 KB)

br1:avahi Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
          inet end.: 169.254.10.37  Bcast:169.254.255.255  Masc:255.255.0.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1

cloud0    Link encap:Ethernet  Endereço de HW 56:8c:6c:b0:95:a8  
          inet end.: 169.254.0.1  Bcast:169.254.255.255  Masc:255.255.0.0
          endereço inet6: fe80::548c:6cff:feb0:95a8/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:63 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:11411 (11.4 KB)

eth0      Link encap:Ethernet  Endereço de HW 00:e0:4c:68:17:30  
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

eth1      Link encap:Ethernet  Endereço de HW 5c:d9:98:b1:6f:2d  
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

eth2      Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
          endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:61601 erros:0 descartados:102 excesso:0 quadro:0
          Pacotes TX:49016 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:72158063 (72.1 MB) TX bytes:6778184 (6.7 MB)

lo        Link encap:Loopback Local  
          inet end.: 127.0.0.1  Masc:255.0.0.0
          endereço inet6: ::1/128 Escopo:Máquina
          UP LOOPBACK RUNNING  MTU:65536  Métrica:1
          pacotes RX:245 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:245 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:20092 (20.0 KB) TX bytes:20092 (20.0 KB)

virbr0    Link encap:Ethernet  Endereço de HW 8a:7e:d9:10:69:32  
          inet end.: 192.168.122.1  Bcast:192.168.122.255  Masc:255.255.255.0
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

I have the br0, which is the public, network and the br1, which is the private network.

The /etc/cloudstack/agent/agent.properties looks like:
#Storage
#Fri Feb 21 17:20:25 BRT 2014
guest.network.device=br0
workers=5
private.network.device=br1
port=8250
resource=com.cloud.hypervisor.kvm.resource.LibvirtComputingResource
pod=1
zone=1
guid=2e1d6dee-aa9a-3e29-8fb7-995490b62daf
public.network.device=br0
cluster=1
local.storage.uuid=eae1fe36-6779-435c-99b5-e39af074ef74
domr.scripts.dir=scripts/network/domr/kvm
LibvirtComputingResource.id=1
host=10.16.1.32


  was:
When I'm at the UI of cloudstack and I try to add a VM on "System VMs" it gives me a warning saying "fail to start vm", and it makes me unable to test the environment.

The log of the management-server.log gives me:
2014-02-21 18:01:23,297 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2014-02-21 18:01:23,303 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 47275958272 for $
2014-02-21 18:01:23,303 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2014-02-21 18:01:23,303 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vla$
2014-02-21 18:01:23,310 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2014-02-21 18:01:23,310 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2014-02-21 18:01:23,316 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2014-02-21 18:01:23,316 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2014-02-21 18:01:23,352 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2014-02-21 18:01:24,845 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 1
2014-02-21 18:01:34,566 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2014-02-21 18:01:50,323 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2014-02-21 18:01:50,328 INFO  [storage.endpoint.DefaultEndPointSelector] (StatsCollector-3:null) No running ssvm is found, so comman$
2014-02-21 18:01:50,386 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101145: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:01:52,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:01:52,798 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:01:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:01:52,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:01:59,393 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2014-02-21 18:01:59,395 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for recon$
2014-02-21 18:01:59,395 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned b$
2014-02-21 18:01:59,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters alrea$
2014-02-21 18:01:59,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by an$
2014-02-21 18:01:59,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not o$
2014-02-21 18:01:59,676 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2014-02-21 18:02:00,291 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101146: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:02:22,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:02:22,797 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:02:22,805 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:02:22,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:02:24,850 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 1
2014-02-21 18:02:34,570 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2014-02-21 18:02:50,387 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2014-02-21 18:02:50,393 INFO  [storage.endpoint.DefaultEndPointSelector] (StatsCollector-3:null) No running ssvm is found, so comman$
2014-02-21 18:02:50,450 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101147: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:02:52,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:02:52,798 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:02:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:02:52,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:03:00,292 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2014-02-21 18:03:00,889 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-365101148: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:03:22,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:03:22,797 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:03:22,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:03:22,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:03:24,873 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 1
2014-02-21 18:03:29,393 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2014-02-21 18:03:29,395 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for recon$
2014-02-21 18:03:29,395 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned b$
2014-02-21 18:03:29,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters alrea$
2014-02-21 18:03:29,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by an$
2014-02-21 18:03:29,396 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not o$
2014-02-21 18:03:34,574 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2014-02-21 18:03:46,486 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START===  10.16.1.34 -- GET  command=listZones&respo$
2014-02-21 18:03:46,498 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END===  10.16.1.34 -- GET  command=listZones&respons$
2014-02-21 18:03:46,576 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START===  10.16.1.34 -- GET  command=listPods&respon$
2014-02-21 18:03:46,590 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END===  10.16.1.34 -- GET  command=listPods&response$
2014-02-21 18:03:46,597 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START===  10.16.1.34 -- GET  command=listClusters&res$
2014-02-21 18:03:46,612 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END===  10.16.1.34 -- GET  command=listClusters&respo$
2014-02-21 18:03:46,617 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START===  10.16.1.34 -- GET  command=listHosts&respo$
2014-02-21 18:03:46,625 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Searching for hosts>>>
2014-02-21 18:03:46,632 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Generating Response>>>
2014-02-21 18:03:46,639 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END===  10.16.1.34 -- GET  command=listHosts&respons$
2014-02-21 18:03:46,644 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===START===  10.16.1.34 -- GET  command=listStoragePools$
2014-02-21 18:03:46,657 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null) ===END===  10.16.1.34 -- GET  command=listStoragePools&r$
2014-02-21 18:03:46,666 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START===  10.16.1.34 -- GET  command=listImageStores&$
2014-02-21 18:03:46,680 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END===  10.16.1.34 -- GET  command=listImageStores&re$
2014-02-21 18:03:46,683 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START===  10.16.1.34 -- GET  command=listSystemVms&re$
2014-02-21 18:03:46,692 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END===  10.16.1.34 -- GET  command=listSystemVms&resp$
2014-02-21 18:03:46,698 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START===  10.16.1.34 -- GET  command=listRouters&res$
2014-02-21 18:03:46,712 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END===  10.16.1.34 -- GET  command=listRouters&respo$
2014-02-21 18:03:46,715 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START===  10.16.1.34 -- GET  command=listRouters&res$
2014-02-21 18:03:46,721 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END===  10.16.1.34 -- GET  command=listRouters&respo$
2014-02-21 18:03:46,728 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===START===  10.16.1.34 -- GET  command=listCapacity&re$
2014-02-21 18:03:46,744 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===END===  10.16.1.34 -- GET  command=listCapacity&resp$
2014-02-21 18:03:50,451 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2014-02-21 18:03:50,456 INFO  [storage.endpoint.DefaultEndPointSelector] (StatsCollector-2:null) No running ssvm is found, so comman$
2014-02-21 18:03:50,518 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-365101149: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:03:52,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:03:52,797 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:03:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:03:52,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:04:00,889 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2014-02-21 18:04:01,512 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101150: Received:  { Ans: , MgmtId: 1593876$
2014-02-21 18:04:13,588 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START===  10.16.1.34 -- GET  command=listSystemVms&r$
2014-02-21 18:04:13,598 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END===  10.16.1.34 -- GET  command=listSystemVms&res$
2014-02-21 18:04:22,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:04:22,797 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:04:22,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
2014-02-21 18:04:22,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
2014-02-21 18:04:24,873 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 1

The agent.log gives me:
2014-02-21 18:08:24,884 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-49:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
2014-02-21 18:08:24,896 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) Received response: Seq 1-49:  { Ans: , MgmtId: 159387626793$
2014-02-21 18:08:50,816 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) Processing command: com.cloud.agent.api.GetStorageSt$
2014-02-21 18:09:03,959 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing command: com.cloud.agent.api.GetHostStats$
2014-02-21 18:09:03,960 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c idle=$(t$
2014-02-21 18:09:04,479 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:04,480 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c freeMem=$
2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c free|gre$
2014-02-21 18:09:04,490 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
2014-02-21 18:09:24,825 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Executing: /usr/share/cloudstack-common/scr$
2014-02-21 18:09:24,887 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Execution is successful.
2014-02-21 18:09:24,889 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-50:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
2014-02-21 18:09:24,902 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) Received response: Seq 1-50:  { Ans: , MgmtId: 159387626793$

The output of "ifconfig" on my hypervisor is:
br0       Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
          inet end.: 10.16.1.34  Bcast:10.16.255.255  Masc:255.255.0.0
          endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:58025 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:48982 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:71081838 (71.0 MB) TX bytes:6757079 (6.7 MB)

br1       Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
          endereço inet6: fe80::ec24:80ff:fedd:23f9/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:183 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:52722 (52.7 KB)

br1:avahi Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
          inet end.: 169.254.10.37  Bcast:169.254.255.255  Masc:255.255.0.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1

cloud0    Link encap:Ethernet  Endereço de HW 56:8c:6c:b0:95:a8  
          inet end.: 169.254.0.1  Bcast:169.254.255.255  Masc:255.255.0.0
          endereço inet6: fe80::548c:6cff:feb0:95a8/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:63 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:11411 (11.4 KB)

eth0      Link encap:Ethernet  Endereço de HW 00:e0:4c:68:17:30  
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

eth1      Link encap:Ethernet  Endereço de HW 5c:d9:98:b1:6f:2d  
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

eth2      Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
          endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
          pacotes RX:61601 erros:0 descartados:102 excesso:0 quadro:0
          Pacotes TX:49016 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:1000 
          RX bytes:72158063 (72.1 MB) TX bytes:6778184 (6.7 MB)

lo        Link encap:Loopback Local  
          inet end.: 127.0.0.1  Masc:255.0.0.0
          endereço inet6: ::1/128 Escopo:Máquina
          UP LOOPBACK RUNNING  MTU:65536  Métrica:1
          pacotes RX:245 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:245 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:20092 (20.0 KB) TX bytes:20092 (20.0 KB)

virbr0    Link encap:Ethernet  Endereço de HW 8a:7e:d9:10:69:32  
          inet end.: 192.168.122.1  Bcast:192.168.122.255  Masc:255.255.255.0
          UP BROADCAST MULTICAST  MTU:1500  Métrica:1
          pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
          Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
          colisões:0 txqueuelen:0 
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

I have the br0, which is the public, network and the br1, which is the private network.

The /etc/cloudstack/agent/agent.properties looks like:
#Storage
#Fri Feb 21 17:20:25 BRT 2014
guest.network.device=br0
workers=5
private.network.device=br1
port=8250
resource=com.cloud.hypervisor.kvm.resource.LibvirtComputingResource
pod=1
zone=1
guid=2e1d6dee-aa9a-3e29-8fb7-995490b62daf
public.network.device=br0
cluster=1
local.storage.uuid=eae1fe36-6779-435c-99b5-e39af074ef74
domr.scripts.dir=scripts/network/domr/kvm
LibvirtComputingResource.id=1
host=10.16.1.32



> Unable to start a VM on Cloudstack
> ----------------------------------
>
>                 Key: CLOUDSTACK-6153
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-6153
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>         Environment: Two physical machines, one for the hypervisor  and another for the management server. They're on a internal network at my lab.
>            Reporter: Ana Paula de Sousa
>              Labels: agent, issue, kvm, management, systemvm, vm
>
> When I'm at the UI of cloudstack and I try to add a VM on "System VMs" it gives me a warning saying "fail to start vm", and it makes me unable to test the environment.
> The log of the management-server.log gives me:
> 2014-02-21 18:30:24,867 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 1
> 2014-02-21 18:30:29,399 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
> 2014-02-21 18:30:29,401 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for recon$
> 2014-02-21 18:30:29,401 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned b$
> 2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters alrea$
> 2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by an$
> 2014-02-21 18:30:29,402 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not o$
> 2014-02-21 18:30:34,699 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
> 2014-02-21 18:30:52,123 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Primary storage is not ready, wait$
> 2014-02-21 18:30:52,123 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch seco$
> 2014-02-21 18:30:52,201 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console p$
> 2014-02-21 18:30:52,201 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capaci$
> 2014-02-21 18:30:52,205 INFO  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, brin$
> 2014-02-21 18:30:52,217 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starti$
> 2014-02-21 18:30:52,217 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state fo$
> 2014-02-21 18:30:52,263 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and pod$
> 2014-02-21 18:30:52,264 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, h$
> 2014-02-21 18:30:52,266 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
> 2014-02-21 18:30:52,267 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters:$
> 2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algori$
> 2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and stora$
> 2014-02-21 18:30:52,268 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already $
> 2014-02-21 18:30:52,268 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching all possible resources under this Zone:$
> 2014-02-21 18:30:52,270 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, $
> 2014-02-21 18:30:52,272 INFO  [storage.endpoint.DefaultEndPointSelector] (StatsCollector-3:null) No running ssvm is found, so comman$
> 2014-02-21 18:30:52,279 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking resources in Cluster: 1 un$
> 2014-02-21 18:30:52,279 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: $
> 2014-02-21 18:30:52,292 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 h$
> 2014-02-21 18:30:52,294 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocat$
> 2014-02-21 18:30:52,294 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz,$
> 2014-02-21 18:30:52,297 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has$
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CP$
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 29608 , Reque$
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 8356601856 , $
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and$
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU fr$
> 2014-02-21 18:30:52,299 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM fr$
> 2014-02-21 18:30:52,299 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, ad$
> 2014-02-21 18:30:52,299 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning $
> 2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking suitable pools for volume $
> 2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) We need to allocate new storagepool$
> 2014-02-21 18:30:52,299 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Calling StoragePoolAllocators to fi$
> 2014-02-21 18:30:52,300 DEBUG [storage.allocator.LocalStoragePoolAllocator] (consoleproxy-1:null) LocalStoragePoolAllocator trying t$
> 2014-02-21 18:30:52,300 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) ClusterScopeStoragePoolAllo$
> 2014-02-21 18:30:52,300 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) Looking for pools in dc: 1 $
> 2014-02-21 18:30:52,301 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) No storage pools available $
> 2014-02-21 18:30:52,301 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator] (consoleproxy-1:null) ZoneWideStoragePoolAllocator to$
> 2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable pools found for volume:$
> 2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable pools found
> 2014-02-21 18:30:52,304 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No suitable storagePools found unde$
> 2014-02-21 18:30:52,307 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Could not find suitable Deployment $
> 2014-02-21 18:30:52,307 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching all possible resources under this Zone:$
> 2014-02-21 18:30:52,308 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Listing clusters in order of aggregate capacity, $
> 2014-02-21 18:30:52,311 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Removing from the clusterId list these clusters f$
> 2014-02-21 18:30:52,311 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) No clusters found after removing disabled cluster$
> 2014-02-21 18:30:52,346 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-365101203: Received:  { Ans: , MgmtId: 1593876$
> 2014-02-21 18:30:52,405 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopp$
> 2014-02-21 18:30:52,410 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start con$
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-1-VM]Scope=interface co$
>         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-02-21 18:30:52,767 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats $
> 2014-02-21 18:30:52,794 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
> 2014-02-21 18:30:52,796 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
> 2014-02-21 18:30:52,798 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
> 2014-02-21 18:30:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
> 2014-02-21 18:30:52,804 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to up$
> 2014-02-21 18:30:52,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to u$
> 2014-02-21 18:30:53,295 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being call$
> 2014-02-21 18:30:53,297 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 201$
> The agent.log gives me:
> 2014-02-21 18:08:24,884 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-49:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
> 2014-02-21 18:08:24,896 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) Received response: Seq 1-49:  { Ans: , MgmtId: 159387626793$
> 2014-02-21 18:08:50,816 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) Processing command: com.cloud.agent.api.GetStorageSt$
> 2014-02-21 18:09:03,959 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Processing command: com.cloud.agent.api.GetHostStats$
> 2014-02-21 18:09:03,960 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c idle=$(t$
> 2014-02-21 18:09:04,479 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
> 2014-02-21 18:09:04,480 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c freeMem=$
> 2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
> 2014-02-21 18:09:04,486 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Executing: /bin/bash -c free|gre$
> 2014-02-21 18:09:04,490 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) Execution is successful.
> 2014-02-21 18:09:24,825 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Executing: /usr/share/cloudstack-common/scr$
> 2014-02-21 18:09:24,887 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) Execution is successful.
> 2014-02-21 18:09:24,889 DEBUG [cloud.agent.Agent] (UgentTask-5:null) Sending ping: Seq 1-50:  { Cmd , MgmtId: -1, via: 1, Ver: v1, F$
> 2014-02-21 18:09:24,902 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) Received response: Seq 1-50:  { Ans: , MgmtId: 159387626793$
> The output of "ifconfig" on my hypervisor is:
> br0       Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
>           inet end.: 10.16.1.34  Bcast:10.16.255.255  Masc:255.255.0.0
>           endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:58025 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:48982 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:0 
>           RX bytes:71081838 (71.0 MB) TX bytes:6757079 (6.7 MB)
> br1       Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
>           endereço inet6: fe80::ec24:80ff:fedd:23f9/64 Escopo:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:183 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:0 
>           RX bytes:0 (0.0 B) TX bytes:52722 (52.7 KB)
> br1:avahi Link encap:Ethernet  Endereço de HW ee:24:80:dd:23:f9  
>           inet end.: 169.254.10.37  Bcast:169.254.255.255  Masc:255.255.0.0
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
> cloud0    Link encap:Ethernet  Endereço de HW 56:8c:6c:b0:95:a8  
>           inet end.: 169.254.0.1  Bcast:169.254.255.255  Masc:255.255.0.0
>           endereço inet6: fe80::548c:6cff:feb0:95a8/64 Escopo:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:63 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:0 
>           RX bytes:0 (0.0 B) TX bytes:11411 (11.4 KB)
> eth0      Link encap:Ethernet  Endereço de HW 00:e0:4c:68:17:30  
>           UP BROADCAST MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:1000 
>           RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)
> eth1      Link encap:Ethernet  Endereço de HW 5c:d9:98:b1:6f:2d  
>           UP BROADCAST MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:1000 
>           RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)
> eth2      Link encap:Ethernet  Endereço de HW 1c:6f:65:d7:4a:4b  
>           endereço inet6: fe80::1e6f:65ff:fed7:4a4b/64 Escopo:Link
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:61601 erros:0 descartados:102 excesso:0 quadro:0
>           Pacotes TX:49016 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:1000 
>           RX bytes:72158063 (72.1 MB) TX bytes:6778184 (6.7 MB)
> lo        Link encap:Loopback Local  
>           inet end.: 127.0.0.1  Masc:255.0.0.0
>           endereço inet6: ::1/128 Escopo:Máquina
>           UP LOOPBACK RUNNING  MTU:65536  Métrica:1
>           pacotes RX:245 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:245 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:0 
>           RX bytes:20092 (20.0 KB) TX bytes:20092 (20.0 KB)
> virbr0    Link encap:Ethernet  Endereço de HW 8a:7e:d9:10:69:32  
>           inet end.: 192.168.122.1  Bcast:192.168.122.255  Masc:255.255.255.0
>           UP BROADCAST MULTICAST  MTU:1500  Métrica:1
>           pacotes RX:0 erros:0 descartados:0 excesso:0 quadro:0
>           Pacotes TX:0 erros:0 descartados:0 excesso:0 portadora:0
>           colisões:0 txqueuelen:0 
>           RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)
> I have the br0, which is the public, network and the br1, which is the private network.
> The /etc/cloudstack/agent/agent.properties looks like:
> #Storage
> #Fri Feb 21 17:20:25 BRT 2014
> guest.network.device=br0
> workers=5
> private.network.device=br1
> port=8250
> resource=com.cloud.hypervisor.kvm.resource.LibvirtComputingResource
> pod=1
> zone=1
> guid=2e1d6dee-aa9a-3e29-8fb7-995490b62daf
> public.network.device=br0
> cluster=1
> local.storage.uuid=eae1fe36-6779-435c-99b5-e39af074ef74
> domr.scripts.dir=scripts/network/domr/kvm
> LibvirtComputingResource.id=1
> host=10.16.1.32



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

Mime
View raw message