You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by James Towner <ja...@yahoo.com> on 2013/12/19 08:52:13 UTC
router VM failed - reservedCpu: 0, requested cpu: 500,
Hello,
I have CloudStack 4.2.0 on ubuntu 12.04 with KVM hypervisor. The router VMs failed to start. Two system VMs work fine. When the router VM failed to start, there are entries like the following in management-server.log:
2013-12-18 22:49:48,076 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Reserved CPU: 0 , Requested CPU: 500
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Reserved RAM: 0 , Requested RAM: 134217728
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: 0, requested mem: 134217728
2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-12-18 22:49:48,077 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) The last host of this VM does not have enough capacity
2013-12-18 22:49:48,077 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Cannot choose the last host to deploy this VM
My host has eight core CPU, enough free memory, and only two VMs are running at that time.
~$ free
total used free shared buffers cached
Mem: 16404204 825780 15578424 0 24144 106496
-/+ buffers/cache: 695140 15709064
Swap: 48932860 0 48932860
Why CloudStack still don't have enough resource?
Thanks in advance,
James
Re: router VM failed - reservedCpu: 0, requested cpu: 500,
Posted by Bharat Kumar <bh...@citrix.com>.
Hi,
I see this in the logs.
{"com.cloud.agent.api.check.CheckSshAnswer":{"result":false,"details":"Can not ping System vm r-9-VMdue to:Unable to
connect","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2013-12-20 15:30:59,455 WARN [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Unable to ssh to the VM: Can not ping System vm r-9-VMdue to:Unable to connect
This means that the management server is not able to ssh to the router vm. This can happen if there is a mismatch in the ssh keys used my the management server and the routerVM. try to destroy the router VMs can recreate them.
If this dose not work try copying the systemvm.iso to the KVM host and recreate router VM again.
Thanks,
Bharat.
On 21-Dec-2013, at 5:34 am, James Towner <ja...@yahoo.com>> wrote:
{"com.cloud.agent.api.check.CheckSshAnswer":{"result":false,"details":"Can not ping System vm r-9-VMdue to:Unable to
connect","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
Re: router VM failed - reservedCpu: 0, requested cpu: 500,
Posted by James Towner <ja...@yahoo.com>.
Nitin,
Thanks for your response.
My management server is on a VM (out side of CloudStack), and nfs directories are on management server. I reinstalled the management server, re-created teh Zone. Two system VMs are fine, but still seeing the same problem on router VM.
At current stage, i have the following entries in vm_instance:
mysql> select name,instance_name, state,host_id,last_host_id from vm_instance;
+---------+---------------+-----------+---------+--------------+
| name | instance_name | state | host_id | last_host_id |
+---------+---------------+-----------+---------+--------------+
| s-1-VM | s-1-VM | Expunging | NULL | 1 |
| v-2-VM | v-2-VM | Running | 1 | 1 |
| vm1 | i-2-3-VM | Expunging | NULL | NULL |
| r-4-VM | r-4-VM | Expunging | NULL | NULL |
| vm2 | i-2-5-VM | Expunging | NULL | NULL |
| r-6-VM | r-6-VM | Stopped | NULL | 1 |
| vm3 | i-2-7-VM | Stopped | NULL | 1 |
| vm4 | i-2-8-VM | Error | NULL | NULL |
| r-9-VM | r-9-VM | Stopped | NULL | NULL |
| s-10-VM | s-10-VM | Expunging | NULL | NULL |
| s-11-VM | s-11-VM | Expunging | NULL | NULL |
| s-12-VM | s-12-VM | Expunging | NULL | NULL |
| s-13-VM | s-13-VM | Expunging | NULL | NULL |
| s-14-VM | s-14-VM | Expunging | NULL | NULL |
| s-15-VM | s-15-VM | Expunging | NULL | NULL |
| s-16-VM | s-16-VM | Running | 1 | 1 |
+---------+---------------+-----------+---------+--------------+
16 rows in set (0.00 sec)
I have two router VMs, r-6-VM and r-9-VM. They both failed. The full log for restarting r-9-VM is at the following. In this log, it didn't complain on the CPU resource. Could you please help to take a look.
Again thanks for your help,
James
root@cs-mgmt:/var/log/cloudstack/management# cat error4.log
2013-12-20 15:22:56,960 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Starting router VM[DomainRouter|r-9-VM]
2013-12-20 15:22:56,962 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2013-12-20 15:22:56,962 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Successfully transitioned to start state for VM[DomainRouter|r-9-VM] reservation id = cd8b5d0e-aff6-4837-8b31-923a8d020da4
2013-12-20 15:22:57,015 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-20 15:22:57,015 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-20 15:22:57,018 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Root volume is ready, need to place VM in volume's cluster
2013-12-20 15:22:57,018 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Vol[9|vm=9|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-12-20 15:22:57,019 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-20 15:22:57,020 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_875e841@2186a7a9
2013-12-20 15:22:57,020 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 134217728
2013-12-20 15:22:57,020 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Is ROOT volume READY (pool already allocated)?: Yes
2013-12-20 15:22:57,020 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Searching resources only under specified Cluster: 1
2013-12-20 15:22:57,022 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Checking resources in Cluster: 1 under Pod: 1
2013-12-20 15:22:57,023 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-12-20 15:22:57,024 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2013-12-20 15:22:57,025 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2013-12-20 15:22:57,025 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=128
2013-12-20 15:22:57,028 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Free CPU: 26508 , Requested CPU: 500
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Free RAM: 15321509888 , Requested RAM: 134217728
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total: 28008, total with overprovisioning: 28008; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-20 15:22:57,030 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1476395008, reserved: 0, total: 16797904896; requested mem: 134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-20 15:22:57,030 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-20 15:22:57,030 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-20 15:22:57,031 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Checking suitable pools for volume (Id, Type): (9,ROOT)
2013-12-20 15:22:57,031 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2013-12-20 15:22:57,031 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Planner need not allocate a pool for this volume since its READY
2013-12-20 15:22:57,031 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-20 15:22:57,031 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-20 15:22:57,032 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Host: 1 can access pool: 1
2013-12-20 15:22:57,033 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found a potential host id: 1 name: cs-host1 and associated storage pools for this VM
2013-12-20 15:22:57,033 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2013-12-20 15:22:57,033 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Deployment found - P0=VM[DomainRouter|r-9-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2013-12-20 15:22:57,115 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) We are allocating VM, increasing the used capacity of this host:1
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Current Used CPU: 1500 , Free CPU:26508 ,Requested CPU: 500
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Current Used RAM: 1476395008 , Free RAM:15321509888 ,Requested RAM: 134217728
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) CPU STATS after allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 28008, total with overprovisioning: 28008; new used:2000, reserved:0; requested cpu:500,alloc_from_last:false
2013-12-20 15:22:57,122 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) RAM STATS after allocation: for host: 1, old used: 1476395008, old reserved: 0, total: 16797904896; new used: 1610612736, reserved: 0; requested mem: 134217728,alloc_from_last:false
2013-12-20 15:22:57,173 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) VM is being created in podId: 1
2013-12-20 15:22:57,178 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Network id=200 is already implemented
2013-12-20 15:22:57,242 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Network id=207 is already implemented
2013-12-20 15:22:57,300 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Service SecurityGroup is not supported in the network id=207
2013-12-20 15:22:57,386 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Asking VirtualRouter to prepare for Nic[18-9-cd8b5d0e-aff6-4837-8b31-923a8d020da4-192.168.20.1]
2013-12-20 15:22:57,387 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Service SecurityGroup is not supported in the network id=207
2013-12-20 15:22:57,389 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Network id=202 is already implemented
2013-12-20 15:22:57,594 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Checking if we need to prepare 1 volumes for VM[DomainRouter|r-9-VM]
2013-12-20 15:22:57,594 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) No need to recreate the volume: Vol[9|vm=9|ROOT], since it already has a pool assigned: 1, adding disk to VM
2013-12-20 15:22:57,611 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Boot Args for VM[DomainRouter|r-9-VM]: template=domP name=r-9-VM eth2ip=10.1.1.74 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.20.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.20.1 eth1ip=169.254.0.98 eth1mask=255.255.0.0 type=router disable_rp_filter=true dns1=8.8.8.8
2013-12-20 15:22:57,679 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 1 ip(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,692 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Resending ipAssoc, port forwarding, load balancing rules as a part of Virtual router start
2013-12-20 15:22:57,697 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 firewall Egress rule(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 static nat(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 firewall Ingress rule(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 port forwarding rule(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 static nat rule(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,701 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 vpn(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,702 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 load balancing rule(s) to apply as a part of domR VM[DomainRouter|r-9-VM] start.
2013-12-20 15:22:57,703 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Reapplying dhcp entries as a part of domR VM[DomainRouter|r-9-VM] start...
2013-12-20 15:22:57,705 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Reapplying vm data (userData and metaData) entries as a part of domR VM[DomainRouter|r-9-VM] start...
2013-12-20 15:22:57,754 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110781: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":9,"name":"r-9-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-9-VM eth2ip=10.1.1.74 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.20.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.20.1 eth1ip=169.254.0.98 eth1mask=255.255.0.0 type=router disable_rp_filter=true
dns1=8.8.8.8","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"11223cf41eaafaa2","params":{},"uuid":"9ffe0f77-65b8-4e32-b370-6e2a168860b9","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"00a1f71f-ddd6-4c67-9202-c52a78be4ac2","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"edb22d83-4522-360c-8d64-409614a841e4","id":1,"poolType":"NetworkFilesystem","host":"172.16.1.61","path":"/export/primary","port":2049}},"name":"ROOT-9","size":276162048,"path":"84b0b904-7d59-4257-a5f8-541d8d9bdb83","volumeId":9,"vmName":"r-9-VM","accountId":2,"format":"QCOW2","id":9,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"a8240efa-d540-4b3d-88fa-a5adb733a625","ip":"10.1.1.74","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"06:e9:b6:00:00:19","dns1":"8.8.8.8","broadc
astType":"Vlan","type":"Public","broadcastUri":"vlan://10","isolationUri":"vlan://10","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"uuid":"e1e1c57e-c517-4a65-a1d3-663de1dd27eb","ip":"192.168.20.1","netmask":"255.255.255.0","mac":"02:00:32:7f:00:02","dns1":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1082","isolationUri":"vlan://1082","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"4e57d394-e075-4648-abdc-35b09be2738d","ip":"169.254.0.98","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:00:62","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"172.16.1.62","executeInSequence":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.0.98","port":3922,"interval":6,"retries":100,"name":"r-9-VM","wait":0}},{"com.cloud.agent.api.GetDomRVe
rsionCmd":{"accessDetails":{"router.ip":"169.254.0.98","router.name":"r-9-VM"},"wait":0}},{},{"com.cloud.agent.api.routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.1.1.74","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"10","vlanGateway":"10.1.1.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:17:80:00:00:19","networkRate":200,"trafficType":"Public","networkName":"cloudbr0"}],"accessDetails":{"router.guest.ip":"192.168.20.1","zone.network.type":"Advanced","router.ip":"169.254.0.98","router.name":"r-9-VM"},"wait":0}}] }
2013-12-20 15:22:58,338 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1046: Processing Seq 3-1046: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:22:58,455 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1046: Sending Seq 3-1046: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:22:59,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:22:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:22:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:22:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:22:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:22:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:23:08,339 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1047: Processing Seq 3-1047: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:08,424 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1047: Sending Seq 3-1047: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:18,339 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1048: Processing Seq 3-1048: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:18,424 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1048: Sending Seq 3-1048: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:23,609 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:23:23,782 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:23:24,851 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:23:24,853 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:23:24,854 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:23:24,854 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:23:27,391 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 1
2013-12-20 15:23:27,957 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 4
2013-12-20 15:23:27,985 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3
2013-12-20 15:23:28,378 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-1050: Processing Seq 3-1050: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:28,440 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-1050: Sending Seq 3-1050: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:31,579 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2013-12-20 15:23:32,175 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110782: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:23:38,342 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1051: Processing Seq 3-1051: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:38,416 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1051: Sending Seq 3-1051: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:40,162 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-20 15:23:48,342 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1052: Processing Seq 3-1052: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:48,424 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1052: Sending Seq 3-1052: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:52,432 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2013-12-20 15:23:52,502 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1151467617: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:23:52,544 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110783: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:23:53,343 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1053: Processing Seq 3-1053: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:23:53,440 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1053: Sending Seq 3-1053: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:23:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:23:53,778 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:23:54,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:23:54,851 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:23:54,853 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:23:54,854 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:24:03,345 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1054: Processing Seq 3-1054: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:03,423 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1054: Sending Seq 3-1054: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:13,345 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1055: Processing Seq 3-1055: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:13,405 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1055: Sending Seq 3-1055: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:23,346 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1056: Processing Seq 3-1056: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:23,413 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1056: Sending Seq 3-1056: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:23,599 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:24:23,792 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:24:24,699 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-12-20 23:24:24 GMT
2013-12-20 15:24:24,700 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-12-20 23:24:24 GMT
2013-12-20 15:24:24,815 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running...
2013-12-20 15:24:24,821 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 204 is not configured for external networking, so skipping usage check.
2013-12-20 15:24:24,821 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 206 is not configured for external networking, so skipping usage check.
2013-12-20 15:24:24,822 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 207 is not configured for external networking, so skipping usage check.
2013-12-20 15:24:24,839 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-4:null) checking health of usage server
2013-12-20 15:24:24,842 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (HA-4:null) usage server running? false, heartbeat: null
2013-12-20 15:24:24,842 WARN [apache.cloudstack.alerts] (HA-4:null) alertType:: 13 // dataCenterId:: 0 // podId:: 0 // clusterId:: null // message:: No usage server process running
2013-12-20 15:24:24,844 DEBUG [cloud.alert.AlertManagerImpl] (HA-4:null) Have already sent: 1 emails for alert type '13' -- skipping send email
2013-12-20 15:24:24,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 1 running routers.
2013-12-20 15:24:24,853 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 1 running routers.
2013-12-20 15:24:24,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:24:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:24:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:24:24,860 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:24:24,970 DEBUG [cloud.network.NetworkManagerImpl] (Network-Scavenger-1:null) Network 206 is still free but it's not time to shutdown yet: 1355059829
2013-12-20 15:24:24,974 DEBUG [cloud.network.NetworkModelImpl] (Network-Scavenger-1:null) Network id=207 is not ready for GC as it has vms that are Starting at the moment
2013-12-20 15:24:24,987 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-832110784: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-6-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-20 15:24:24,987 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-832110784: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-20 15:24:24,987 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-20 15:24:24,987 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics
2013-12-20 15:24:25,097 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 1-832110785: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-6-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-20 15:24:25,098 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-832110785: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-20 15:24:25,098 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-20 15:24:25,098 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics
2013-12-20 15:24:27,392 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 1
2013-12-20 15:24:27,956 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 4
2013-12-20 15:24:27,986 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3
2013-12-20 15:24:29,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:24:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:24:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:24:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:24:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:24:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:24:32,175 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-20 15:24:32,771 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110786: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:24:33,386 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1058: Processing Seq 3-1058: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:33,454 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1058: Sending Seq 3-1058: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:34,944 DEBUG [network.lb.LBHealthCheckManagerImpl] (LBHealthCheck-1:null) LB HealthCheck Manager is running and getting the updates from LB providers and updating service status
2013-12-20 15:24:34,953 DEBUG [network.lb.LBHealthCheckManagerImpl] (LBHealthCheck-1:null) LB HealthCheck Manager is running and getting the updates from LB providers and updating service status
2013-12-20 15:24:40,166 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2013-12-20 15:24:43,348 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1059: Processing Seq 3-1059: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:43,404 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1059: Sending Seq 3-1059: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:52,544 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-20 15:24:52,606 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 4-1151467618: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:24:52,662 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110787: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:24:53,349 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1060: Processing Seq 3-1060: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:24:53,411 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1060: Sending Seq 3-1060: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:24:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:24:53,774 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:24:54,701 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Checking if any host reservation can be released ...
2013-12-20 15:24:54,702 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2013-12-20 15:24:54,703 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2013-12-20 15:24:54,703 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2013-12-20 15:24:54,712 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Cannot release reservation, Found 4 VMs Running on host 1
2013-12-20 15:24:54,712 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Done running HostReservationReleaseChecker ...
2013-12-20 15:24:54,714 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 4 VMs on host 1
2013-12-20 15:24:54,720 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 1 VM, not running on host 1
2013-12-20 15:24:54,721 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 2000 reservedCpu: 0
2013-12-20 15:24:54,721 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1610612736 reservedMem: 0
2013-12-20 15:24:54,722 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2013-12-20 15:24:54,722 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2013-12-20 15:24:54,794 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 209265098752 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2013-12-20 15:24:54,794 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2013-12-20 15:24:54,794 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2013-12-20 15:24:54,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:24:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:24:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:24:54,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:24:54,912 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2013-12-20 15:24:54,912 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2013-12-20 15:24:54,919 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2013-12-20 15:24:54,919 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2013-12-20 15:24:54,941 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2013-12-20 15:25:03,350 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1061: Processing Seq 3-1061: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:03,419 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1061: Sending Seq 3-1061: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:11,227 DEBUG [api.query.QueryManagerImpl] (catalina-exec-1:null) >>>Searching for hosts>>>
2013-12-20 15:25:11,234 DEBUG [api.query.QueryManagerImpl] (catalina-exec-1:null) >>>Generating Response>>>
2013-12-20 15:25:12,301 DEBUG [api.query.QueryManagerImpl] (catalina-exec-11:null) >>>Searching for hosts>>>
2013-12-20 15:25:12,304 DEBUG [api.query.QueryManagerImpl] (catalina-exec-11:null) >>>Generating Response>>>
2013-12-20 15:25:13,352 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1062: Processing Seq 3-1062: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:13,410 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1062: Sending Seq 3-1062: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:17,450 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Searching for hosts>>>
2013-12-20 15:25:17,454 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Generating Response>>>
2013-12-20 15:25:18,362 DEBUG [api.query.QueryManagerImpl] (catalina-exec-1:null) >>>Searching for hosts>>>
2013-12-20 15:25:18,370 DEBUG [api.query.QueryManagerImpl] (catalina-exec-1:null) >>>Generating Response>>>
2013-12-20 15:25:23,352 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1063: Processing Seq 3-1063: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:23,529 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1063: Sending Seq 3-1063: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:23,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:25:23,780 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:25:24,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:25:24,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:25:24,853 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:25:24,854 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:25:27,389 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 1
2013-12-20 15:25:27,957 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 4
2013-12-20 15:25:27,986 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 3
2013-12-20 15:25:32,771 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2013-12-20 15:25:33,366 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110788: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:25:33,390 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-1065: Processing Seq 3-1065: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:33,476 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-1065: Sending Seq 3-1065: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:40,169 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-20 15:25:43,355 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1066: Processing Seq 3-1066: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:43,408 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1066: Sending Seq 3-1066: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:52,663 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2013-12-20 15:25:52,726 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1151467619: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:25:52,781 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110789: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:25:53,355 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1067: Processing Seq 3-1067: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:25:53,424 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1067: Sending Seq 3-1067: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:25:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:25:53,781 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:25:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:25:54,861 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:25:54,862 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:25:54,862 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:25:59,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:25:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:25:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:25:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:25:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:25:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:26:03,358 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1068: Processing Seq 3-1068: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:03,440 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1068: Sending Seq 3-1068: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:13,358 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-1069: Processing Seq 3-1069: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:13,406 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-1069: Sending Seq 3-1069: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:23,359 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1070: Processing Seq 3-1070: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:23,447 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1070: Sending Seq 3-1070: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:23,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:26:23,774 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:26:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:26:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:26:24,858 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:26:24,858 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:26:27,392 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 1
2013-12-20 15:26:27,957 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 4
2013-12-20 15:26:27,986 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) Ping from 3
2013-12-20 15:26:33,367 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-20 15:26:33,398 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1072: Processing Seq 3-1072: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:33,471 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1072: Sending Seq 3-1072: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:33,963 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110790: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:26:40,172 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2013-12-20 15:26:43,360 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1073: Processing Seq 3-1073: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:43,437 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1073: Sending Seq 3-1073: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:52,782 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-20 15:26:52,846 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 4-1151467620: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:26:52,903 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110791: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:26:53,362 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1074: Processing Seq 3-1074: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:26:53,436 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1074: Sending Seq 3-1074: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:26:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:26:53,779 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:26:54,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:26:54,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:26:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:26:54,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:27:03,362 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-1075: Processing Seq 3-1075: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:03,411 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-1075: Sending Seq 3-1075: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:13,364 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1076: Processing Seq 3-1076: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:13,503 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1076: Sending Seq 3-1076: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:23,364 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1077: Processing Seq 3-1077: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:23,417 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1077: Sending Seq 3-1077: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:23,605 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:27:23,787 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:27:24,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:27:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:27:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:27:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:27:27,392 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 1
2013-12-20 15:27:27,957 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) Ping from 4
2013-12-20 15:27:27,987 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 3
2013-12-20 15:27:29,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:27:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:27:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:27:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:27:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:27:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:27:33,402 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1079: Processing Seq 3-1079: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:33,474 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-1079: Sending Seq 3-1079: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:33,963 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2013-12-20 15:27:34,559 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110792: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:27:40,176 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-20 15:27:43,366 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1080: Processing Seq 3-1080: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:43,457 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1080: Sending Seq 3-1080: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:52,903 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2013-12-20 15:27:52,966 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1151467621: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:27:53,016 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110793: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:27:53,367 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1081: Processing Seq 3-1081: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:27:53,422 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1081: Sending Seq 3-1081: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:27:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:27:53,781 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:27:54,851 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:27:54,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:27:54,858 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:27:54,859 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:28:03,368 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-1082: Processing Seq 3-1082: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:03,430 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-1082: Sending Seq 3-1082: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:13,369 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-1083: Processing Seq 3-1083: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:13,438 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-1083: Sending Seq 3-1083: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:23,370 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1084: Processing Seq 3-1084: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:23,453 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1084: Sending Seq 3-1084: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:23,605 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:28:23,781 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:28:24,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:28:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:28:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:28:24,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:28:27,392 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 1
2013-12-20 15:28:27,958 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 4
2013-12-20 15:28:27,987 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 3
2013-12-20 15:28:33,410 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1086: Processing Seq 3-1086: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:33,478 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-1086: Sending Seq 3-1086: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:34,559 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-20 15:28:35,155 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110794: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:28:40,179 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-20 15:28:43,373 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1087: Processing Seq 3-1087: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:43,460 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1087: Sending Seq 3-1087: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:53,017 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2013-12-20 15:28:53,082 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1151467622: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:28:53,125 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110795: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:28:53,373 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1088: Processing Seq 3-1088: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:28:53,442 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1088: Sending Seq 3-1088: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:28:53,603 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:28:53,780 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:28:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:28:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:28:54,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:28:54,858 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:28:59,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:28:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:28:59,692 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:28:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:28:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:28:59,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:29:03,374 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1089: Processing Seq 3-1089: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:03,451 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1089: Sending Seq 3-1089: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:13,375 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1090: Processing Seq 3-1090: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:13,441 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1090: Sending Seq 3-1090: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:23,376 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1091: Processing Seq 3-1091: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:23,432 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-1091: Sending Seq 3-1091: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:23,605 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:29:23,773 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:29:24,700 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-12-20 23:29:24 GMT
2013-12-20 15:29:24,701 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-12-20 23:29:24 GMT
2013-12-20 15:29:24,815 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running...
2013-12-20 15:29:24,822 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 204 is not configured for external networking, so skipping usage check.
2013-12-20 15:29:24,823 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 206 is not configured for external networking, so skipping usage check.
2013-12-20 15:29:24,824 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 207 is not configured for external networking, so skipping usage check.
2013-12-20 15:29:24,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 1 running routers.
2013-12-20 15:29:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 1 running routers.
2013-12-20 15:29:24,860 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:29:24,861 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:29:24,863 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:29:24,863 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:29:25,033 DEBUG [agent.transport.Request] (AgentManager-Handler-14:null) Seq 1-832110796: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-6-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-20 15:29:25,034 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-832110796: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-20 15:29:25,034 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-20 15:29:25,034 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics
2013-12-20 15:29:25,141 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 1-832110797: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-6-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-20 15:29:25,141 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-832110797: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-20 15:29:25,141 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-20 15:29:25,141 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics
2013-12-20 15:29:27,398 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 1
2013-12-20 15:29:27,958 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 4
2013-12-20 15:29:27,987 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3
2013-12-20 15:29:33,414 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1093: Processing Seq 3-1093: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:33,481 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1093: Sending Seq 3-1093: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:35,155 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-20 15:29:35,747 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110798: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:29:40,182 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2013-12-20 15:29:43,378 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-1094: Processing Seq 3-1094: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:43,464 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-1094: Sending Seq 3-1094: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:46,680 DEBUG [api.query.QueryManagerImpl] (catalina-exec-23:null) >>>Searching for hosts>>>
2013-12-20 15:29:46,686 DEBUG [api.query.QueryManagerImpl] (catalina-exec-23:null) >>>Generating Response>>>
2013-12-20 15:29:53,125 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-20 15:29:53,190 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 4-1151467623: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:29:53,239 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-832110799: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:29:53,380 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1095: Processing Seq 3-1095: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:29:53,447 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-1095: Sending Seq 3-1095: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:29:53,605 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:29:53,775 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:29:54,701 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Checking if any host reservation can be released ...
2013-12-20 15:29:54,702 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2013-12-20 15:29:54,702 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2013-12-20 15:29:54,703 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2013-12-20 15:29:54,711 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Cannot release reservation, Found 4 VMs Running on host 1
2013-12-20 15:29:54,711 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Done running HostReservationReleaseChecker ...
2013-12-20 15:29:54,713 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 4 VMs on host 1
2013-12-20 15:29:54,719 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 1 VM, not running on host 1
2013-12-20 15:29:54,730 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 2000 reservedCpu: 0
2013-12-20 15:29:54,731 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1610612736 reservedMem: 0
2013-12-20 15:29:54,731 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2013-12-20 15:29:54,731 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2013-12-20 15:29:54,814 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 209265098752 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2013-12-20 15:29:54,814 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2013-12-20 15:29:54,814 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2013-12-20 15:29:54,831 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2013-12-20 15:29:54,831 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2013-12-20 15:29:54,833 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2013-12-20 15:29:54,833 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2013-12-20 15:29:54,848 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:29:54,848 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:29:54,850 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2013-12-20 15:29:54,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:29:54,858 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:30:03,380 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1096: Processing Seq 3-1096: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:03,438 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-1096: Sending Seq 3-1096: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:13,381 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1097: Processing Seq 3-1097: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:13,437 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1097: Sending Seq 3-1097: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:23,382 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1098: Processing Seq 3-1098: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:23,587 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1098: Sending Seq 3-1098: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:23,600 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:30:23,780 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:30:24,848 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:30:24,849 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:30:24,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:30:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:30:27,394 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1
2013-12-20 15:30:27,958 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 4
2013-12-20 15:30:27,988 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 3
2013-12-20 15:30:28,422 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1100: Processing Seq 3-1100: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:28,486 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1100: Sending Seq 3-1100: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:29,691 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-20 15:30:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-20 15:30:29,693 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-20 15:30:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-20 15:30:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-20 15:30:29,694 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-20 15:30:35,747 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2013-12-20 15:30:36,343 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110800: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-20 15:30:38,384 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1101: Processing Seq 3-1101: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:38,444 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-1101: Sending Seq 3-1101: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:40,185 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-20 15:30:40,605 DEBUG [api.query.QueryManagerImpl] (catalina-exec-5:null) >>>Searching for hosts>>>
2013-12-20 15:30:40,610 DEBUG [api.query.QueryManagerImpl] (catalina-exec-5:null) >>>Generating Response>>>
2013-12-20 15:30:48,386 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1102: Processing Seq 3-1102: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:48,452 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-1102: Sending Seq 3-1102: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:53,240 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2013-12-20 15:30:53,298 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1151467624: Received: { Ans: , MgmtId: 33296, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:30:53,348 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-832110801: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 15:30:53,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:30:53,774 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:30:54,850 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:30:54,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:30:54,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:30:54,857 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:30:58,386 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1103: Processing Seq 3-1103: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:30:58,446 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-1103: Sending Seq 3-1103: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:30:59,407 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 1-832110781: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":9,"name":"r-9-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-9-VM eth2ip=10.1.1.74 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.20.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.20.1 eth1ip=169.254.0.98 eth1mask=255.255.0.0 type=router disable_rp_filter=true
dns1=8.8.8.8","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"11223cf41eaafaa2","vncAddr":"172.16.1.62","params":{},"uuid":"9ffe0f77-65b8-4e32-b370-6e2a168860b9","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"00a1f71f-ddd6-4c67-9202-c52a78be4ac2","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"edb22d83-4522-360c-8d64-409614a841e4","id":1,"poolType":"NetworkFilesystem","host":"172.16.1.61","path":"/export/primary","port":2049}},"name":"ROOT-9","size":276162048,"path":"84b0b904-7d59-4257-a5f8-541d8d9bdb83","volumeId":9,"vmName":"r-9-VM","accountId":2,"format":"QCOW2","id":9,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"a8240efa-d540-4b3d-88fa-a5adb733a625","ip":"10.1.1.74","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"06:e9:b6:00:00:19",
"dns1":"8.8.8.8","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://10","isolationUri":"vlan://10","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"uuid":"e1e1c57e-c517-4a65-a1d3-663de1dd27eb","ip":"192.168.20.1","netmask":"255.255.255.0","mac":"02:00:32:7f:00:02","dns1":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1082","isolationUri":"vlan://1082","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"4e57d394-e075-4648-abdc-35b09be2738d","ip":"169.254.0.98","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:00:62","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":false,"details":"Can not ping System vm r-9-VMdue to:Unable to
connect","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
2013-12-20 15:30:59,407 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110781: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer, Answer, Answer, Answer } }
2013-12-20 15:30:59,409 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-7:null) Seq 1-832110781: No more commands found
2013-12-20 15:30:59,455 WARN [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Unable to ssh to the VM: Can not ping System vm r-9-VMdue to:Unable to connect
2013-12-20 15:30:59,455 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) The guru did not like the answers so stopping VM[DomainRouter|r-9-VM]
2013-12-20 15:30:59,459 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110802: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"r-9-VM","wait":0}}] }
2013-12-20 15:31:03,704 DEBUG [agent.transport.Request] (AgentManager-Handler-5:null) Seq 1-832110802: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-20 15:31:03,704 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110802: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-20 15:31:03,705 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Failed to start instance VM[DomainRouter|r-9-VM]
com.cloud.utils.exception.ExecutionException: Unable to start VM[DomainRouter|r-9-VM] due to error in finalizeStart, not retrying
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:955)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2740)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1872)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1972)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1950)
at com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElement.java:188)
at com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(NetworkManagerImpl.java:2034)
at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java:1939)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.network.NetworkManagerImpl.startNetwork(NetworkManagerImpl.java:3383)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouter(VirtualNetworkApplianceManagerImpl.java:3121)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouter(VirtualNetworkApplianceManagerImpl.java:3090)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.admin.router.StartRouterCmd.execute(StartRouterCmd.java:110)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2013-12-20 15:31:03,707 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-5:null) Seq 1-832110802: No more commands found
2013-12-20 15:31:03,796 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Cleaning up resources for the vm VM[DomainRouter|r-9-VM] in Starting state
2013-12-20 15:31:03,798 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110803: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"r-9-VM","wait":0}}] }
2013-12-20 15:31:03,922 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-832110803: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-20 15:31:03,922 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-8:null) Seq 1-832110803: No more commands found
2013-12-20 15:31:03,922 DEBUG [agent.transport.Request] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Seq 1-832110803: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-20 15:31:03,930 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Successfully updated user statistics as a part of domR VM[DomainRouter|r-9-VM] reboot/stop
2013-12-20 15:31:03,962 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Service SecurityGroup is not supported in the network id=207
2013-12-20 15:31:04,017 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Asking VirtualRouter to release Nic[18-9-cd8b5d0e-aff6-4837-8b31-923a8d020da4-192.168.20.1]
2013-12-20 15:31:04,020 DEBUG [network.guru.ControlNetworkGuru] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Released nic: NicProfile[19-9-null-null-null
2013-12-20 15:31:04,139 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Successfully released network resources for the vm VM[DomainRouter|r-9-VM]
2013-12-20 15:31:04,139 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Successfully cleanued up resources for the vm VM[DomainRouter|r-9-VM] in Starting state
2013-12-20 15:31:04,265 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2013-12-20 15:31:04,270 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-20 15:31:04,270 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Hosts's actual total RAM: 16797904896 and RAM after applying overprovisioning: 16797904896
2013-12-20 15:31:04,270 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) release cpu from host: 1, old used: 2000,reserved: 0, actual total: 28008, total with overprovisioning: 28008; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-20 15:31:04,270 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) release mem from host: 1, old used: 1610612736,reserved: 0, total: 16797904896; new used: 1476395008,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-20 15:31:04,324 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Cleaning up because we're unable to implement the network Ntwk[207|Guest|8]
2013-12-20 15:31:04,377 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Lock is acquired for network Ntwk[207|Guest|8] as a part of network shutdown
2013-12-20 15:31:04,409 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Releasing 0 port forwarding rules for network id=207 as a part of shutdownNetworkRules
2013-12-20 15:31:04,410 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no rules to forward to the network elements
2013-12-20 15:31:04,411 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Releasing 0 static nat rules for network id=207 as a part of shutdownNetworkRules
2013-12-20 15:31:04,411 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no rules to forward to the network elements
2013-12-20 15:31:04,412 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Revoking 0 Public load balancing rules for network id=207
2013-12-20 15:31:04,412 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no Load Balancing Rules to forward to the network elements
2013-12-20 15:31:04,414 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Revoking 0 Internal load balancing rules for network id=207
2013-12-20 15:31:04,414 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no Load Balancing Rules to forward to the network elements
2013-12-20 15:31:04,415 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Releasing 0 firewall ingress rules for network id=207 as a part of shutdownNetworkRules
2013-12-20 15:31:04,415 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no rules to forward to the network elements
2013-12-20 15:31:04,416 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Releasing 0 firewall egress rules for network id=207 as a part of shutdownNetworkRules
2013-12-20 15:31:04,416 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) There are no rules to forward to the network elements
2013-12-20 15:31:04,417 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Found 0 static nat rules to apply for network id 207
2013-12-20 15:31:04,432 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Router r-9-VM is in Stopped, so not sending apply ip association commands to the backend
2013-12-20 15:31:04,434 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Sending network shutdown to VirtualRouter
2013-12-20 15:31:04,435 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Stopping router VM[DomainRouter|r-9-VM]
2013-12-20 15:31:04,435 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) VM is already stopped: VM[DomainRouter|r-9-VM]
2013-12-20 15:31:04,436 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Network id=207 is shutdown successfully, cleaning up corresponding resources now.
2013-12-20 15:31:04,437 DEBUG [network.guru.GuestNetworkGuru] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Releasing vnet for the network id=207
2013-12-20 15:31:04,491 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Lock is released for network Ntwk[207|Guest|8] as a part of network shutdown
2013-12-20 15:31:04,492 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Lock is released for network id 207 as a part of network implement
2013-12-20 15:31:04,625 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Unexpected exception while executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to start VM[DomainRouter|r-9-VM] due to error in finalizeStart, not retrying
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:988)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2740)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1872)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1972)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1950)
at com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElement.java:188)
at com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(NetworkManagerImpl.java:2034)
at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java:1939)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.network.NetworkManagerImpl.startNetwork(NetworkManagerImpl.java:3383)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouter(VirtualNetworkApplianceManagerImpl.java:3121)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouter(VirtualNetworkApplianceManagerImpl.java:3090)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.admin.router.StartRouterCmd.execute(StartRouterCmd.java:110)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start VM[DomainRouter|r-9-VM] due to error in finalizeStart, not retrying
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:955)
... 30 more
2013-12-20 15:31:04,632 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-2:job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ]) Complete async job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to start VM[DomainRouter|r-9-VM] due to error in finalizeStart, not retrying
2013-12-20 15:31:05,854 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-24:null) Async job-39 = [ 069c2587-3000-45ae-979f-887dc1e99b23 ] completed
2013-12-20 15:31:08,387 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1104: Processing Seq 3-1104: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:31:08,449 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-1104: Sending Seq 3-1104: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:31:18,388 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1105: Processing Seq 3-1105: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:31:18,446 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-1105: Sending Seq 3-1105: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 15:31:23,602 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-20 15:31:23,775 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-20 15:31:24,854 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:31:24,855 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 2 routers to update status.
2013-12-20 15:31:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:31:24,856 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-20 15:31:27,363 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1
2013-12-20 15:31:27,958 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 4
2013-12-20 15:31:27,988 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 3
2013-12-20 15:31:28,426 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1107: Processing Seq 3-1107: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-20 15:31:28,486 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-1107: Sending Seq 3-1107: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
On Thursday, December 19, 2013 12:00 PM, Nitin Mehta <Ni...@citrix.com> wrote:
James - can you paste the complete logs on paste bin ? Also what does
op_host_capacity for this host id say for cpu and ram (capacity_type=0 and
1) ?
An easy way out is to clear the last_host_id in the vm_instance table and
try starting the router.
On 18/12/13 11:52 PM, "James Towner" <ja...@yahoo.com> wrote:
>Hello,
>
>I have CloudStack 4.2.0 on ubuntu 12.04 with KVM hypervisor. The router
>VMs failed to start. Two system VMs work fine. When the router VM failed
>to start, there are entries like the following in management-server.log:
>
>
>2013-12-18 22:49:48,076 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Checking if host: 1 has enough capacity for requested CPU: 500 and
>requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Hosts's actual total CPU: 28008 and CPU after applying overprovisioning:
>28008
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) We
>need to allocate to the last host again, so checking if there is enough
>reserved capacity
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Reserved CPU: 0 , Requested CPU: 500
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Reserved RAM: 0 , Requested RAM: 134217728
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested
>cpu: 500, reservedMem: 0, requested mem: 134217728
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Host
>does not have enough reserved CPU available, cannot allocate to this host.
>2013-12-18 22:49:48,077 DEBUG
>[cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [
>fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) The last host of this VM does not
>have enough capacity
>2013-12-18 22:49:48,077 DEBUG
>[cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [
>fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Cannot choose the last host to
>deploy this VM
>
>My host has eight core CPU, enough free memory, and only two VMs are
>running at that time.
>
>~$ free
> total used free shared buffers cached
>Mem: 16404204 825780 15578424 0 24144 106496
>-/+ buffers/cache: 695140 15709064
>Swap: 48932860 0 48932860
>
>Why CloudStack still don't have enough resource?
>
>Thanks in advance,
>James
Re: router VM failed - reservedCpu: 0, requested cpu: 500,
Posted by Nitin Mehta <Ni...@citrix.com>.
James - can you paste the complete logs on paste bin ? Also what does
op_host_capacity for this host id say for cpu and ram (capacity_type=0 and
1) ?
An easy way out is to clear the last_host_id in the vm_instance table and
try starting the router.
On 18/12/13 11:52 PM, "James Towner" <ja...@yahoo.com> wrote:
>Hello,
>
>I have CloudStack 4.2.0 on ubuntu 12.04 with KVM hypervisor. The router
>VMs failed to start. Two system VMs work fine. When the router VM failed
>to start, there are entries like the following in management-server.log:
>
>
>2013-12-18 22:49:48,076 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Checking if host: 1 has enough capacity for requested CPU: 500 and
>requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Hosts's actual total CPU: 28008 and CPU after applying overprovisioning:
>28008
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) We
>need to allocate to the last host again, so checking if there is enough
>reserved capacity
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Reserved CPU: 0 , Requested CPU: 500
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>Reserved RAM: 0 , Requested RAM: 134217728
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ])
>STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested
>cpu: 500, reservedMem: 0, requested mem: 134217728
>2013-12-18 22:49:48,077 DEBUG [cloud.capacity.CapacityManagerImpl]
>(Job-Executor-14:job-47 = [ fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Host
>does not have enough reserved CPU available, cannot allocate to this host.
>2013-12-18 22:49:48,077 DEBUG
>[cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [
>fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) The last host of this VM does not
>have enough capacity
>2013-12-18 22:49:48,077 DEBUG
>[cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-14:job-47 = [
>fb35f9d6-10bb-4a69-9dcd-ad0d405ab1f1 ]) Cannot choose the last host to
>deploy this VM
>
>My host has eight core CPU, enough free memory, and only two VMs are
>running at that time.
>
>~$ free
> total used free shared buffers cached
>Mem: 16404204 825780 15578424 0 24144 106496
>-/+ buffers/cache: 695140 15709064
>Swap: 48932860 0 48932860
>
>Why CloudStack still don't have enough resource?
>
>Thanks in advance,
>James