Welcome, Guest
Username: Password: Remember me
Archived CloudStack Forums for reference purposes please direct all future inquiries to the Apache CloudStack mailing lists.

incubator.apache.org/cloudstack/mailing-lists.html
  • Page:
  • 1

TOPIC: Unable to launch VM using ISO

Unable to launch VM using ISO 8 months 1 week ago #12973

  • kadam134
  • kadam134's Avatar
  • OFFLINE
  • Fresh Boarder
  • Posts: 2
  • Karma: 0
Environment : CloudStack on CentOS 6.3
Host : XenServer 6.0
Primary and Secondary Storege : NFS share from FreeBSD 8.2


able to download FreeBSD ISO through CLoudStack, but while creating a Instance using the FreeBSD ISO, it fails saying --- " Unable to create a deployment for VM[User|i-2-9-VM] "

CloudStack Dashboard shows that --- " VLAN Failed to deploy Vm with Id: 9 "

I doubt that this is a Virtual Router issue.. and please someone help me out how do i fix it..



Attachment : management-server.log

ManagementServerLog.txt
Last Edit: 8 months 1 week ago by kadam134.
The administrator has disabled public write access.

Re: Unable to launch VM using ISO 8 months 1 week ago #12974

  • kadam134
  • kadam134's Avatar
  • OFFLINE
  • Fresh Boarder
  • Posts: 2
  • Karma: 0
Here is the Management Server Log ----


