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 00:23:31 UTC
System Virtual Routers failed to start
Hello,
I have CloudStack 4.2.0 on Ubuntu 12.04 as management server. One KVM host on Ubuntu 12.04. On this setup, i created 6 isolated networks. On this same host, only two virtual routers can start normally, the others failed to start and end at "Stopped" status. When i try to restart one failed router, i got the following messages on ClooudStack UI:
Resource [Host:1] is unreachable: Host 1: Unable to start instance due to Unable to start VM[DomainRouter|r-16-VM] due to error in finalizeStart, not retrying
In management-server.log, i saw the following entries:
2013-12-18 11:23:48,220 WARN [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Unable to ssh to the VM: Can not ping System vm r-16-VMdue to:Unable to connect
...
2013-12-18 11:23:54,476 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-908263463: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-18 11:23:54,477 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-9:null) Seq 1-908263463: No more commands found
2013-12-18 11:23:54,477 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263463: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-18 11:23:54,478 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Failed to start instance VM[DomainRouter|r-16-VM]
I cannot see any other log entry which points to the root cause of this failure. What do i missed? The full log for this restart is at the bottom of this message.
Thanks in advance,
James
management-server.log:
root@cs-mgmt:/var/log/cloudstack/management# cat mgmt-log1.log
2013-12-18 11:15:29,714 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 3-20874: Sending Seq 3-20874: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:15:34,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:15:34,485 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:15:35,273 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:15:35,335 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446159: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:15:35,416 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263433: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:15:35,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:15:35,654 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:15:35,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:15:35,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:15:39,525 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20875: Processing Seq 3-20875: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:15:39,666 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20875: Sending Seq 3-20875: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:15:39,726 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 3
2013-12-18 11:15:39,861 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 2
2013-12-18 11:15:44,590 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Executing org.apache.cloudstack.api.command.admin.router.StartRouterCmd for job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]
2013-12-18 11:15:44,736 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Starting network Ntwk[209|Guest|8]...
2013-12-18 11:15:44,739 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is acquired for network id 209 as a part of network implement
2013-12-18 11:15:44,739 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Asking ExternalGuestNetworkGuru to implement Ntwk[209|Guest|8]
2013-12-18 11:15:45,185 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Asking VirtualRouter to implemenet Ntwk[209|Guest|8]
2013-12-18 11:15:45,195 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is acquired for network id 209 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(null)-Host(null)-Storage()]
2013-12-18 11:15:45,198 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is released for network id 209 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(null)-Host(null)-Storage()]
2013-12-18 11:15:45,198 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Starting router VM[DomainRouter|r-16-VM]
2013-12-18 11:15:45,201 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 1 new host id: null host id before state transition: null
2013-12-18 11:15:45,201 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Successfully transitioned to start state for VM[DomainRouter|r-16-VM] reservation id = decb3ccd-d9dc-4f7d-8ff8-507358795d0b
2013-12-18 11:15:45,288 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-12-18 11:15:45,288 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-18 11:15:45,291 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Root volume is ready, need to place VM in volume's cluster
2013-12-18 11:15:45,291 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Vol[16|vm=16|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-12-18 11:15:45,292 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Deploy avoids pods: null, clusters: null, hosts: null
2013-12-18 11:15:45,293 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_c8f49d4@537eff32
2013-12-18 11:15:45,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 134217728
2013-12-18 11:15:45,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Is ROOT volume READY (pool already allocated)?: Yes
2013-12-18 11:15:45,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) This VM has last host_id specified, trying to choose the same host: 1
2013-12-18 11:15:45,300 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) We need to allocate to the last host again, so checking if there is enough reserved capacity
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reserved CPU: 0 , Requested CPU: 500
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reserved RAM: 0 , Requested RAM: 134217728
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) STATS: Failed to alloc resource from host: 1 reservedCpu: 0, requested cpu: 500, reservedMem: 0, requested mem: 134217728
2013-12-18 11:15:45,301 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Host does not have enough reserved CPU available, cannot allocate to this host.
2013-12-18 11:15:45,301 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) The last host of this VM does not have enough capacity
2013-12-18 11:15:45,301 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Cannot choose the last host to deploy this VM
2013-12-18 11:15:45,301 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Searching resources only under specified Cluster: 1
2013-12-18 11:15:45,309 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Checking resources in Cluster: 1 under Pod: 1
2013-12-18 11:15:45,309 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-12-18 11:15:45,310 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2013-12-18 11:15:45,312 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2013-12-18 11:15:45,312 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=128
2013-12-18 11:15:45,316 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 134217728 , cpuOverprovisioningFactor: 1.0
2013-12-18 11:15:45,317 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-18 11:15:45,317 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Free CPU: 25008 , Requested CPU: 500
2013-12-18 11:15:45,317 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Free RAM: 14113550336 , Requested RAM: 134217728
2013-12-18 11:15:45,317 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Host has enough CPU and RAM available
2013-12-18 11:15:45,318 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 3000, reserved: 0, actual total: 28008, total with overprovisioning: 28008; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-18 11:15:45,318 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 2684354560, reserved: 0, total: 16797904896; requested mem: 134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-12-18 11:15:45,318 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2013-12-18 11:15:45,318 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2013-12-18 11:15:45,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Checking suitable pools for volume (Id, Type): (16,ROOT)
2013-12-18 11:15:45,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Volume has pool already allocated, checking if pool can be reused, poolId: 1
2013-12-18 11:15:45,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Planner need not allocate a pool for this volume since its READY
2013-12-18 11:15:45,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2013-12-18 11:15:45,319 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2013-12-18 11:15:45,320 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Host: 1 can access pool: 1
2013-12-18 11:15:45,320 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found a potential host id: 1 name: cs-host1 and associated storage pools for this VM
2013-12-18 11:15:45,321 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) 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-18 11:15:45,321 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Deployment found - P0=VM[DomainRouter|r-16-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-18 11:15:45,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 1 new host id: 1 host id before state transition: null
2013-12-18 11:15:45,449 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM starting again on the last host it was stopped on
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) We are allocating VM, increasing the used capacity of this host:1
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Current Used CPU: 3000 , Free CPU:25008 ,Requested CPU: 500
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Current Used RAM: 2684354560 , Free RAM:14113550336 ,Requested RAM: 134217728
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reserved CPU: 0 , Requested CPU: 500
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reserved RAM: 0 , Requested RAM: 134217728
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) CPU STATS after allocation: for host: 1, old used: 3000, old reserved: 0, actual total: 28008, total with overprovisioning: 28008; new used:3500, reserved:0; requested cpu:500,alloc_from_last:true
2013-12-18 11:15:45,457 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) RAM STATS after allocation: for host: 1, old used: 2684354560, old reserved: 0, total: 16797904896; new used: 2818572288, reserved: 0; requested mem: 134217728,alloc_from_last:true
2013-12-18 11:15:45,539 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM is being created in podId: 1
2013-12-18 11:15:45,543 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Network id=200 is already implemented
2013-12-18 11:15:45,640 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Network id=209 is already implemented
2013-12-18 11:15:45,732 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Service SecurityGroup is not supported in the network id=209
2013-12-18 11:15:45,826 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Asking VirtualRouter to prepare for Nic[32-16-decb3ccd-d9dc-4f7d-8ff8-507358795d0b-192.168.60.1]
2013-12-18 11:15:45,827 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Service SecurityGroup is not supported in the network id=209
2013-12-18 11:15:45,830 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Network id=202 is already implemented
2013-12-18 11:15:46,084 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Checking if we need to prepare 1 volumes for VM[DomainRouter|r-16-VM]
2013-12-18 11:15:46,084 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) No need to recreate the volume: Vol[16|vm=16|ROOT], since it already has a pool assigned: 1, adding disk to VM
2013-12-18 11:15:46,096 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Boot Args for VM[DomainRouter|r-16-VM]: template=domP name=r-16-VM eth2ip=10.1.1.77 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.60.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.60.1 eth1ip=169.254.2.176 eth1mask=255.255.0.0 type=router disable_rp_filter=true dns1=8.8.8.8
2013-12-18 11:15:46,220 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 1 ip(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,231 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Resending ipAssoc, port forwarding, load balancing rules as a part of Virtual router start
2013-12-18 11:15:46,235 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 firewall Egress rule(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,239 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 static nat(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,239 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 firewall Ingress rule(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,239 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 port forwarding rule(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,239 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 static nat rule(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,239 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 vpn(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,240 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 load balancing rule(s) to apply as a part of domR VM[DomainRouter|r-16-VM] start.
2013-12-18 11:15:46,241 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reapplying dhcp entries as a part of domR VM[DomainRouter|r-16-VM] start...
2013-12-18 11:15:46,258 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Reapplying vm data (userData and metaData) entries as a part of domR VM[DomainRouter|r-16-VM] start...
2013-12-18 11:15:46,326 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263434: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":16,"name":"r-16-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-16-VM eth2ip=10.1.1.77 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.60.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.60.1 eth1ip=169.254.2.176 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":"3056da58bd515037","params":{},"uuid":"eb18b719-0558-47b0-88b1-fd21f55f6c91","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"459e887e-e63c-44f7-93fe-ac4ff50bd027","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-16","size":276162048,"path":"49cfbc1c-d90a-4269-a2ea-532bc421bac9","volumeId":16,"vmName":"r-16-VM","accountId":2,"format":"QCOW2","id":16,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"c773c8c8-76f4-4ce5-9315-c93fb66d5191","ip":"10.1.1.77","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"06:22:de:00:00:1c","dns1":"8.8.8.8","br
oadcastType":"Vlan","type":"Public","broadcastUri":"vlan://10","isolationUri":"vlan://10","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"uuid":"2f4bddf8-ac19-42eb-a82a-a799542e0f2d","ip":"192.168.60.1","netmask":"255.255.255.0","mac":"02:00:53:bf:00:02","dns1":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1071","isolationUri":"vlan://1071","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"aa3cf004-e467-450f-ad05-f4bf0fa9bc8f","ip":"169.254.2.176","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:b0","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"hostIp":"172.16.1.62","executeInSequence":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.2.176","port":3922,"interval":6,"retries":100,"name":"r-16-VM","wait":0}},{"com.cloud.agent.api.Ge
tDomRVersionCmd":{"accessDetails":{"router.ip":"169.254.2.176","router.name":"r-16-VM"},"wait":0}},{},{"com.cloud.agent.api.routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.1.1.77","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"10","vlanGateway":"10.1.1.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:dd:78:00:00:1c","networkRate":200,"trafficType":"Public","networkName":"cloudbr0"}],"accessDetails":{"router.guest.ip":"192.168.60.1","zone.network.type":"Advanced","router.ip":"169.254.2.176","router.name":"r-16-VM"},"wait":0}}] }
2013-12-18 11:15:48,386 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2013-12-18 11:15:48,964 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263435: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:15:49,563 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20877: Processing Seq 3-20877: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:15:49,641 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20877: Sending Seq 3-20877: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:15:59,526 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20878: Processing Seq 3-20878: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:15:59,682 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20878: Sending Seq 3-20878: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:00,774 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 1
2013-12-18 11:16:04,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:16:04,497 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:16:04,528 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20879: Processing Seq 3-20879: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:04,650 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20879: Sending Seq 3-20879: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:05,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:16:05,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:16:05,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:16:05,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:16:14,529 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20880: Processing Seq 3-20880: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:14,639 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20880: Sending Seq 3-20880: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:23,210 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-18 11:16:23,303 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263436: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:16:24,529 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20881: Processing Seq 3-20881: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:24,629 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20881: Sending Seq 3-20881: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:34,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:16:34,485 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:16:34,530 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20882: Processing Seq 3-20882: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:34,595 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20882: Sending Seq 3-20882: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:35,416 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-12-18 11:16:35,487 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 2-538446160: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:16:35,566 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263437: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:16:35,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:16:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:16:35,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:16:35,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:16:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 3
2013-12-18 11:16:39,857 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 2
2013-12-18 11:16:40,969 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:16:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:16:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:16:40,973 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:16:40,973 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:16:40,974 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:16:44,567 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20884: Processing Seq 3-20884: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:44,763 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20884: Sending Seq 3-20884: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:48,965 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-18 11:16:49,538 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263438: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:16:54,532 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20885: Processing Seq 3-20885: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:54,618 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20885: Sending Seq 3-20885: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:16:59,532 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20886: Processing Seq 3-20886: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:16:59,610 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20886: Sending Seq 3-20886: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:00,904 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1
2013-12-18 11:17:04,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:17:04,491 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:17:05,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:17:05,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:17:05,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:17:05,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:17:09,533 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20887: Processing Seq 3-20887: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:09,635 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20887: Sending Seq 3-20887: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:19,534 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20888: Processing Seq 3-20888: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:19,642 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20888: Sending Seq 3-20888: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:23,304 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2013-12-18 11:17:23,399 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263439: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:17:29,536 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20889: Processing Seq 3-20889: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:29,633 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20889: Sending Seq 3-20889: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:34,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:17:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:17:34,535 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20890: Processing Seq 3-20890: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:34,616 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20890: Sending Seq 3-20890: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:35,567 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:17:35,629 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446161: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:17:35,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:17:35,661 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:17:35,661 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:17:35,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:17:35,711 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263440: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:17:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3
2013-12-18 11:17:39,857 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 2
2013-12-18 11:17:44,575 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20892: Processing Seq 3-20892: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:44,866 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20892: Sending Seq 3-20892: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:17:49,538 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2013-12-18 11:17:50,116 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263441: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:17:54,537 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20893: Processing Seq 3-20893: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:17:54,901 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20893: Sending Seq 3-20893: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:00,900 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 1
2013-12-18 11:18:04,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:18:04,485 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:18:04,539 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20894: Processing Seq 3-20894: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:04,621 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20894: Sending Seq 3-20894: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:05,661 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:18:05,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:18:05,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:18:05,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:18:10,969 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:18:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:18:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:18:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:18:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:18:10,973 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:18:14,539 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20895: Processing Seq 3-20895: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:14,629 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20895: Sending Seq 3-20895: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:19,539 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20896: Processing Seq 3-20896: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:19,637 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20896: Sending Seq 3-20896: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:22,809 DEBUG [cloud.network.NetworkModelImpl] (Network-Scavenger-1:null) Network id=209 is not ready for GC as it has vms that are Starting at the moment
2013-12-18 11:18:23,400 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-18 11:18:23,495 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263442: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:18:29,540 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20897: Processing Seq 3-20897: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:29,770 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20897: Sending Seq 3-20897: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:34,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:18:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:18:35,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:18:35,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:18:35,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:18:35,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:18:35,712 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-12-18 11:18:35,771 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 2-538446162: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:18:35,857 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263443: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:18:39,542 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20898: Processing Seq 3-20898: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:39,652 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20898: Sending Seq 3-20898: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:39,728 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 3
2013-12-18 11:18:39,857 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 2
2013-12-18 11:18:49,579 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20900: Processing Seq 3-20900: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:49,692 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20900: Sending Seq 3-20900: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:18:50,117 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-18 11:18:50,694 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263444: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:18:59,543 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20901: Processing Seq 3-20901: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:18:59,625 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20901: Sending Seq 3-20901: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:00,903 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 1
2013-12-18 11:19:04,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:19:04,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:19:04,543 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20902: Processing Seq 3-20902: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:04,691 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20902: Sending Seq 3-20902: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:05,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:19:05,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:19:05,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:19:05,665 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:19:14,545 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20903: Processing Seq 3-20903: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:14,706 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20903: Sending Seq 3-20903: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:23,496 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2013-12-18 11:19:23,600 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263445: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:19:24,544 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20904: Processing Seq 3-20904: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:24,663 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20904: Sending Seq 3-20904: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:34,312 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:19:34,485 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:19:34,545 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20905: Processing Seq 3-20905: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:34,883 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20905: Sending Seq 3-20905: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:35,623 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running...
2013-12-18 11:19:35,628 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 204 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,628 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 205 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,629 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 206 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,629 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 207 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,630 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 208 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,631 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 209 is not configured for external networking, so skipping usage check.
2013-12-18 11:19:35,652 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 2 running routers.
2013-12-18 11:19:35,657 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 2 running routers.
2013-12-18 11:19:35,665 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:19:35,666 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:19:35,669 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:19:35,669 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:19:35,797 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-908263446: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":87840,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:19:35,797 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263446: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:19:35,797 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:19:35,829 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-12-18 19:19:35 GMT
2013-12-18 11:19:35,830 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-12-18 19:19:35 GMT
2013-12-18 11:19:35,857 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:19:35,906 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 1-908263447: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":87840,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:19:35,906 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263447: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:19:35,907 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:19:35,919 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446163: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:19:36,019 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263449: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:19:36,065 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 1-908263448: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-9-VM","bytesSent":56160,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:19:36,066 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263448: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:19:36,066 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:19:36,119 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 1-908263450: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-9-VM","bytesSent":56160,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:19:36,120 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263450: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:19:36,120 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:19:39,546 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20906: Processing Seq 3-20906: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:39,697 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20906: Sending Seq 3-20906: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 3
2013-12-18 11:19:39,858 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 2
2013-12-18 11:19:40,969 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:19:40,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:19:40,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:19:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:19:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:19:40,973 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:19:49,583 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20908: Processing Seq 3-20908: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:49,730 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20908: Sending Seq 3-20908: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:19:50,695 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2013-12-18 11:19:51,314 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263451: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:19:59,548 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20909: Processing Seq 3-20909: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:19:59,891 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20909: Sending Seq 3-20909: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:00,903 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1
2013-12-18 11:20:04,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:20:04,491 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:20:05,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:20:05,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:20:05,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:20:05,665 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:20:05,813 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2013-12-18 11:20:05,813 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2013-12-18 11:20:05,814 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2013-12-18 11:20:05,816 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Checking if any host reservation can be released ...
2013-12-18 11:20:05,820 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Cannot release reservation, Found 7 VMs Running on host 1
2013-12-18 11:20:05,824 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:null) Done running HostReservationReleaseChecker ...
2013-12-18 11:20:05,824 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 7 VMs on host 1
2013-12-18 11:20:05,833 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 4 VM, not running on host 1
2013-12-18 11:20:05,836 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (CapacityChecker:null) MessageBus message: host reserved capacity released for VM: 1, checking if host reservation can be released for host:1
2013-12-18 11:20:05,839 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (CapacityChecker:null) Cannot release reservation, Found 7 VMs Running on host 1
2013-12-18 11:20:05,840 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 3500 reservedCpu: 0
2013-12-18 11:20:05,841 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 2818572288 reservedMem: 0
2013-12-18 11:20:05,841 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2013-12-18 11:20:05,841 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2013-12-18 11:20:05,969 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 209265098752 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2013-12-18 11:20:05,969 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2013-12-18 11:20:05,970 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2013-12-18 11:20:06,044 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2013-12-18 11:20:06,045 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2013-12-18 11:20:06,048 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2013-12-18 11:20:06,048 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2013-12-18 11:20:06,062 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2013-12-18 11:20:09,548 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20910: Processing Seq 3-20910: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:09,645 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20910: Sending Seq 3-20910: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:19,549 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20911: Processing Seq 3-20911: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:19,661 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20911: Sending Seq 3-20911: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:23,600 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2013-12-18 11:20:23,695 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263452: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:20:24,550 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20912: Processing Seq 3-20912: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:24,889 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20912: Sending Seq 3-20912: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:34,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:20:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:20:34,550 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20913: Processing Seq 3-20913: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:34,693 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20913: Sending Seq 3-20913: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:35,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:20:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:20:35,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:20:35,665 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:20:36,019 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:20:36,075 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446164: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:20:36,141 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263453: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:20:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3
2013-12-18 11:20:39,857 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 2
2013-12-18 11:20:44,591 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20915: Processing Seq 3-20915: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:44,693 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20915: Sending Seq 3-20915: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:51,314 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2013-12-18 11:20:51,889 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263454: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:20:54,552 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20916: Processing Seq 3-20916: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:54,626 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20916: Sending Seq 3-20916: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:20:59,553 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20917: Processing Seq 3-20917: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:20:59,759 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20917: Sending Seq 3-20917: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:00,903 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 1
2013-12-18 11:21:04,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:21:04,351 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Searching for hosts>>>
2013-12-18 11:21:04,355 DEBUG [api.query.QueryManagerImpl] (catalina-exec-22:null) >>>Generating Response>>>
2013-12-18 11:21:04,485 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:21:05,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:21:05,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:21:05,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:21:05,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:21:09,553 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20918: Processing Seq 3-20918: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:09,862 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20918: Sending Seq 3-20918: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:10,970 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:21:10,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:21:10,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:21:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:21:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:21:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:21:19,554 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20919: Processing Seq 3-20919: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:19,746 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20919: Sending Seq 3-20919: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:23,695 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-18 11:21:23,787 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263455: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:21:29,555 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20920: Processing Seq 3-20920: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:29,790 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20920: Sending Seq 3-20920: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:34,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:21:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:21:34,557 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20921: Processing Seq 3-20921: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:35,142 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 3-20921: Sending Seq 3-20921: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:35,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:21:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:21:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:21:35,664 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:21:36,141 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-12-18 11:21:36,203 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 2-538446165: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:21:36,264 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263456: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:21:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 3
2013-12-18 11:21:39,857 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 2
2013-12-18 11:21:44,595 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20923: Processing Seq 3-20923: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:44,841 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 3-20923: Sending Seq 3-20923: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:21:51,889 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-18 11:21:52,468 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263457: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:21:54,558 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20924: Processing Seq 3-20924: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:21:54,704 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 3-20924: Sending Seq 3-20924: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:00,914 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 1
2013-12-18 11:22:04,315 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:22:04,487 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:22:04,558 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20925: Processing Seq 3-20925: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:05,330 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20925: Sending Seq 3-20925: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:05,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:22:05,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:22:05,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:22:05,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:22:14,559 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20926: Processing Seq 3-20926: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:14,860 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20926: Sending Seq 3-20926: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:19,560 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20927: Processing Seq 3-20927: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:19,838 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20927: Sending Seq 3-20927: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:23,787 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2013-12-18 11:22:23,888 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263458: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:22:29,560 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20928: Processing Seq 3-20928: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:29,649 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20928: Sending Seq 3-20928: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:34,313 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:22:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:22:35,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:22:35,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:22:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:22:35,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:22:36,265 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:22:36,323 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446166: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:22:36,380 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263459: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:22:39,561 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20929: Processing Seq 3-20929: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:39,649 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 3-20929: Sending Seq 3-20929: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 3
2013-12-18 11:22:39,858 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 2
2013-12-18 11:22:40,970 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:22:40,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:22:40,971 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:22:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:22:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:22:40,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:22:49,599 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-20931: Processing Seq 3-20931: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:49,665 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-20931: Sending Seq 3-20931: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:22:52,469 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2013-12-18 11:22:53,048 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263460: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:22:54,110 DEBUG [api.query.QueryManagerImpl] (catalina-exec-19:null) >>>Searching for hosts>>>
2013-12-18 11:22:54,113 DEBUG [api.query.QueryManagerImpl] (catalina-exec-19:null) >>>Generating Response>>>
2013-12-18 11:22:59,563 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20932: Processing Seq 3-20932: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:22:59,656 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 3-20932: Sending Seq 3-20932: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:00,907 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 1
2013-12-18 11:23:04,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:23:04,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:23:04,564 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20933: Processing Seq 3-20933: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:04,639 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20933: Sending Seq 3-20933: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:05,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:23:05,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:23:05,662 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:23:05,663 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:23:14,564 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20934: Processing Seq 3-20934: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:14,889 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 3-20934: Sending Seq 3-20934: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:23,888 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running...
2013-12-18 11:23:23,979 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263461: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:23:24,565 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20935: Processing Seq 3-20935: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:24,662 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20935: Sending Seq 3-20935: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:34,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:23:34,486 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:23:34,566 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20936: Processing Seq 3-20936: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:34,645 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 3-20936: Sending Seq 3-20936: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:35,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:23:35,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:23:35,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:23:35,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:23:36,381 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-12-18 11:23:36,443 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 2-538446167: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:23:36,503 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263462: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:23:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 3
2013-12-18 11:23:39,858 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 2
2013-12-18 11:23:44,603 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20938: Processing Seq 3-20938: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:44,775 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-20938: Sending Seq 3-20938: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:48,053 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 1-908263434: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":16,"name":"r-16-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-16-VM eth2ip=10.1.1.77 eth2mask=255.255.255.0 gateway=10.1.1.1 eth0ip=192.168.60.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=192.168.60.1 eth1ip=169.254.2.176 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":"3056da58bd515037","vncAddr":"172.16.1.62","params":{},"uuid":"eb18b719-0558-47b0-88b1-fd21f55f6c91","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"459e887e-e63c-44f7-93fe-ac4ff50bd027","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-16","size":276162048,"path":"49cfbc1c-d90a-4269-a2ea-532bc421bac9","volumeId":16,"vmName":"r-16-VM","accountId":2,"format":"QCOW2","id":16,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"c773c8c8-76f4-4ce5-9315-c93fb66d5191","ip":"10.1.1.77","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"06:22:de:00:00:
1c","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":"2f4bddf8-ac19-42eb-a82a-a799542e0f2d","ip":"192.168.60.1","netmask":"255.255.255.0","mac":"02:00:53:bf:00:02","dns1":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1071","isolationUri":"vlan://1071","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"aa3cf004-e467-450f-ad05-f4bf0fa9bc8f","ip":"169.254.2.176","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:b0","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-16-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-18 11:23:48,053 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263434: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer, Answer, Answer, Answer } }
2013-12-18 11:23:48,056 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-3:null) Seq 1-908263434: No more commands found
2013-12-18 11:23:48,220 WARN [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Unable to ssh to the VM: Can not ping System vm r-16-VMdue to:Unable to connect
2013-12-18 11:23:48,224 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) The guru did not like the answers so stopping VM[DomainRouter|r-16-VM]
2013-12-18 11:23:48,227 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263463: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"r-16-VM","wait":0}}] }
2013-12-18 11:23:49,567 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-20939: Processing Seq 3-20939: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:49,703 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-20939: Sending Seq 3-20939: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:23:53,049 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
2013-12-18 11:23:53,627 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263464: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-12-18 11:23:54,476 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-908263463: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-18 11:23:54,477 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-9:null) Seq 1-908263463: No more commands found
2013-12-18 11:23:54,477 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263463: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-18 11:23:54,478 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Failed to start instance VM[DomainRouter|r-16-VM]
com.cloud.utils.exception.ExecutionException: Unable to start VM[DomainRouter|r-16-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-18 11:23:54,803 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Cleaning up resources for the vm VM[DomainRouter|r-16-VM] in Starting state
2013-12-18 11:23:54,805 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263465: Sending { Cmd , MgmtId: 33296, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"r-16-VM","wait":0}}] }
2013-12-18 11:23:54,931 DEBUG [agent.transport.Request] (AgentManager-Handler-10:null) Seq 1-908263465: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-12-18 11:23:54,932 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-10:null) Seq 1-908263465: No more commands found
2013-12-18 11:23:54,932 DEBUG [agent.transport.Request] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Seq 1-908263465: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-12-18 11:23:54,935 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Successfully updated user statistics as a part of domR VM[DomainRouter|r-16-VM] reboot/stop
2013-12-18 11:23:54,983 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Service SecurityGroup is not supported in the network id=209
2013-12-18 11:23:55,055 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Asking VirtualRouter to release Nic[32-16-decb3ccd-d9dc-4f7d-8ff8-507358795d0b-192.168.60.1]
2013-12-18 11:23:55,057 DEBUG [network.guru.ControlNetworkGuru] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Released nic: NicProfile[33-16-null-null-null
2013-12-18 11:23:55,228 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Successfully released network resources for the vm VM[DomainRouter|r-16-VM]
2013-12-18 11:23:55,229 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Successfully cleanued up resources for the vm VM[DomainRouter|r-16-VM] in Starting state
2013-12-18 11:23:55,387 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 1 new host id: null host id before state transition: 1
2013-12-18 11:23:55,392 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Hosts's actual total CPU: 28008 and CPU after applying overprovisioning: 28008
2013-12-18 11:23:55,392 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Hosts's actual total RAM: 16797904896 and RAM after applying overprovisioning: 16797904896
2013-12-18 11:23:55,392 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) release cpu from host: 1, old used: 3500,reserved: 0, actual total: 28008, total with overprovisioning: 28008; new used: 3000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-18 11:23:55,392 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) release mem from host: 1, old used: 2818572288,reserved: 0, total: 16797904896; new used: 2684354560,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-12-18 11:23:55,481 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Cleaning up because we're unable to implement the network Ntwk[209|Guest|8]
2013-12-18 11:23:55,574 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is acquired for network Ntwk[209|Guest|8] as a part of network shutdown
2013-12-18 11:23:55,624 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Releasing 0 port forwarding rules for network id=209 as a part of shutdownNetworkRules
2013-12-18 11:23:55,624 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no rules to forward to the network elements
2013-12-18 11:23:55,625 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Releasing 0 static nat rules for network id=209 as a part of shutdownNetworkRules
2013-12-18 11:23:55,626 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no rules to forward to the network elements
2013-12-18 11:23:55,627 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Revoking 0 Public load balancing rules for network id=209
2013-12-18 11:23:55,628 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no Load Balancing Rules to forward to the network elements
2013-12-18 11:23:55,629 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Revoking 0 Internal load balancing rules for network id=209
2013-12-18 11:23:55,630 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no Load Balancing Rules to forward to the network elements
2013-12-18 11:23:55,630 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Releasing 0 firewall ingress rules for network id=209 as a part of shutdownNetworkRules
2013-12-18 11:23:55,630 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no rules to forward to the network elements
2013-12-18 11:23:55,631 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Releasing 0 firewall egress rules for network id=209 as a part of shutdownNetworkRules
2013-12-18 11:23:55,631 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) There are no rules to forward to the network elements
2013-12-18 11:23:55,632 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Found 0 static nat rules to apply for network id 209
2013-12-18 11:23:55,638 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Router r-16-VM is in Stopped, so not sending apply ip association commands to the backend
2013-12-18 11:23:55,640 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Sending network shutdown to VirtualRouter
2013-12-18 11:23:55,641 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Stopping router VM[DomainRouter|r-16-VM]
2013-12-18 11:23:55,641 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) VM is already stopped: VM[DomainRouter|r-16-VM]
2013-12-18 11:23:55,643 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Network id=209 is shutdown successfully, cleaning up corresponding resources now.
2013-12-18 11:23:55,644 DEBUG [network.guru.GuestNetworkGuru] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Releasing vnet for the network id=209
2013-12-18 11:23:55,730 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is released for network Ntwk[209|Guest|8] as a part of network shutdown
2013-12-18 11:23:55,731 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Lock is released for network id 209 as a part of network implement
2013-12-18 11:23:55,815 ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) 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-16-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-16-VM] due to error in finalizeStart, not retrying
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:955)
... 30 more
2013-12-18 11:23:55,818 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-9:job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ]) Complete async job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ], 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-16-VM] due to error in finalizeStart, not retrying
2013-12-18 11:23:56,723 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-24:null) Async job-42 = [ 6574db80-1636-4d7e-824d-0a7d2a7be166 ] completed
2013-12-18 11:23:59,568 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20940: Processing Seq 3-20940: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:23:59,664 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) SeqA 3-20940: Sending Seq 3-20940: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:24:00,868 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 1
2013-12-18 11:24:04,318 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:24:04,492 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:24:05,658 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:24:05,659 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:24:05,660 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:24:05,661 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:24:09,569 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20941: Processing Seq 3-20941: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:24:09,679 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 3-20941: Sending Seq 3-20941: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:24:10,970 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect
2013-12-18 11:24:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect
2013-12-18 11:24:10,972 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server
2013-12-18 11:24:10,973 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server
2013-12-18 11:24:10,974 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server
2013-12-18 11:24:10,974 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server
2013-12-18 11:24:19,570 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20942: Processing Seq 3-20942: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:24:19,720 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 3-20942: Sending Seq 3-20942: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:24:23,980 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2013-12-18 11:24:24,076 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-908263466: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2013-12-18 11:24:24,570 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20943: Processing Seq 3-20943: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:24:24,668 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-20943: Sending Seq 3-20943: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:24:34,314 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-12-18 11:24:34,494 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-12-18 11:24:34,571 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20944: Processing Seq 3-20944: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2013-12-18 11:24:34,641 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 3-20944: Sending Seq 3-20944: { Ans: , MgmtId: 33296, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-18 11:24:35,623 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running...
2013-12-18 11:24:35,633 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 204 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,634 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 205 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,635 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 206 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,636 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 207 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,637 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 208 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,638 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 209 is not configured for external networking, so skipping usage check.
2013-12-18 11:24:35,641 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-2:null) checking health of usage server
2013-12-18 11:24:35,645 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (HA-2:null) usage server running? false, heartbeat: null
2013-12-18 11:24:35,645 WARN [apache.cloudstack.alerts] (HA-2:null) alertType:: 13 // dataCenterId:: 0 // podId:: 0 // clusterId:: null // message:: No usage server process running
2013-12-18 11:24:35,653 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 2 running routers.
2013-12-18 11:24:35,657 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 2 running routers.
2013-12-18 11:24:35,663 DEBUG [cloud.alert.AlertManagerImpl] (HA-2:null) Have already sent: 1 emails for alert type '13' -- skipping send email
2013-12-18 11:24:35,666 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:24:35,667 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 5 routers to update status.
2013-12-18 11:24:35,669 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:24:35,671 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-12-18 11:24:35,802 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 1-908263467: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":87840,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:24:35,802 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263467: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:24:35,802 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:24:35,807 DEBUG [agent.transport.Request] (AgentManager-Handler-4:null) Seq 1-908263468: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":87840,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:24:35,807 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263468: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:24:35,807 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:24:35,830 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-12-18 19:24:35 GMT
2013-12-18 11:24:35,830 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-12-18 19:24:35 GMT
2013-12-18 11:24:36,000 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 1-908263469: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-9-VM","bytesSent":56520,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:24:36,000 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263469: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:24:36,000 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:24:36,025 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 1-908263470: Processing: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-9-VM","bytesSent":56520,"bytesReceived":0,"result":true,"details":"","wait":0}}] }
2013-12-18 11:24:36,025 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-908263470: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2013-12-18 11:24:36,025 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand:
2013-12-18 11:24:36,034 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Router stats changed from the time NetworkUsageCommand was sent. Ignoring current answer. Router: r-9-VM Rcvd: 0Sent: 56520
2013-12-18 11:24:36,034 DEBUG [db.Transaction.Transaction] (RouterMonitor-1:null) Rolling back the transaction: Time = 9 Name = -VirtualNetworkApplianceManagerImpl$NetworkUsageTask.run:900-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201:165-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:267-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:701; called by -Transaction.rollback:898-Transaction.removeUpTo:841-Transaction.close:665-VirtualNetworkApplianceManagerImpl$NetworkUsageTask.run:955-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201:165-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:267-ThreadPoolExecutor.runWorker:1146-ThreadPoolExecutor$Worker.run:615-Thread.run:701
2013-12-18 11:24:36,503 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running...
2013-12-18 11:24:36,563 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-538446168: Received: { Ans: , MgmtId: 33296, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:24:36,630 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-908263471: Received: { Ans: , MgmtId: 33296, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-18 11:24:39,727 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 3
2013-12-18 11:24:39,858 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 2