2012-11-05 11:08:54,832 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:08:59,862 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2012-11-05 11:08:59,922 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-9:null) Cleanup succeeded. Details null
2012-11-05 11:08:59,923 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1875513492: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:08:59,923 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:08:59,945 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-220:null) Seq 1-843325073: Executing request
2012-11-05 11:09:00,410 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-220:null) Seq 1-843325073: Response Received:
2012-11-05 11:09:00,411 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325073: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:09:00,411 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:09:00,412 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-220:null) Cleanup succeeded. Details null
2012-11-05 11:09:02,190 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-246:null) Ping from 1
2012-11-05 11:09:03,516 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-220:null) Seq 1-843317254: Executing request
2012-11-05 11:09:03,802 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-220:null) Seq 1-843317254: Response Received:
2012-11-05 11:09:03,802 DEBUG [agent.transport.Request] (DirectAgent-220:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:09:09,010 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 4
2012-11-05 11:09:11,811 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2012-11-05 11:09:18,877 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:09:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:09:24,837 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:09:36,141 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 3
2012-11-05 11:09:43,403 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2012-11-05 11:09:43,425 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-266:null) Seq 1-843325074: Executing request
2012-11-05 11:09:43,665 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-266:null) Seq 1-843325074: Response Received:
2012-11-05 11:09:43,665 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325074: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:09:43,666 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:09:43,666 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-266:null) Cleanup succeeded. Details null
2012-11-05 11:09:44,566 DEBUG [cloud.user.AccountManagerImpl] (catalina-exec-23:null) Access granted to Acct[2-admin] to Domain:1/ by DomainChecker
2012-11-05 11:09:48,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:09:49,072 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:09:54,313 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-22:null) Allocating in the DB for vm
2012-11-05 11:09:54,313 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-22:null) Allocating entries for VM: VM[User|i-2-9-VM]
2012-11-05 11:09:54,316 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-22:null) Allocating nics for VM[User|i-2-9-VM]
2012-11-05 11:09:54,326 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-22:null) Allocaing disks for VM[User|i-2-9-VM]
2012-11-05 11:09:54,332 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catalina-exec-22:null) Allocation completed for VM: VM[User|i-2-9-VM]
2012-11-05 11:09:54,332 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-22:null) Successfully allocated DB entry for VM[User|i-2-9-VM]
2012-11-05 11:09:54,391 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-22:null) submit async job-15, details: AsyncJobVO {id:15, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 9, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null, cmdInfo: {"sessionkey":"wHDVtb2gVWkBHw13UnJxAXjuJpI\u003d","ctxUserId":"2","serviceOfferingId":"9af8f51c-e40b-47f8-a370-8e387952e7e1","securitygroupids":"b3af98b0-7650-4821-bb19-8ec57d01bab3","zoneId":"d5ec0389-5ae4-4e49-89fb-635f27f83af2","response":"json","templateId":"1b6112d4-3fa2-4299-af94-c6a17ef03f40","id":"9","hypervisor":"XenServer","diskOfferingId":"1c55ab9b-0eda-4ad6-92cb-680dba38c5be","name":"TestVM1","_":"1352093994370","ctxAccountId":"2","group":"test","ctxStartEventId":"132","displayname":"TestVM1"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 52240803170, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-11-05 11:09:54,397 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-5:job-15) Executing com.cloud.api.commands.DeployVMCmd for job-15
2012-11-05 11:09:54,420 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2012-11-05 11:09:54,420 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Successfully transitioned to start state for VM[User|i-2-9-VM] reservation id = a81fe5f8-f227-4eee-a15d-edd851de46e0
2012-11-05 11:09:54,426 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Trying to deploy VM, vm has dcId: 1 and podId: null
2012-11-05 11:09:54,426 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Deploy avoids pods: null, clusters: null, hosts: null
2012-11-05 11:09:54,428 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) DeploymentPlanner allocation algorithm: random
2012-11-05 11:09:54,428 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2012-11-05 11:09:54,428 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Is ROOT volume READY (pool already allocated)?: No
2012-11-05 11:09:54,428 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Searching all possible resources under this Zone: 1
2012-11-05 11:09:54,430 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-11-05 11:09:54,431 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) CPUOverprovisioningFactor considered: 1.0
2012-11-05 11:09:54,438 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Checking resources in Cluster: 1 under Pod: 1
2012-11-05 11:09:54,438 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Calling HostAllocators to find suitable hosts
2012-11-05 11:09:54,438 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-11-05 11:09:54,440 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2012-11-05 11:09:54,443 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2012-11-05 11:09:54,443 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2012-11-05 11:09:54,444 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2012-11-05 11:09:54,446 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Hosts's actual total CPU: 9064 and CPU after applying overprovisioning: 9064
2012-11-05 11:09:54,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Free CPU: 7564 , Requested CPU: 1000
2012-11-05 11:09:54,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Free RAM: 31426329728 , Requested RAM: 1073741824
2012-11-05 11:09:54,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2012-11-05 11:09:54,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total: 9064, total with overprovisioning: 9064; requested cpu:1000,alooa_from_last_host?:false ,considerReservedCapacity?: true
2012-11-05 11:09:54,447 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1476395008, reserved: 0, total: 32902724736; requested mem: 1073741824,alooa_from_last_host?:false ,considerReservedCapacity?: true
2012-11-05 11:09:54,447 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2012-11-05 11:09:54,447 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2012-11-05 11:09:54,448 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Checking suitable pools for volume (Id, Type): (11,ROOT)
2012-11-05 11:09:54,448 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) We need to allocate new storagepool for this volume
2012-11-05 11:09:54,448 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Calling StoragePoolAllocators to find suitable pools
2012-11-05 11:09:54,449 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-5:job-15) Looking for pools in dc: 1 pod:1 cluster:1
2012-11-05 11:09:54,450 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-5:job-15) FirstFitStoragePoolAllocator has 1 pools to check for allocation
2012-11-05 11:09:54,450 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-5:job-15) Checking if storage pool is suitable, name: Primary ,poolId: 203
2012-11-05 11:09:54,450 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-5:job-15) Is localStorageAllocationNeeded? false
2012-11-05 11:09:54,450 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-5:job-15) Is storage pool shared? true
2012-11-05 11:09:54,451 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-5:job-15) Attempting to look for pool 203 for storage, totalSize: 105164374016, usedBytes: 1284964352, usedPct: 0.012218627876817885, disable threshold: 0.85
2012-11-05 11:09:54,453 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-5:job-15) Attempting to look for pool 203 for storage, maxSize : 210328748032, totalAllocatedSize : 7007691264, askingSize : 107374182400, allocated disable threshold: 0.85
2012-11-05 11:09:54,453 DEBUG [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-5:job-15) FirstFitStoragePoolAllocator returning 1 suitable storage pools
2012-11-05 11:09:54,453 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2012-11-05 11:09:54,453 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2012-11-05 11:09:54,454 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Host: 1 can access pool: 203
2012-11-05 11:09:54,454 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Found a potential host id: 1 name: xenserver1 and associated storage pools for this VM
2012-11-05 11:09:54,456 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) 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(Volume(11|ROOT-->Pool(203))]
2012-11-05 11:09:54,456 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Deployment found - P0=VM[User|i-2-9-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(11|ROOT-->Pool(203))]
2012-11-05 11:09:54,462 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) Hosts's actual total CPU: 9064 and CPU after applying overprovisioning: 9064
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) We are allocating VM, increasing the used capacity of this host:1
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) Current Used CPU: 1500 , Free CPU:7564 ,Requested CPU: 1000
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) Current Used RAM: 1476395008 , Free RAM:31426329728 ,Requested RAM: 1073741824
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) CPU STATS after allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 9064, total with overprovisioning: 9064; new used:2500, reserved:0; requested cpu:1000,alooa_from_last:false
2012-11-05 11:09:54,470 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) RAM STATS after allocation: for host: 1, old used: 1476395008, old reserved: 0, total: 32902724736; new used: 2550136832, reserved: 0; requested mem: 1073741824,alooa_from_last:false
2012-11-05 11:09:54,477 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) VM is being started in podId: 1
2012-11-05 11:09:54,480 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Network id=204 is already implemented
2012-11-05 11:09:54,504 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Changing active number of nics for network id=204 on 1
2012-11-05 11:09:54,507 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Asking JuniperSRX to prepare for Nic[15-9-a81fe5f8-f227-4eee-a15d-edd851de46e0-10.56.20.1]
2012-11-05 11:09:54,510 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Asking Netscaler to prepare for Nic[15-9-a81fe5f8-f227-4eee-a15d-edd851de46e0-10.56.20.1]
2012-11-05 11:09:54,513 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Asking F5BigIp to prepare for Nic[15-9-a81fe5f8-f227-4eee-a15d-edd851de46e0-10.56.20.1]
2012-11-05 11:09:54,517 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Asking VirtualRouter to prepare for Nic[15-9-a81fe5f8-f227-4eee-a15d-edd851de46e0-10.56.20.1]
2012-11-05 11:09:54,525 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-15) Starting a router for Ntwk[204|Guest|5] in datacenter:com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$2461485f@1
2012-11-05 11:09:54,539 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-15) Applying dhcp entry in network Ntwk[204|Guest|5]
2012-11-05 11:09:54,552 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325075: Sending { Cmd , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:4a:40:00:00:65","vmIpAddress":"10.56.20.1","vmName":"TestVM1","defaultRouter":"10.10.1.1","defaultDns":"10.56.20.2","accessDetails":{"router.guest.ip":"10.56.20.2","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.2.95"},"wait":0}}] }
2012-11-05 11:09:54,552 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325075: Executing: { Cmd , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmMac":"06:4a:40:00:00:65","vmIpAddress":"10.56.20.1","vmName":"TestVM1","defaultRouter":"10.10.1.1","defaultDns":"10.56.20.2","accessDetails":{"router.guest.ip":"10.56.20.2","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.2.95"},"wait":0}}] }
2012-11-05 11:09:54,552 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-1:null) Seq 1-843325075: Executing request
2012-11-05 11:09:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:09:54,865 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-1:null) Seq 1-843325075: Response Received:
2012-11-05 11:09:54,866 DEBUG [agent.transport.Request] (DirectAgent-1:null) Seq 1-843325075: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"DhcpEntry failed","wait":0}}] }
2012-11-05 11:09:54,866 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325075: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 110, { Answer } }
2012-11-05 11:09:54,867 WARN [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Cleanup failed due to DhcpEntry failed
2012-11-05 11:09:54,872 WARN [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-1:null) Cleanup failed due to DhcpEntry failed
2012-11-05 11:09:54,874 DEBUG [agent.manager.AgentAttache] (DirectAgent-1:null) Seq 1-843325075: No more commands found
2012-11-05 11:09:54,875 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [Pod:1] is unreachable: Unable to apply dhcp entry on router
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:2802)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:2089)
at com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:738)
at com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:1792)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:1887)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:741)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:461)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2580)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2517)
at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:32)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:317)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:132)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:427)
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:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-11-05 11:09:54,884 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Cleaning up resources for the vm VM[User|i-2-9-VM] in Starting state
2012-11-05 11:09:54,885 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325076: Sending { Cmd , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-9-VM","wait":0}}] }
2012-11-05 11:09:54,885 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325076: Executing: { Cmd , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-9-VM","wait":0}}] }
2012-11-05 11:09:54,886 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-153:null) Seq 1-843325076: Executing request
2012-11-05 11:09:54,982 INFO [xen.resource.CitrixResourceBase] (DirectAgent-153:null) VM does not exist on XenServer089f8b3f-0214-4083-8ea1-9b2a9a01fe9d
2012-11-05 11:09:54,982 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-153:null) Seq 1-843325076: Response Received:
2012-11-05 11:09:54,983 DEBUG [agent.transport.Request] (DirectAgent-153:null) Seq 1-843325076: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"bytesSent":0,"bytesReceived":0,"result":true,"details":"VM does not exist","wait":0}}] }
2012-11-05 11:09:54,983 DEBUG [agent.transport.Request] (Job-Executor-5:job-15) Seq 1-843325076: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2012-11-05 11:09:54,983 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Cleanup succeeded. Details VM does not exist
2012-11-05 11:09:54,989 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-153:null) Cleanup succeeded. Details VM does not exist
2012-11-05 11:09:54,989 DEBUG [agent.manager.AgentAttache] (DirectAgent-153:null) Seq 1-843325076: No more commands found
2012-11-05 11:09:55,015 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-15) Changing active number of nics for network id=204 on -1
2012-11-05 11:09:55,018 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Successfully cleanued up resources for the vm VM[User|i-2-9-VM] in Starting state
2012-11-05 11:09:55,020 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) DeploymentPlanner allocation algorithm: random
2012-11-05 11:09:55,020 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2012-11-05 11:09:55,020 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Is ROOT volume READY (pool already allocated)?: No
2012-11-05 11:09:55,020 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Searching all possible resources under this Zone: 1
2012-11-05 11:09:55,021 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2012-11-05 11:09:55,022 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) CPUOverprovisioningFactor considered: 1.0
2012-11-05 11:09:55,029 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Checking resources in Cluster: 1 under Pod: 1
2012-11-05 11:09:55,029 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Calling HostAllocators to find suitable hosts
2012-11-05 11:09:55,029 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2012-11-05 11:09:55,031 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2012-11-05 11:09:55,033 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2012-11-05 11:09:55,033 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2012-11-05 11:09:55,033 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Host name: xenserver1, hostId: 1 is in avoid set, skipping this and trying other available hosts
2012-11-05 11:09:55,033 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-5:job-15 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2012-11-05 11:09:55,033 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) No suitable hosts found
2012-11-05 11:09:55,033 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) No suitable hosts found under this Cluster: 1
2012-11-05 11:09:55,033 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-15) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2012-11-05 11:09:55,040 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2012-11-05 11:09:55,043 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) Hosts's actual total CPU: 9064 and CPU after applying overprovisioning: 9064
2012-11-05 11:09:55,044 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) release cpu from host: 1, old used: 2500,reserved: 0, actual total: 9064, total with overprovisioning: 9064; new used: 1500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-11-05 11:09:55,044 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) release mem from host: 1, old used: 2550136832,reserved: 0, total: 32902724736; new used: 1476395008,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-11-05 11:09:55,055 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-15) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
2012-11-05 11:09:55,097 INFO [api.commands.DeployVMCmd] (Job-Executor-5:job-15) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-9-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2012-11-05 11:09:55,097 WARN [cloud.api.ApiDispatcher] (Job-Executor-5:job-15) class com.cloud.api.ServerApiException : Unable to create a deployment for VM[User|i-2-9-VM]
2012-11-05 11:09:55,097 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-5:job-15) Complete async job-15, jobStatus: 2, resultCode: 530, result: com.cloud.api.response.ExceptionResponse@2b5e498c
2012-11-05 11:09:59,434 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-24:null) Async job-15 completed
2012-11-05 11:10:00,412 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2012-11-05 11:10:00,472 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-12:null) Cleanup succeeded. Details null
2012-11-05 11:10:00,472 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1875513493: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:10:00,472 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:10:00,482 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-268:null) Seq 1-843325077: Executing request
2012-11-05 11:10:00,933 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-268:null) Seq 1-843325077: Response Received:
2012-11-05 11:10:00,933 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325077: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:10:00,934 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:10:00,934 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-268:null) Cleanup succeeded. Details null
2012-11-05 11:10:02,170 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-153:null) Ping from 1
2012-11-05 11:10:03,516 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-268:null) Seq 1-843317254: Executing request
2012-11-05 11:10:03,802 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-268:null) Seq 1-843317254: Response Received:
2012-11-05 11:10:03,802 DEBUG [agent.transport.Request] (DirectAgent-268:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:10:09,010 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 4
2012-11-05 11:10:11,823 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2012-11-05 11:10:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:10:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:10:24,836 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2012-11-05 11:10:24,837 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:10:25,023 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) External load balancer devices stats collector is running...
2012-11-05 11:10:25,380 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2012-11-05 05:40:25 GMT
2012-11-05 11:10:25,383 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2012-11-05 05:40:25 GMT
2012-11-05 11:10:36,142 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3
2012-11-05 11:10:43,666 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2012-11-05 11:10:43,686 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-421:null) Seq 1-843325078: Executing request
2012-11-05 11:10:43,911 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-421:null) Seq 1-843325078: Response Received:
2012-11-05 11:10:43,912 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325078: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:10:43,912 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:10:43,912 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-421:null) Cleanup succeeded. Details null
2012-11-05 11:10:48,870 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:10:49,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:10:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:10:55,307 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2012-11-05 11:10:55,307 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2012-11-05 11:10:55,307 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2012-11-05 11:10:55,325 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 3 VMs on host 1
2012-11-05 11:10:55,326 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 0 VM, not running on host 1
2012-11-05 11:10:55,328 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 1500 reservedCpu: 0
2012-11-05 11:10:55,328 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1476395008 reservedMem: 0
2012-11-05 11:10:55,328 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2012-11-05 11:10:55,328 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2012-11-05 11:10:55,337 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 210328748032 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 203, PodId 1
2012-11-05 11:10:55,337 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2012-11-05 11:10:55,337 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2012-11-05 11:10:55,345 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2012-11-05 11:10:55,346 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2012-11-05 11:10:55,350 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2012-11-05 11:10:55,351 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2012-11-05 11:10:55,365 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2012-11-05 11:11:00,934 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:11:00,994 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-1:null) Cleanup succeeded. Details null
2012-11-05 11:11:00,994 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513494: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:11:00,994 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:11:00,999 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843325079: Executing request
2012-11-05 11:11:01,521 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843325079: Response Received:
2012-11-05 11:11:01,521 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325079: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:11:01,521 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:11:01,521 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-444:null) Cleanup succeeded. Details null
2012-11-05 11:11:02,191 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-421:null) Ping from 1
2012-11-05 11:11:03,516 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843317254: Executing request
2012-11-05 11:11:03,796 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843317254: Response Received:
2012-11-05 11:11:03,797 DEBUG [agent.transport.Request] (DirectAgent-444:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:11:09,011 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 4
2012-11-05 11:11:11,835 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-11-05 11:11:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:11:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:11:24,832 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:11:36,143 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 3
2012-11-05 11:11:43,912 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:11:43,937 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-143:null) Seq 1-843325080: Executing request
2012-11-05 11:11:44,166 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-143:null) Seq 1-843325080: Response Received:
2012-11-05 11:11:44,167 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325080: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:11:44,167 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:11:44,168 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-143:null) Cleanup succeeded. Details null
2012-11-05 11:11:48,886 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:11:49,057 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:11:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:12:01,522 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2012-11-05 11:12:01,599 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-4:null) Cleanup succeeded. Details null
2012-11-05 11:12:01,600 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1875513495: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:12:01,600 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:12:01,621 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-481:null) Seq 1-843325081: Executing request
2012-11-05 11:12:02,143 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-481:null) Seq 1-843325081: Response Received:
2012-11-05 11:12:02,143 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325081: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:12:02,143 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:12:02,144 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-481:null) Cleanup succeeded. Details null
2012-11-05 11:12:02,196 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-143:null) Ping from 1
2012-11-05 11:12:03,516 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843317254: Executing request
2012-11-05 11:12:03,803 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-444:null) Seq 1-843317254: Response Received:
2012-11-05 11:12:03,803 DEBUG [agent.transport.Request] (DirectAgent-444:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:12:09,011 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 4
2012-11-05 11:12:11,838 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-11-05 11:12:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:12:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:12:24,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:12:36,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) Ping from 3
2012-11-05 11:12:44,168 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:12:44,197 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843325082: Executing request
2012-11-05 11:12:44,416 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843325082: Response Received:
2012-11-05 11:12:44,416 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325082: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:12:44,416 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:12:44,416 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-391:null) Cleanup succeeded. Details null
2012-11-05 11:12:48,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:12:49,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:12:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:13:02,148 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:13:02,207 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Ping from 1
2012-11-05 11:13:02,226 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-7:null) Cleanup succeeded. Details null
2012-11-05 11:13:02,226 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513496: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:13:02,226 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:13:02,244 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-166:null) Seq 1-843325083: Executing request
2012-11-05 11:13:02,660 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-166:null) Seq 1-843325083: Response Received:
2012-11-05 11:13:02,661 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325083: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:13:02,661 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:13:02,665 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-166:null) Cleanup succeeded. Details null
2012-11-05 11:13:03,516 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843317254: Executing request
2012-11-05 11:13:03,801 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843317254: Response Received:
2012-11-05 11:13:03,801 DEBUG [agent.transport.Request] (DirectAgent-391:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:13:09,012 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-8:null) Ping from 4
2012-11-05 11:13:11,850 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-11-05 11:13:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:13:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:13:24,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:13:36,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 3
2012-11-05 11:13:44,416 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running...
2012-11-05 11:13:44,424 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-314:null) Seq 1-843325084: Executing request
2012-11-05 11:13:44,648 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-314:null) Seq 1-843325084: Response Received:
2012-11-05 11:13:44,649 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325084: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:13:44,649 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:13:44,649 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-314:null) Cleanup succeeded. Details null
2012-11-05 11:13:48,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:13:49,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:13:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:14:02,187 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Ping from 1
2012-11-05 11:14:02,670 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:14:02,751 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-9:null) Cleanup succeeded. Details null
2012-11-05 11:14:02,752 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513497: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:14:02,752 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:14:02,775 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-16:null) Seq 1-843325085: Executing request
2012-11-05 11:14:03,439 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-16:null) Seq 1-843325085: Response Received:
2012-11-05 11:14:03,439 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325085: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:14:03,439 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:14:03,440 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-16:null) Cleanup succeeded. Details null
2012-11-05 11:14:03,517 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843317254: Executing request
2012-11-05 11:14:03,803 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Seq 1-843317254: Response Received:
2012-11-05 11:14:03,803 DEBUG [agent.transport.Request] (DirectAgent-391:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:14:09,012 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 4
2012-11-05 11:14:11,856 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-11-05 11:14:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:14:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:14:24,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:14:36,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 3
2012-11-05 11:14:44,649 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:14:44,676 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-289:null) Seq 1-843325086: Executing request
2012-11-05 11:14:44,898 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-289:null) Seq 1-843325086: Response Received:
2012-11-05 11:14:44,899 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325086: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:14:44,899 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:14:44,899 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-289:null) Cleanup succeeded. Details null
2012-11-05 11:14:48,880 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:14:49,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:14:54,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:15:02,198 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-391:null) Ping from 1
2012-11-05 11:15:03,440 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:15:03,517 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-289:null) Seq 1-843317254: Executing request
2012-11-05 11:15:03,538 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513498: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:15:03,538 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-12:null) Cleanup succeeded. Details null
2012-11-05 11:15:03,538 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:15:03,552 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-95:null) Seq 1-843325087: Executing request
2012-11-05 11:15:03,822 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-289:null) Seq 1-843317254: Response Received:
2012-11-05 11:15:03,822 DEBUG [agent.transport.Request] (DirectAgent-289:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:15:04,113 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-95:null) Seq 1-843325087: Response Received:
2012-11-05 11:15:04,113 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325087: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:15:04,113 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:15:04,114 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-95:null) Cleanup succeeded. Details null
2012-11-05 11:15:09,013 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Ping from 4
2012-11-05 11:15:11,859 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2012-11-05 11:15:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:15:19,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:15:24,836 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
2012-11-05 11:15:24,837 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:15:25,024 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) External load balancer devices stats collector is running...
2012-11-05 11:15:25,032 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-1:null) checking health of usage server
2012-11-05 11:15:25,037 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (HA-1:null) usage server running? false, heartbeat: null
2012-11-05 11:15:25,044 DEBUG [cloud.alert.AlertManagerImpl] (HA-1:null) Have already sent: 1 emails for alert type '12' -- skipping send email
2012-11-05 11:15:25,369 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2012-11-05 05:45:25 GMT
2012-11-05 11:15:25,372 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2012-11-05 05:45:25 GMT
2012-11-05 11:15:25,374 INFO [storage.upload.UploadMonitorImpl] (UploadMonitor-Scavenger-1:null) Extract Monitor Garbage Collection Thread is running.
2012-11-05 11:15:36,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3
2012-11-05 11:15:44,900 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:15:44,925 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-2:null) Seq 1-843325088: Executing request
2012-11-05 11:15:45,149 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-2:null) Seq 1-843325088: Response Received:
2012-11-05 11:15:45,150 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325088: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:15:45,150 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:15:45,150 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-2:null) Cleanup succeeded. Details null
2012-11-05 11:15:48,876 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:15:49,075 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:15:54,836 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:15:55,308 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ...
2012-11-05 11:15:55,308 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity
2012-11-05 11:15:55,308 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update
2012-11-05 11:15:55,326 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 3 VMs on host 1
2012-11-05 11:15:55,327 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 0 VM, not running on host 1
2012-11-05 11:15:55,329 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 1500 reservedCpu: 0
2012-11-05 11:15:55,329 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1476395008 reservedMem: 0
2012-11-05 11:15:55,329 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update
2012-11-05 11:15:55,329 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update
2012-11-05 11:15:55,338 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 210328748032 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 203, PodId 1
2012-11-05 11:15:55,338 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update
2012-11-05 11:15:55,338 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans
2012-11-05 11:15:55,343 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans
2012-11-05 11:15:55,343 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip
2012-11-05 11:15:55,348 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip
2012-11-05 11:15:55,348 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity
2012-11-05 11:15:55,363 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ...
2012-11-05 11:16:02,167 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-95:null) Ping from 1
2012-11-05 11:16:03,517 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-2:null) Seq 1-843317254: Executing request
2012-11-05 11:16:03,811 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-2:null) Seq 1-843317254: Response Received:
2012-11-05 11:16:03,811 DEBUG [agent.transport.Request] (DirectAgent-2:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:16:04,114 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running...
2012-11-05 11:16:04,186 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-1:null) Cleanup succeeded. Details null
2012-11-05 11:16:04,187 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 4-1875513499: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:16:04,187 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:16:04,205 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-310:null) Seq 1-843325089: Executing request
2012-11-05 11:16:04,672 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-310:null) Seq 1-843325089: Response Received:
2012-11-05 11:16:04,673 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-843325089: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:16:04,673 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-2:null) Cleanup succeeded. Details null
2012-11-05 11:16:04,673 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-310:null) Cleanup succeeded. Details null
2012-11-05 11:16:09,012 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 4
2012-11-05 11:16:11,871 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running...
2012-11-05 11:16:18,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:16:19,080 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:16:24,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:16:36,146 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 3
2012-11-05 11:16:45,151 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:16:45,175 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-129:null) Seq 1-843325090: Executing request
2012-11-05 11:16:45,398 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-129:null) Seq 1-843325090: Response Received:
2012-11-05 11:16:45,398 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325090: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:16:45,398 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:16:45,399 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-129:null) Cleanup succeeded. Details null
2012-11-05 11:16:48,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:16:49,071 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:16:54,834 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:17:02,193 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-310:null) Ping from 1
2012-11-05 11:17:03,517 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-129:null) Seq 1-843317254: Executing request
2012-11-05 11:17:03,802 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-129:null) Seq 1-843317254: Response Received:
2012-11-05 11:17:03,803 DEBUG [agent.transport.Request] (DirectAgent-129:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:17:04,673 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:17:04,749 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-4:null) Cleanup succeeded. Details null
2012-11-05 11:17:04,749 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513500: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:17:04,749 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:17:04,758 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-254:null) Seq 1-843325091: Executing request
2012-11-05 11:17:05,837 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-254:null) Seq 1-843325091: Response Received:
2012-11-05 11:17:05,838 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325091: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:17:05,838 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:17:05,838 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-254:null) Cleanup succeeded. Details null
2012-11-05 11:17:09,014 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 4
2012-11-05 11:17:11,885 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
2012-11-05 11:17:18,886 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:17:19,073 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:17:24,835 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:17:36,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) Ping from 3
2012-11-05 11:17:45,399 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running...
2012-11-05 11:17:45,414 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-262:null) Seq 1-843325092: Executing request
2012-11-05 11:17:45,634 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-262:null) Seq 1-843325092: Response Received:
2012-11-05 11:17:45,635 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-843325092: Received: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2012-11-05 11:17:45,635 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:17:45,635 DEBUG [cloud.vm.VirtualMachineManagerImpl] (DirectAgent-262:null) Cleanup succeeded. Details null
2012-11-05 11:17:48,885 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-11-05 11:17:49,072 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-11-05 11:17:54,836 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers.
2012-11-05 11:18:02,176 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-262:null) Ping from 1
2012-11-05 11:18:03,517 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-254:null) Seq 1-843317254: Executing request
2012-11-05 11:18:03,812 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-254:null) Seq 1-843317254: Response Received:
2012-11-05 11:18:03,812 DEBUG [agent.transport.Request] (DirectAgent-254:null) Seq 1-843317254: Processing: { Ans: , MgmtId: 52240803170, via: 1, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}] }
2012-11-05 11:18:05,839 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2012-11-05 11:18:05,916 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-7:null) Cleanup succeeded. Details null
2012-11-05 11:18:05,917 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1875513501: Received: { Ans: , MgmtId: 52240803170, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-11-05 11:18:05,917 DEBUG [cloud.vm.VirtualMachineManagerImpl] (StatsCollector-3:null) Cleanup succeeded. Details null
2012-11-05 11:18:05,935 DEBUG [agent.manage
The administrator has disabled public write access.

Re: Unable to launch VM using ISO 8 months 1 week ago #12988

  • chirauki
  • chirauki's Avatar
  • OFFLINE
  • Gold Boarder
  • Posts: 193
  • Thank you received: 19
  • Karma: 11
Hello,
2012-11-05 11:09:54,875 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-15) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [Pod:1] is unreachable: Unable to apply dhcp entry on router

It seems your virtual router is not available. Are you using redundant virtual routers? If so, check this out. If not, check if your virtual router is running and pingable.

You could try restarting networkc checking "clean up" option.

thx
The administrator has disabled public write access.
  • Page:
  • 1
Time to create page: 0.850 seconds
About BuildaCloud.org Resources Site Info

Build a Cloud.org is a resource for those users who want to build cloud computing software with both open source and proprietary software.