You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users-cn@cloudstack.apache.org by Lucien <li...@126.com> on 2013/06/20 04:38:47 UTC
hi,新建的vm不成功！
Hi,你好
我的系统虚拟机可以正常启动，就是新建的虚拟机启动不了！ 希望能得到你
的帮助，谢谢~
-
2013-06-20 17:01:46,555 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-5:null) Ping from 2
2013-06-20 17:01:49,820 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-2:null) Service SecurityGroup is not supported in the network
id=204
2013-06-20 17:01:58,636 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:01:58,809 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) HostStatsCollector is running...
2013-06-20 17:01:58,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:01:59,408 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 1-1689060600: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:01:59,717 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
(SnapshotPollTask:null) Snapshot scheduler.poll is being called at
2013-06-20 09:01:59 GMT
2013-06-20 17:01:59,718 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
(SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-06-20
09:01:59 GMT
2013-06-20 17:01:59,744 DEBUG
[cloud.network.ExternalLoadBalancerUsageManagerImpl]
(ExternalNetworkMonitor-1:null) External load balancer devices stats
collector is running...
2013-06-20 17:01:59,751 DEBUG
[cloud.network.ExternalLoadBalancerUsageManagerImpl]
(ExternalNetworkMonitor-1:null) Network 204 is not configured for external
networking, so skipping usage check.
2013-06-20 17:01:59,778 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-4:null) checking health of usage server
2013-06-20 17:01:59,780 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
(HA-4:null) usage server running? false, heartbeat: null
2013-06-20 17:01:59,781 DEBUG [cloud.alert.AlertManagerImpl] (HA-4:null)
Have already sent: 1 emails for alert type '12' -- skipping send email
2013-06-20 17:01:59,782 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null)
Found 0 running routers.
2013-06-20 17:01:59,785 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:02:00,005 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 2-1927415088: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:02:12,538 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-10:null) Ping from 1
2013-06-20 17:02:17,254 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2013-06-20 17:02:24,895 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-9:null) Ping from 4
2013-06-20 17:02:27,472 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2013-06-20 17:02:27,522 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 4-1147995178: Received: { Ans: , MgmtId:
119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:02:27,691 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 2-1927415089: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:02:28,636 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:02:28,879 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Running Capacity Checker ...
2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) recalculating system capacity
2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing cpu/ram capacity update
2013-06-20 17:02:29,720 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 1 VMs on host 1
2013-06-20 17:02:29,721 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 0 VM, not running on host 1
2013-06-20 17:02:29,723 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu:
500 reservedCpu: 0
2013-06-20 17:02:29,723 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem:
268435456 reservedMem: 0
2013-06-20 17:02:29,726 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 1 VMs on host 2
2013-06-20 17:02:29,727 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) Found 0 VM, not running on host 2
2013-06-20 17:02:29,728 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate cpu capacity, host:2 usedCpu:
500 reservedCpu: 0
2013-06-20 17:02:29,728 DEBUG [cloud.capacity.CapacityManagerImpl]
(CapacityChecker:null) No need to calibrate memory capacity, host:2 usedMem:
1073741824 reservedMem: 0
2013-06-20 17:02:29,728 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing cpu/ram capacity update
2013-06-20 17:02:29,728 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing storage capacity update
2013-06-20 17:02:29,785 DEBUG [cloud.storage.StorageManagerImpl]
(CapacityChecker:null) Successfully set Capacity - 211392921600 for capacity
type - 3 , DataCenterId - 1, HostOrPoolId - 200, PodId 1
2013-06-20 17:02:29,785 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing storage capacity update
2013-06-20 17:02:29,785 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for public ip and Vlans
2013-06-20 17:02:29,786 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:02:29,844 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done capacity updates for public ip and Vlans
2013-06-20 17:02:29,844 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing capacity updates for private ip
2013-06-20 17:02:29,849 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done executing capacity updates for private ip
2013-06-20 17:02:29,849 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done recalculating system capacity
2013-06-20 17:02:29,863 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Done running Capacity Checker ...
2013-06-20 17:02:32,616 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-15:null) THE WHERE CLAUSE IS:vm_instance.host_id = ?
2013-06-20 17:02:33,312 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) Ping from 5
2013-06-20 17:02:46,555 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) Ping from 2
2013-06-20 17:02:48,118 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-13:null) Access granted to Acct[2-admin] to Domain:1/ by
DomainChecker
2013-06-20 17:02:57,150 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-8:null) Access granted to Acct[2-admin] to Domain:1/ by
DomainChecker
2013-06-20 17:02:58,637 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:02:58,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:02:59,786 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:03:00,005 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) HostStatsCollector is running...
2013-06-20 17:03:00,600 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 1-1689060601: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:03:01,195 DEBUG [agent.transport.Request]
(StatsCollector-2:null) Seq 2-1927415090: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:03:12,540 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-12:null) Ping from 1
2013-06-20 17:03:17,259 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2013-06-20 17:03:19,187 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-25:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker
2013-06-20 17:03:19,187 DEBUG [cloud.configuration.ConfigurationManagerImpl]
(catalina-exec-25:null) Access granted to Acct[2-admin] to zone:1 by
DomainChecker
2013-06-20 17:03:19,189 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-25:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,244 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-25:null) Allocating in the DB for vm
2013-06-20 17:03:19,244 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-25:null) Allocating entries for VM: VM[User|test]
2013-06-20 17:03:19,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-25:null) Allocating nics for VM[User|test]
2013-06-20 17:03:19,248 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-25:null) Allocating nic for vm VM[User|test] in network
Ntwk[204|Guest|8] with requested profile NicProfile[0-0-null-null-null
2013-06-20 17:03:19,307 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-25:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,308 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-25:null) Allocaing disks for VM[User|test]
2013-06-20 17:03:19,316 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-25:null) Allocation completed for VM: VM[User|test]
2013-06-20 17:03:19,316 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-25:null) Successfully allocated DB entry for VM[User|test]
2013-06-20 17:03:19,434 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-25:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,436 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-25:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,599 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-25:null) submit async job-18, details: AsyncJobVO {id:18,
userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
instanceId: 7, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator: null,
cmdInfo:
{"sessionkey":"eWgve9o2rsvt/oWjMaSgqHnS0iQ\u003d","ctxUserId":"2","serviceOf
feringId":"48e02b1f-31fb-432f-91f8-8d1ec5916076","zoneId":"5878f7a5-21da-428
3-ba12-35a112f2000c","templateId":"01ae8322-425e-4c14-babb-8d1f53f79525","re
sponse":"json","id":"7","networkIds":"5df27e8c-f180-4c4e-a9e1-ffa6aa49ea17",
"hypervisor":"KVM","name":"test","diskOfferingId":"436e8bf3-d9bc-46cd-b8cf-7
85ae5335219","_":"1371690206027","ctxAccountId":"2","group":"news","ctxStart
EventId":"69","displayname":"test"}, cmdVersion: 0, callbackType: 0,
callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result:
null, initMsid: 119004504374952, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2013-06-20 17:03:19,600 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-18:job-18) Executing com.cloud.api.commands.DeployVMCmd for
job-18
2013-06-20 17:03:19,673 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,675 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:19,679 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Stopped to Starting with
event: StartRequestedvm's original host id: null new host id: null host id
before state transition: null
2013-06-20 17:03:19,680 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully transitioned to start state for
VM[User|test] reservation id = 66aab04e-8558-467d-84dd-f4ab73348ef5
2013-06-20 17:03:19,741 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-06-20 17:03:19,741 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Deploy avoids pods: null, clusters: null, hosts:
null
2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Trying to allocate a host and storage pools from
dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?: No
2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Searching all possible resources under this Zone: 1
2013-06-20 17:03:19,745 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU and RAM capacity under this
Zone: 1
2013-06-20 17:03:19,745 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) CPUOverprovisioningFactor considered: 1.0
2013-06-20 17:03:19,751 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
2013-06-20 17:03:19,751 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
2013-06-20 17:03:19,751 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2013-06-20 17:03:19,752 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
2013-06-20 17:03:19,754 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
2013-06-20 17:03:19,754 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for speed=1000Mhz,
Ram=1024
2013-06-20 17:03:19,756 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 2 has
enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
12804 and CPU after applying overprovisioning: 12804
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
Requested CPU: 1000
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 15521193984 ,
Requested RAM: 1073741824
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
RAM available
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 2, used: 500, reserved: 0, actual total: 12804, total with
overprovisioning: 12804; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 2, used: 1073741824, reserved: 0, total: 16594935808; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-20 17:03:19,757 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 2
2013-06-20 17:03:19,759 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 1 has
enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
12804 and CPU after applying overprovisioning: 12804
2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
Requested CPU: 1000
2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 16326500352 ,
Requested RAM: 1073741824
2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
RAM available
2013-06-20 17:03:19,761 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 500, reserved: 0, actual total: 12804, total with
overprovisioning: 12804; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-06-20 17:03:19,761 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 268435456, reserved: 0, total: 16594935808; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-20 17:03:19,761 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 1
2013-06-20 17:03:19,761 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning 2
suitable hosts
2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type): (10,
ROOT)
2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) We need to allocate new storagepool for this volume
2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Calling StoragePoolAllocators to find suitable
pools
2013-06-20 17:03:19,763 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
Looking for pools in dc: 1 pod:1 cluster:1
2013-06-20 17:03:19,763 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2013-06-20 17:03:19,763 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
Checking if storage pool is suitable, name: vm_primary ,poolId: 200
2013-06-20 17:03:19,764 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18) Is
localStorageAllocationNeeded? false
2013-06-20 17:03:19,764 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18) Is
storage pool shared? true
2013-06-20 17:03:19,765 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
threshold: 0.85
2013-06-20 17:03:19,770 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool: 200 for volume allocation
[Vol[10|vm=7|ROOT]], maxSize : 211392921600, totalAllocatedSize :
2495488000, askingSize : 8589934592, allocated disable threshold: 0.85
2013-06-20 17:03:19,770 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
FirstFitStoragePoolAllocator returning 1 suitable storage pools
2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type): (11,
DATADISK)
2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) We need to allocate new storagepool for this volume
2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Calling StoragePoolAllocators to find suitable
pools
2013-06-20 17:03:19,771 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
Looking for pools in dc: 1 pod:1 cluster:1
2013-06-20 17:03:19,772 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
FirstFitStoragePoolAllocator has 1 pools to check for allocation
2013-06-20 17:03:19,772 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
Checking if storage pool is suitable, name: vm_primary ,poolId: 200
2013-06-20 17:03:19,772 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18) Is
localStorageAllocationNeeded? false
2013-06-20 17:03:19,772 DEBUG
[storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18) Is
storage pool shared? true
2013-06-20 17:03:19,773 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
threshold: 0.85
2013-06-20 17:03:19,775 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool: 200 for volume allocation
[Vol[11|vm=7|DATADISK]], maxSize : 211392921600, totalAllocatedSize :
725950464, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-20 17:03:19,775 DEBUG
[storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
FirstFitStoragePoolAllocator returning 1 suitable storage pools
2013-06-20 17:03:19,775 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Trying to find a potenial host and associated
storage pools from the suitable host/pool lists for this VM
2013-06-20 17:03:19,775 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking if host: 2 can access any suitable storage
pool for volume: DATADISK
2013-06-20 17:03:19,776 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Host: 2 can access pool: 200
2013-06-20 17:03:19,776 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
threshold: 0.85
2013-06-20 17:03:19,778 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool: 200 for volume allocation
[Vol[11|vm=7|DATADISK]], maxSize : 211392921600, totalAllocatedSize :
725950464, askingSize : 21474836480, allocated disable threshold: 0.85
2013-06-20 17:03:19,778 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking if host: 2 can access any suitable storage
pool for volume: ROOT
2013-06-20 17:03:19,779 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Host: 2 can access pool: 200
2013-06-20 17:03:19,779 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
threshold: 0.85
2013-06-20 17:03:19,784 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking pool: 200 for volume allocation
[Vol[11|vm=7|DATADISK], Vol[10|vm=7|ROOT]], maxSize : 211392921600,
totalAllocatedSize : 2495488000, askingSize : 30064771072, allocated disable
threshold: 0.85
2013-06-20 17:03:19,784 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Found a potential host id: 2 name: node1.cloud.com
and associated storage pools for this VM
2013-06-20 17:03:19,785 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) 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(2)-Storage(Volume(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2013-06-20 17:03:19,785 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Deployment found - P0=VM[User|test],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
Id))] :
Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2013-06-20 17:03:19,865 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: null new host id: 2 host id
before state transition: null
2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
applying overprovisioning: 12804
2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) We are allocating VM, increasing the used capacity
of this host:2
2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Current Used CPU: 500 , Free CPU:12304 ,Requested
CPU: 1000
2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Current Used RAM: 1073741824 , Free RAM:15521193984
,Requested RAM: 1073741824
2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) CPU STATS after allocation: for host: 2, old used:
500, old reserved: 0, actual total: 12804, total with overprovisioning:
12804; new used:1500, reserved:0; requested cpu:1000,alloc_from_last:false
2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) RAM STATS after allocation: for host: 2, old used:
1073741824, old reserved: 0, total: 16594935808; new used: 2147483648,
reserved: 0; requested mem: 1073741824,alloc_from_last:false
2013-06-20 17:03:19,924 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) VM is being created in podId: 1
2013-06-20 17:03:19,926 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is acquired for network id 204 as a part of
network implement
2013-06-20 17:03:19,926 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalGuestNetworkGuru to implement
Ntwk[204|Guest|8]
2013-06-20 17:03:20,136 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to implemenet
Ntwk[204|Guest|8]
2013-06-20 17:03:20,138 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Lock is acquired for network id 204 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(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2013-06-20 17:03:20,141 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Lock is released for network id 204 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(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
Volume(11|DATADISK-->Pool(200))]
2013-06-20 17:03:20,141 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Starting router VM[DomainRouter|r-6-VM]
2013-06-20 17:03:20,144 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Stopped to Starting with
event: StartRequestedvm's original host id: null new host id: null host id
before state transition: null
2013-06-20 17:03:20,144 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully transitioned to start state for
VM[DomainRouter|r-6-VM] reservation id =
ee074068-816a-4022-ba18-61f62d24ae71
2013-06-20 17:03:20,216 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Trying to deploy VM, vm has dcId: 1 and podId: 1
2013-06-20 17:03:20,216 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Deploy avoids pods: null, clusters: null, hosts:
null
2013-06-20 17:03:20,219 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Root volume is ready, need to place VM in volume's
cluster
2013-06-20 17:03:20,219 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Vol[8|vm=6|ROOT] is READY, changing deployment plan
to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Trying to allocate a host and storage pools from
dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 134217728
2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?: Yes
2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Searching resources only under specified Cluster: 1
2013-06-20 17:03:20,225 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
2013-06-20 17:03:20,225 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
2013-06-20 17:03:20,225 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2013-06-20 17:03:20,226 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
hosts to check for allocation: [Host[-1-Routing], Host[-2-Routing]]
2013-06-20 17:03:20,228 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
2013-06-20 17:03:20,228 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=128
2013-06-20 17:03:20,229 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 1 has
enough capacity for requested CPU: 500 and requested RAM: 134217728 ,
cpuOverprovisioningFactor: 1.0
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
12804 and CPU after applying overprovisioning: 12804
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
Requested CPU: 500
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 16326500352 ,
Requested RAM: 134217728
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
RAM available
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 1, used: 500, reserved: 0, actual total: 12804, total with
overprovisioning: 12804; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 1, used: 268435456, reserved: 0, total: 16594935808; requested mem:
134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-20 17:03:20,231 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 1
2013-06-20 17:03:20,232 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 2 has
enough capacity for requested CPU: 500 and requested RAM: 134217728 ,
cpuOverprovisioningFactor: 1.0
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
12804 and CPU after applying overprovisioning: 12804
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 11304 ,
Requested CPU: 500
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 14447452160 ,
Requested RAM: 134217728
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
RAM available
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
host: 2, used: 1500, reserved: 0, actual total: 12804, total with
overprovisioning: 12804; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
host: 2, used: 2147483648, reserved: 0, total: 16594935808; requested mem:
134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
2013-06-20 17:03:20,234 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
adding to list: 2
2013-06-20 17:03:20,234 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning 2
suitable hosts
2013-06-20 17:03:20,240 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type):
(8,ROOT)
2013-06-20 17:03:20,240 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Volume is in READY state and has pool already
allocated, checking if pool can be reused, poolId: 200
2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Planner need not allocate a pool for this volume
since its READY
2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Trying to find a potenial host and associated
storage pools from the suitable host/pool lists for this VM
2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking if host: 1 can access any suitable storage
pool for volume: ROOT
2013-06-20 17:03:20,242 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Host: 1 can access pool: 200
2013-06-20 17:03:20,242 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Found a potential host id: 1 name: node1.cloud.com
and associated storage pools for this VM
2013-06-20 17:03:20,243 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) 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-06-20 17:03:20,243 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Deployment found - P0=VM[DomainRouter|r-6-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-06-20 17:03:20,331 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: null new host id: 1 host id
before state transition: null
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
applying overprovisioning: 12804
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) We are allocating VM, increasing the used capacity
of this host:1
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Current Used CPU: 500 , Free CPU:12304 ,Requested
CPU: 500
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Current Used RAM: 268435456 , Free RAM:16326500352
,Requested RAM: 134217728
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) CPU STATS after allocation: for host: 1, old used:
500, old reserved: 0, actual total: 12804, total with overprovisioning:
12804; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) RAM STATS after allocation: for host: 1, old used:
268435456, old reserved: 0, total: 16594935808; new used: 402653184,
reserved: 0; requested mem: 134217728,alloc_from_last:false
2013-06-20 17:03:20,406 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) VM is being created in podId: 1
2013-06-20 17:03:20,409 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is acquired for network id 200 as a part of
network implement
2013-06-20 17:03:20,409 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Network id=200 is already implemented
2013-06-20 17:03:20,410 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is released for network id 200 as a part of
network implement
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking JuniperSRX to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Netscaler to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking F5BigIP to prepare for Nic[13-6-null-10.168.
4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Ovs to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking BareMetal to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,477 WARN [network.element.VpcVirtualRouterElement]
(Job-Executor-18:job-18) Network Ntwk[200|Public|1] is not associated with
any VPC
2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking NiciraNvp to prepare for
Nic[13-6-null-10.168.4.122]
2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is acquired for network id 204 as a part of
network implement
2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Network id=204 is already implemented
2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is released for network id 204 as a part of
network implement
2013-06-20 17:03:20,536 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking JuniperSRX to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Netscaler to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking F5BigIP to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Ovs to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking BareMetal to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,651 WARN [network.element.VpcVirtualRouterElement]
(Job-Executor-18:job-18) Network Ntwk[204|Guest|8] is not associated with
any VPC
2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking NiciraNvp to prepare for
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:03:20,652 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:03:20,653 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is acquired for network id 202 as a part of
network implement
2013-06-20 17:03:20,654 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Network id=202 is already implemented
2013-06-20 17:03:20,654 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is released for network id 202 as a part of
network implement
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking JuniperSRX to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Netscaler to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking F5BigIP to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Ovs to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking BareMetal to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,836 WARN [network.element.VpcVirtualRouterElement]
(Job-Executor-18:job-18) Network Ntwk[202|Control|3] is not associated with
any VPC
2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking NiciraNvp to prepare for
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
2013-06-20 17:03:20,837 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) Checking if we need to prepare 1 volumes for
VM[DomainRouter|r-6-VM]
2013-06-20 17:03:20,837 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-18:job-18) No need to recreate the volume: Vol[8|vm=6|ROOT],
since it already has a pool assigned: 200, adding disk to VM
2013-06-20 17:03:20,844 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Boot Args for VM[DomainRouter|r-6-VM]: template=domP name=r-6-VM eth2ip=10.
168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254 eth0ip=10.1.1.1
eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
dns1=202.106.196.115 dns2=202.106.46.151
2013-06-20 17:03:20,934 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 1 ip(s) to apply as a part of domR VM[DomainRouter|r-6-VM] start.
2013-06-20 17:03:20,946 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Resending ipAssoc, port forwarding, load balancing rules as a part of
Virtual router start
2013-06-20 17:03:20,955 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 static nat(s) to apply as a part of domR VM[DomainRouter|r-6-VM]
start.
2013-06-20 17:03:20,955 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 firewall rule(s) to apply as a part of domR VM[DomainRouter|r-6-VM]
start.
2013-06-20 17:03:20,955 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 port forwarding rule(s) to apply as a part of domR
VM[DomainRouter|r-6-VM] start.
2013-06-20 17:03:20,955 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 static nat rule(s) to apply as a part of domR
VM[DomainRouter|r-6-VM] start.
2013-06-20 17:03:20,955 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 vpn(s) to apply as a part of domR VM[DomainRouter|r-6-VM] start.
2013-06-20 17:03:20,956 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Found 0 load balancing rule(s) to apply as a part of domR
VM[DomainRouter|r-6-VM] start.
2013-06-20 17:03:20,957 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Reapplying dhcp entries as a part of domR VM[DomainRouter|r-6-VM] start...
2013-06-20 17:03:20,959 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Reapplying vm data (userData and metaData) entries as a part of domR
VM[DomainRouter|r-6-VM] start...
2013-06-20 17:03:21,021 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060602: Sending { Cmd , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 100111,
[{"StartCommand":{"vm":{"id":6,"name":"r-6-VM","type":"DomainRouter","cpus":
1,"speed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"De
bian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-6-VM
eth2ip=10.168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254 eth0ip=10.1.
1.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
dns1=202.106.196.115
dns2=202.106.46.151","rebootOnCrash":false,"enableHA":true,"limitCpuUse":fal
se,"vncPassword":"42d9b2291d8e0084","params":{},"uuid":"b8d04faa-e563-4a00-a
706-a34c600c1326","disks":[{"id":8,"name":"ROOT-6","mountPoint":"/primary","
path":"3e015950-9ce7-4fe7-9783-cfaf6be94738","size":725811200,"type":"ROOT",
"storagePoolType":"NetworkFilesystem","storagePoolUuid":"b1f7df2b-d05e-3a37-
8103-c5c6be9880c6","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":20
0,"defaultNic":true,"uuid":"7c8daa7b-0bb6-47b3-a97e-f4c3ca848930","ip":"10.1
68.4.122","netmask":"255.255.255.0","gateway":"10.168.4.254","mac":"06:22:12
:00:00:13","dns1":"202.106.196.115","dns2":"202.106.46.151","broadcastType":
"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan
://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps"
:200,"defaultNic":false,"uuid":"6f9f396a-6f4f-4348-ac50-59d92390a5e2","ip":"
10.1.1.1","netmask":"255.255.255.0","mac":"02:00:44:6e:00:04","dns1":"202.10
6.196.115","dns2":"202.106.46.151","broadcastType":"Vlan","type":"Guest","br
oadcastUri":"vlan://170","isolationUri":"vlan://170","isSecurityGroupEnabled
":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"ddf4d
867-3e08-45dc-ba33-d8649920c85a","ip":"169.254.3.18","netmask":"255.255.0.0"
,"gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:12","broadcastType":"LinkLoca
l","type":"Control","isSecurityGroupEnabled":false}]},"wait":0}},{"check.Che
ckSshCommand":{"ip":"169.254.3.18","port":3922,"interval":6,"retries":100,"n
ame":"r-6-VM","wait":0}},{"GetDomRVersionCmd":{"accessDetails":{"router.ip":
"169.254.3.18","router.name":"r-6-VM"},"wait":0}},{},{"routing.IpAssocComman
d":{"ipAddresses":[{"accountId":2,"publicIp":"10.168.4.122","sourceNat":true
,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGate
way":"10.168.4.254","vlanNetmask":"255.255.255.0","vifMacAddress":"06:fb:96:
00:00:13","networkRate":200,"trafficType":"Public"}],"accessDetails":{"route
r.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.3
.18","router.name":"r-6-VM"},"wait":0}}] }
2013-06-20 17:03:24,895 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-7:null) Ping from 4
2013-06-20 17:03:27,691 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2013-06-20 17:03:27,744 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 4-1147995179: Received: { Ans: , MgmtId:
119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:03:27,920 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 2-1927415091: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:03:28,636 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:03:28,879 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:03:29,786 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:03:33,312 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-5:null) Ping from 5
2013-06-20 17:03:46,559 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-8:null) Ping from 2
2013-06-20 17:03:58,001 DEBUG [agent.transport.Request]
(AgentManager-Handler-6:null) Seq 1-1689060602: Processing: { Ans: ,
MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
[{"StartAnswer":{"vm":{"id":6,"name":"r-6-VM","type":"DomainRouter","cpus":1
,"speed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"Deb
ian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-6-VM
eth2ip=10.168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254 eth0ip=10.1.
1.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
dns1=202.106.196.115
dns2=202.106.46.151","rebootOnCrash":false,"enableHA":true,"limitCpuUse":fal
se,"vncPassword":"42d9b2291d8e0084","params":{},"uuid":"b8d04faa-e563-4a00-a
706-a34c600c1326","disks":[{"id":8,"name":"ROOT-6","mountPoint":"/primary","
path":"3e015950-9ce7-4fe7-9783-cfaf6be94738","size":725811200,"type":"ROOT",
"storagePoolType":"NetworkFilesystem","storagePoolUuid":"b1f7df2b-d05e-3a37-
8103-c5c6be9880c6","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":20
0,"defaultNic":true,"uuid":"7c8daa7b-0bb6-47b3-a97e-f4c3ca848930","ip":"10.1
68.4.122","netmask":"255.255.255.0","gateway":"10.168.4.254","mac":"06:22:12
:00:00:13","dns1":"202.106.196.115","dns2":"202.106.46.151","broadcastType":
"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan
://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps"
:200,"defaultNic":false,"uuid":"6f9f396a-6f4f-4348-ac50-59d92390a5e2","ip":"
10.1.1.1","netmask":"255.255.255.0","mac":"02:00:44:6e:00:04","dns1":"202.10
6.196.115","dns2":"202.106.46.151","broadcastType":"Vlan","type":"Guest","br
oadcastUri":"vlan://170","isolationUri":"vlan://170","isSecurityGroupEnabled
":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"ddf4d
867-3e08-45dc-ba33-d8649920c85a","ip":"169.254.3.18","netmask":"255.255.0.0"
,"gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:12","broadcastType":"LinkLoca
l","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0
}},{"check.CheckSshAnswer":{"result":true,"wait":0}},{"GetDomRVersionAnswer"
:{"result":false,"details":"GetDomRVersionCmd
failed","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous
failure","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous
failure","wait":0}}] }
2013-06-20 17:03:58,001 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-6:null) Seq 1-1689060602: No more commands found
2013-06-20 17:03:58,001 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060602: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer,
GetDomRVersionAnswer, Answer, Answer } }
2013-06-20 17:03:58,062 WARN
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Unable to get the template/scripts version of router r-6-VM due to:
GetDomRVersionCmd failed
2013-06-20 17:03:58,062 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) The guru did not like the answers so stopping
VM[DomainRouter|r-6-VM]
2013-06-20 17:03:58,064 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060603: Sending { Cmd , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"r-6-VM","wait":0}}] }
2013-06-20 17:03:58,636 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:03:58,877 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:03:59,786 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:04:01,195 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) HostStatsCollector is running...
2013-06-20 17:04:01,759 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 1-1689060604: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:04:02,189 DEBUG [agent.transport.Request]
(AgentManager-Handler-9:null) Seq 1-1689060603: Processing: { Ans: ,
MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
[{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-06-20 17:04:02,189 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-9:null) Seq 1-1689060603: No more commands found
2013-06-20 17:04:02,189 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060603: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-20 17:04:02,189 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Failed to start instance VM[DomainRouter|r-6-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
l.java:814)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
472)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNet
workApplianceManagerImpl.java:2352)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRout
er(VirtualNetworkApplianceManagerImpl.java:1597)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(Vir
tualNetworkApplianceManagerImpl.java:1697)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRou
terInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
at
com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElemen
t.java:172)
at
com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(Ne
tworkManagerImpl.java:2033)
at
com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.jav
a:1965)
at
com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.
java:2110)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
l.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
472)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:29
29)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:26
01)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:25
89)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
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:11
10)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
03)
at java.lang.Thread.run(Thread.java:679)
2013-06-20 17:04:02,250 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Cleaning up resources for the vm
VM[DomainRouter|r-6-VM] in Starting state
2013-06-20 17:04:02,252 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060605: Sending { Cmd , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"r-6-VM","wait":0}}] }
2013-06-20 17:04:02,355 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 2-1927415092: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2013-06-20 17:04:02,356 DEBUG [agent.transport.Request]
(AgentManager-Handler-2:null) Seq 1-1689060605: Processing: { Ans: ,
MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
[{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-06-20 17:04:02,356 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-2:null) Seq 1-1689060605: No more commands found
2013-06-20 17:04:02,356 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 1-1689060605: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-20 17:04:02,360 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Successfully updated user statistics as a part of domR
VM[DomainRouter|r-6-VM] reboot/stop
2013-06-20 17:04:02,459 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking JuniperSRX to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Netscaler to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking F5BigIP to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Ovs to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalDhcpServer to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking BareMetal to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking SecurityGroupProvider to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VpcVirtualRouter to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking NiciraNvp to release
Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
2013-06-20 17:04:02,679 DEBUG [network.guru.ControlNetworkGuru]
(Job-Executor-18:job-18) Released nic: NicProfile[12-6-null-null-null
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking JuniperSRX to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Netscaler to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking F5BigIP to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VirtualRouter to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking Ovs to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking ExternalDhcpServer to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking BareMetal to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking SecurityGroupProvider to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking VpcVirtualRouter to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Asking NiciraNvp to release
Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
2013-06-20 17:04:02,779 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully released network resources for the vm
VM[DomainRouter|r-6-VM]
2013-06-20 17:04:02,779 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully cleanued up resources for the vm
VM[DomainRouter|r-6-VM] in Starting state
2013-06-20 17:04:02,882 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 1
2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
applying overprovisioning: 12804
2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) release cpu from host: 1, old used: 1000,reserved:
0, actual total: 12804, total with overprovisioning: 12804; new used:
500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) release mem from host: 1, old used:
402653184,reserved: 0, total: 16594935808; new used: 268435456,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-06-20 17:04:02,939 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Cleaning up because we're unable to implement the
network Ntwk[204|Guest|8]
2013-06-20 17:04:03,015 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Releasing 0 port forwarding rules for network
id=204 as a part of shutdownNetworkRules
2013-06-20 17:04:03,015 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) There are no rules to forward to the network
elements
2013-06-20 17:04:03,016 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Releasing 0 static nat rules for network id=204 as
a part of shutdownNetworkRules
2013-06-20 17:04:03,016 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) There are no rules to forward to the network
elements
2013-06-20 17:04:03,017 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) There are no rules to forward to the network
elements
2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Releasing 0 firewall rules for network id=204 as a
part of shutdownNetworkRules
2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) There are no rules to forward to the network
elements
2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Releasing 0 Network ACLs for network id=204 as a
part of shutdownNetworkRules
2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) There are no rules to forward to the network
elements
2013-06-20 17:04:03,019 DEBUG [network.rules.RulesManagerImpl]
(Job-Executor-18:job-18) Found 0 static nat rules to apply for network id
204
2013-06-20 17:04:03,028 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Router r-6-VM is in Stopped, so not sending apply ip association commands to
the backend
2013-06-20 17:04:03,030 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Sending network shutdown to VirtualRouter
2013-06-20 17:04:03,031 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-18:job-18)
Stopping router VM[DomainRouter|r-6-VM]
2013-06-20 17:04:03,032 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) VM is already stopped: VM[DomainRouter|r-6-VM]
2013-06-20 17:04:03,033 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Network id=204 is shutdown successfully, cleaning
up corresponding resources now.
2013-06-20 17:04:03,034 DEBUG [network.guru.GuestNetworkGuru]
(Job-Executor-18:job-18) Releasing vnet for the network id=204
2013-06-20 17:04:03,090 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-18:job-18) Lock is released for network id 204 as a part of
network implement
2013-06-20 17:04:03,090 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Unable to contact resource.
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to Unable to start
VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
l.java:847)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
472)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNet
workApplianceManagerImpl.java:2352)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRout
er(VirtualNetworkApplianceManagerImpl.java:1597)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(Vir
tualNetworkApplianceManagerImpl.java:1697)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRou
terInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
at
com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElemen
t.java:172)
at
com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(Ne
tworkManagerImpl.java:2033)
at
com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.jav
a:1965)
at
com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34)
at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.
java:2110)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
l.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
472)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:29
29)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:26
01)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:25
89)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
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:11
10)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
03)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
l.java:814)
... 33 more
2013-06-20 17:04:03,139 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Cleaning up resources for the vm VM[User|test] in
Starting state
2013-06-20 17:04:03,140 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 2-1927415093: Sending { Cmd , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"i-2-7-VM","wait":0}}] }
2013-06-20 17:04:03,245 DEBUG [agent.transport.Request]
(AgentManager-Handler-13:null) Seq 2-1927415093: Processing: { Ans: ,
MgmtId: 119004504374952, via: 2, Ver: v1, Flags: 110,
[{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-06-20 17:04:03,245 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-13:null) Seq 2-1927415093: No more commands found
2013-06-20 17:04:03,245 DEBUG [agent.transport.Request]
(Job-Executor-18:job-18) Seq 2-1927415093: Received: { Ans: , MgmtId:
119004504374952, via: 2, Ver: v1, Flags: 110, { StopAnswer } }
2013-06-20 17:04:03,249 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully released network resources for the vm
VM[User|test]
2013-06-20 17:04:03,249 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-18:job-18) Successfully cleanued up resources for the vm
VM[User|test] in Starting state
2013-06-20 17:04:03,250 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Trying to allocate a host and storage pools from
dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?: No
2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Searching all possible resources under this Zone: 1
2013-06-20 17:04:03,252 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Listing clusters in order of aggregate capacity,
that have (atleast one host with) enough CPU and RAM capacity under this
Zone: 1
2013-06-20 17:04:03,253 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) CPUOverprovisioningFactor considered: 1.0
2013-06-20 17:04:03,258 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
2013-06-20 17:04:03,258 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
2013-06-20 17:04:03,258 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2013-06-20 17:04:03,259 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
hosts to check for allocation: [Host[-1-Routing], Host[-2-Routing]]
2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for speed=1000Mhz,
Ram=1024
2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host name:
node1.cloud.com, hostId: 1 is in avoid set, skipping this and trying other
available hosts
2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host name:
node1.cloud.com, hostId: 2 is in avoid set, skipping this and trying other
available hosts
2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning 0
suitable hosts
2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) No suitable hosts found
2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) No suitable hosts found under this Cluster: 1
2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-18:job-18) Could not find suitable Deployment Destination for
this VM under any clusters, returning.
2013-06-20 17:04:03,397 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 2
2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
applying overprovisioning: 12804
2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) release cpu from host: 2, old used: 1500,reserved:
0, actual total: 12804, total with overprovisioning: 12804; new used:
500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) release mem from host: 2, old used:
2147483648,reserved: 0, total: 16594935808; new used: 1073741824,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-06-20 17:04:03,458 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-18:job-18) Destroying vm VM[User|test] as it failed to create
2013-06-20 17:04:03,581 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-18:job-18) 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
2013-06-20 17:04:04,198 INFO [api.commands.DeployVMCmd]
(Job-Executor-18:job-18)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|test]Scope=interface com.cloud.dc.DataCenter; id=1
2013-06-20 17:04:04,199 WARN [cloud.api.ApiDispatcher]
(Job-Executor-18:job-18) class com.cloud.api.ServerApiException : Unable to
create a deployment for VM[User|test]
2013-06-20 17:04:04,199 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-18:job-18) Complete async job-18, jobStatus: 2, resultCode:
530, result: Error Code: 533 Error text: Unable to create a deployment for
VM[User|test]
2013-06-20 17:04:04,646 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-11:null) Async job-18 completed
2013-06-20 17:04:04,663 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-4:null) THE WHERE CLAUSE IS:user_vm.id = ?
2013-06-20 17:04:12,539 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-3:null) Ping from 1
2013-06-20 17:04:16,809 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-14:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:04:17,264 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) VmStatsCollector is running...
2013-06-20 17:04:17,545 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-2:null) Service SecurityGroup is not supported in the network
id=204
2013-06-20 17:04:17,993 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-16:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:04:19,138 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-21:null) Service SecurityGroup is not supported in the
network id=204
2013-06-20 17:04:20,282 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-3:null) Service SecurityGroup is not supported in the network
id=204
2013-06-20 17:04:24,895 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-1:null) Ping from 4
2013-06-20 17:04:27,920 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) StorageCollector is running...
2013-06-20 17:04:27,975 DEBUG [agent.transport.Request]
(StatsCollector-3:null) Seq 4-1147995180: Received: { Ans: , MgmtId:
119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:04:28,040 DEBUG [agent.transport.Request]
(StatsCollector-3:null) Seq 1-1689060606: Received: { Ans: , MgmtId:
119004504374952, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-06-20 17:04:28,636 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2013-06-20 17:04:28,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-06-20 17:04:29,786 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2013-06-20 17:04:33,313 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-7:null) Ping from 5
Re: hi,新建的vm不成功！
Posted by 张氓 <15...@gmail.com>.
No suitable hosts found
应该是管理节点和计算节点连接不正常，建议你重新连接计算host，然后重新启动两个系统VM
2013/6/20 Lucien <li...@126.com>
> Hi,你好
>
>
>
> 我的系统虚拟机可以正常启动，就是新建的虚拟机启动不了！ 希望能得到你
> 的帮助，谢谢~
>
>
>
> -
>
> 2013-06-20 17:01:46,555 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-5:null) Ping from 2
>
> 2013-06-20 17:01:49,820 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-2:null) Service SecurityGroup is not supported in the
> network
> id=204
>
> 2013-06-20 17:01:58,636 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:01:58,809 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) HostStatsCollector is running...
>
> 2013-06-20 17:01:58,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:01:59,408 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 1-1689060600: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:01:59,717 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
> (SnapshotPollTask:null) Snapshot scheduler.poll is being called at
> 2013-06-20 09:01:59 GMT
>
> 2013-06-20 17:01:59,718 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
> (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-06-20
> 09:01:59 GMT
>
> 2013-06-20 17:01:59,744 DEBUG
> [cloud.network.ExternalLoadBalancerUsageManagerImpl]
> (ExternalNetworkMonitor-1:null) External load balancer devices stats
> collector is running...
>
> 2013-06-20 17:01:59,751 DEBUG
> [cloud.network.ExternalLoadBalancerUsageManagerImpl]
> (ExternalNetworkMonitor-1:null) Network 204 is not configured for external
> networking, so skipping usage check.
>
> 2013-06-20 17:01:59,778 INFO [cloud.ha.HighAvailabilityManagerImpl]
> (HA-4:null) checking health of usage server
>
> 2013-06-20 17:01:59,780 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
> (HA-4:null) usage server running? false, heartbeat: null
>
> 2013-06-20 17:01:59,781 DEBUG [cloud.alert.AlertManagerImpl] (HA-4:null)
> Have already sent: 1 emails for alert type '12' -- skipping send email
>
> 2013-06-20 17:01:59,782 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null)
> Found 0 running routers.
>
> 2013-06-20 17:01:59,785 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:02:00,005 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 2-1927415088: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:02:12,538 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-10:null) Ping from 1
>
> 2013-06-20 17:02:17,254 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) VmStatsCollector is running...
>
> 2013-06-20 17:02:24,895 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-9:null) Ping from 4
>
> 2013-06-20 17:02:27,472 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) StorageCollector is running...
>
> 2013-06-20 17:02:27,522 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 4-1147995178: Received: { Ans: , MgmtId:
> 119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:02:27,691 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 2-1927415089: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:02:28,636 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:02:28,879 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Running Capacity Checker ...
>
> 2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) recalculating system capacity
>
> 2013-06-20 17:02:29,714 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Executing cpu/ram capacity update
>
> 2013-06-20 17:02:29,720 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) Found 1 VMs on host 1
>
> 2013-06-20 17:02:29,721 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) Found 0 VM, not running on host 1
>
> 2013-06-20 17:02:29,723 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu:
> 500 reservedCpu: 0
>
> 2013-06-20 17:02:29,723 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) No need to calibrate memory capacity, host:1
> usedMem:
> 268435456 reservedMem: 0
>
> 2013-06-20 17:02:29,726 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) Found 1 VMs on host 2
>
> 2013-06-20 17:02:29,727 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) Found 0 VM, not running on host 2
>
> 2013-06-20 17:02:29,728 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) No need to calibrate cpu capacity, host:2 usedCpu:
> 500 reservedCpu: 0
>
> 2013-06-20 17:02:29,728 DEBUG [cloud.capacity.CapacityManagerImpl]
> (CapacityChecker:null) No need to calibrate memory capacity, host:2
> usedMem:
> 1073741824 reservedMem: 0
>
> 2013-06-20 17:02:29,728 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done executing cpu/ram capacity update
>
> 2013-06-20 17:02:29,728 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Executing storage capacity update
>
> 2013-06-20 17:02:29,785 DEBUG [cloud.storage.StorageManagerImpl]
> (CapacityChecker:null) Successfully set Capacity - 211392921600 for
> capacity
> type - 3 , DataCenterId - 1, HostOrPoolId - 200, PodId 1
>
> 2013-06-20 17:02:29,785 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done executing storage capacity update
>
> 2013-06-20 17:02:29,785 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Executing capacity updates for public ip and Vlans
>
> 2013-06-20 17:02:29,786 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:02:29,844 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done capacity updates for public ip and Vlans
>
> 2013-06-20 17:02:29,844 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Executing capacity updates for private ip
>
> 2013-06-20 17:02:29,849 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done executing capacity updates for private ip
>
> 2013-06-20 17:02:29,849 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done recalculating system capacity
>
> 2013-06-20 17:02:29,863 DEBUG [cloud.alert.AlertManagerImpl]
> (CapacityChecker:null) Done running Capacity Checker ...
>
> 2013-06-20 17:02:32,616 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-15:null) THE WHERE CLAUSE IS:vm_instance.host_id = ?
>
> 2013-06-20 17:02:33,312 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-13:null) Ping from 5
>
> 2013-06-20 17:02:46,555 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-3:null) Ping from 2
>
> 2013-06-20 17:02:48,118 DEBUG [cloud.user.AccountManagerImpl]
> (catalina-exec-13:null) Access granted to Acct[2-admin] to Domain:1/ by
> DomainChecker
>
> 2013-06-20 17:02:57,150 DEBUG [cloud.user.AccountManagerImpl]
> (catalina-exec-8:null) Access granted to Acct[2-admin] to Domain:1/ by
> DomainChecker
>
> 2013-06-20 17:02:58,637 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:02:58,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:02:59,786 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:03:00,005 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) HostStatsCollector is running...
>
> 2013-06-20 17:03:00,600 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 1-1689060601: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:03:01,195 DEBUG [agent.transport.Request]
> (StatsCollector-2:null) Seq 2-1927415090: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:03:12,540 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-12:null) Ping from 1
>
> 2013-06-20 17:03:17,259 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-2:null) VmStatsCollector is running...
>
> 2013-06-20 17:03:19,187 DEBUG
> [cloud.configuration.ConfigurationManagerImpl]
> (catalina-exec-25:null) Access granted to Acct[2-admin] to zone:1 by
> DomainChecker
>
> 2013-06-20 17:03:19,187 DEBUG
> [cloud.configuration.ConfigurationManagerImpl]
> (catalina-exec-25:null) Access granted to Acct[2-admin] to zone:1 by
> DomainChecker
>
> 2013-06-20 17:03:19,189 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-25:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,244 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-25:null) Allocating in the DB for vm
>
> 2013-06-20 17:03:19,244 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-25:null) Allocating entries for VM: VM[User|test]
>
> 2013-06-20 17:03:19,247 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-25:null) Allocating nics for VM[User|test]
>
> 2013-06-20 17:03:19,248 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-25:null) Allocating nic for vm VM[User|test] in network
> Ntwk[204|Guest|8] with requested profile NicProfile[0-0-null-null-null
>
> 2013-06-20 17:03:19,307 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-25:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,308 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-25:null) Allocaing disks for VM[User|test]
>
> 2013-06-20 17:03:19,316 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (catalina-exec-25:null) Allocation completed for VM: VM[User|test]
>
> 2013-06-20 17:03:19,316 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-25:null) Successfully allocated DB entry for VM[User|test]
>
> 2013-06-20 17:03:19,434 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-25:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,436 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-25:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,599 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-25:null) submit async job-18, details: AsyncJobVO {id:18,
> userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine,
> instanceId: 7, cmd: com.cloud.api.commands.DeployVMCmd, cmdOriginator:
> null,
> cmdInfo:
>
> {"sessionkey":"eWgve9o2rsvt/oWjMaSgqHnS0iQ\u003d","ctxUserId":"2","serviceOf
>
> feringId":"48e02b1f-31fb-432f-91f8-8d1ec5916076","zoneId":"5878f7a5-21da-428
>
> 3-ba12-35a112f2000c","templateId":"01ae8322-425e-4c14-babb-8d1f53f79525","re
>
> sponse":"json","id":"7","networkIds":"5df27e8c-f180-4c4e-a9e1-ffa6aa49ea17",
>
> "hypervisor":"KVM","name":"test","diskOfferingId":"436e8bf3-d9bc-46cd-b8cf-7
>
> 85ae5335219","_":"1371690206027","ctxAccountId":"2","group":"news","ctxStart
> EventId":"69","displayname":"test"}, cmdVersion: 0, callbackType: 0,
> callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result:
> null, initMsid: 119004504374952, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: null}
>
> 2013-06-20 17:03:19,600 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-18:job-18) Executing com.cloud.api.commands.DeployVMCmd for
> job-18
>
> 2013-06-20 17:03:19,673 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,675 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:19,679 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Stopped to Starting with
> event: StartRequestedvm's original host id: null new host id: null host id
> before state transition: null
>
> 2013-06-20 17:03:19,680 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully transitioned to start state for
> VM[User|test] reservation id = 66aab04e-8558-467d-84dd-f4ab73348ef5
>
> 2013-06-20 17:03:19,741 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Trying to deploy VM, vm has dcId: 1 and podId:
> null
>
> 2013-06-20 17:03:19,741 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Deploy avoids pods: null, clusters: null, hosts:
> null
>
> 2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
>
> 2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Trying to allocate a host and storage pools from
> dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
>
> 2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?: No
>
> 2013-06-20 17:03:19,743 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Searching all possible resources under this Zone:
> 1
>
> 2013-06-20 17:03:19,745 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Listing clusters in order of aggregate capacity,
> that have (atleast one host with) enough CPU and RAM capacity under this
> Zone: 1
>
> 2013-06-20 17:03:19,745 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) CPUOverprovisioningFactor considered: 1.0
>
> 2013-06-20 17:03:19,751 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
>
> 2013-06-20 17:03:19,751 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
>
> 2013-06-20 17:03:19,751 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc:
> 1
> pod:1 cluster:1
>
> 2013-06-20 17:03:19,752 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
> hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]]
>
> 2013-06-20 17:03:19,754 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
> allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]]
>
> 2013-06-20 17:03:19,754 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz,
> Ram=1024
>
> 2013-06-20 17:03:19,756 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 2 has
> enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 12804 and CPU after applying overprovisioning: 12804
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
> Requested CPU: 1000
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 15521193984 ,
> Requested RAM: 1073741824
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 2, used: 500, reserved: 0, actual total: 12804, total with
> overprovisioning: 12804; requested cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:19,757 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 2, used: 1073741824, reserved: 0, total: 16594935808; requested mem:
> 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:19,757 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 2
>
> 2013-06-20 17:03:19,759 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 1 has
> enough capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
> cpuOverprovisioningFactor: 1.0
>
> 2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 12804 and CPU after applying overprovisioning: 12804
>
> 2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
> Requested CPU: 1000
>
> 2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 16326500352 ,
> Requested RAM: 1073741824
>
> 2013-06-20 17:03:19,760 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
>
> 2013-06-20 17:03:19,761 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 1, used: 500, reserved: 0, actual total: 12804, total with
> overprovisioning: 12804; requested cpu:1000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:19,761 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 1, used: 268435456, reserved: 0, total: 16594935808; requested mem:
> 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:19,761 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 1
>
> 2013-06-20 17:03:19,761 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning
> 2
> suitable hosts
>
> 2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type):
> (10,
> ROOT)
>
> 2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) We need to allocate new storagepool for this
> volume
>
> 2013-06-20 17:03:19,762 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Calling StoragePoolAllocators to find suitable
> pools
>
> 2013-06-20 17:03:19,763 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> Looking for pools in dc: 1 pod:1 cluster:1
>
> 2013-06-20 17:03:19,763 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> FirstFitStoragePoolAllocator has 1 pools to check for allocation
>
> 2013-06-20 17:03:19,763 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Checking if storage pool is suitable, name: vm_primary ,poolId: 200
>
> 2013-06-20 17:03:19,764 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Is
> localStorageAllocationNeeded? false
>
> 2013-06-20 17:03:19,764 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Is
> storage pool shared? true
>
> 2013-06-20 17:03:19,765 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
> 105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
> threshold: 0.85
>
> 2013-06-20 17:03:19,770 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool: 200 for volume allocation
> [Vol[10|vm=7|ROOT]], maxSize : 211392921600, totalAllocatedSize :
> 2495488000, askingSize : 8589934592, allocated disable threshold: 0.85
>
> 2013-06-20 17:03:19,770 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> FirstFitStoragePoolAllocator returning 1 suitable storage pools
>
> 2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type):
> (11,
> DATADISK)
>
> 2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) We need to allocate new storagepool for this
> volume
>
> 2013-06-20 17:03:19,770 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Calling StoragePoolAllocators to find suitable
> pools
>
> 2013-06-20 17:03:19,771 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> Looking for pools in dc: 1 pod:1 cluster:1
>
> 2013-06-20 17:03:19,772 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> FirstFitStoragePoolAllocator has 1 pools to check for allocation
>
> 2013-06-20 17:03:19,772 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Checking if storage pool is suitable, name: vm_primary ,poolId: 200
>
> 2013-06-20 17:03:19,772 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Is
> localStorageAllocationNeeded? false
>
> 2013-06-20 17:03:19,772 DEBUG
> [storage.allocator.AbstractStoragePoolAllocator] (Job-Executor-18:job-18)
> Is
> storage pool shared? true
>
> 2013-06-20 17:03:19,773 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
> 105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
> threshold: 0.85
>
> 2013-06-20 17:03:19,775 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool: 200 for volume allocation
> [Vol[11|vm=7|DATADISK]], maxSize : 211392921600, totalAllocatedSize :
> 725950464, askingSize : 21474836480, allocated disable threshold: 0.85
>
> 2013-06-20 17:03:19,775 DEBUG
> [storage.allocator.FirstFitStoragePoolAllocator] (Job-Executor-18:job-18)
> FirstFitStoragePoolAllocator returning 1 suitable storage pools
>
> 2013-06-20 17:03:19,775 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
>
> 2013-06-20 17:03:19,775 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking if host: 2 can access any suitable
> storage
> pool for volume: DATADISK
>
> 2013-06-20 17:03:19,776 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Host: 2 can access pool: 200
>
> 2013-06-20 17:03:19,776 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
> 105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
> threshold: 0.85
>
> 2013-06-20 17:03:19,778 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool: 200 for volume allocation
> [Vol[11|vm=7|DATADISK]], maxSize : 211392921600, totalAllocatedSize :
> 725950464, askingSize : 21474836480, allocated disable threshold: 0.85
>
> 2013-06-20 17:03:19,778 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking if host: 2 can access any suitable
> storage
> pool for volume: ROOT
>
> 2013-06-20 17:03:19,779 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Host: 2 can access pool: 200
>
> 2013-06-20 17:03:19,779 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool 200 for storage, totalSize:
> 105696460800, usedBytes: 11425284096, usedPct: 0.10809523809523809, disable
> threshold: 0.85
>
> 2013-06-20 17:03:19,784 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking pool: 200 for volume allocation
> [Vol[11|vm=7|DATADISK], Vol[10|vm=7|ROOT]], maxSize : 211392921600,
> totalAllocatedSize : 2495488000, askingSize : 30064771072, allocated
> disable
> threshold: 0.85
>
> 2013-06-20 17:03:19,784 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Found a potential host id: 2 name:
> node1.cloud.com
> and associated storage pools for this VM
>
> 2013-06-20 17:03:19,785 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) 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(2)-Storage(Volume(10|ROOT-->Pool(200),
> Volume(11|DATADISK-->Pool(200))]
>
> 2013-06-20 17:03:19,785 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Deployment found - P0=VM[User|test],
>
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
> Id))] :
> Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
> Volume(11|DATADISK-->Pool(200))]
>
> 2013-06-20 17:03:19,865 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Starting to Starting
> with
> event: OperationRetryvm's original host id: null new host id: 2 host id
> before state transition: null
>
> 2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
> applying overprovisioning: 12804
>
> 2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) We are allocating VM, increasing the used capacity
> of this host:2
>
> 2013-06-20 17:03:19,870 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Current Used CPU: 500 , Free CPU:12304 ,Requested
> CPU: 1000
>
> 2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Current Used RAM: 1073741824 , Free
> RAM:15521193984
> ,Requested RAM: 1073741824
>
> 2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) CPU STATS after allocation: for host: 2, old used:
> 500, old reserved: 0, actual total: 12804, total with overprovisioning:
> 12804; new used:1500, reserved:0; requested cpu:1000,alloc_from_last:false
>
> 2013-06-20 17:03:19,871 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) RAM STATS after allocation: for host: 2, old used:
> 1073741824, old reserved: 0, total: 16594935808; new used: 2147483648,
> reserved: 0; requested mem: 1073741824,alloc_from_last:false
>
> 2013-06-20 17:03:19,924 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) VM is being created in podId: 1
>
> 2013-06-20 17:03:19,926 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is acquired for network id 204 as a part of
> network implement
>
> 2013-06-20 17:03:19,926 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalGuestNetworkGuru to implement
> Ntwk[204|Guest|8]
>
> 2013-06-20 17:03:20,136 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to implemenet
> Ntwk[204|Guest|8]
>
> 2013-06-20 17:03:20,138 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Lock is acquired for network id 204 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(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
> Volume(11|DATADISK-->Pool(200))]
>
> 2013-06-20 17:03:20,141 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Lock is released for network id 204 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(1)-Host(2)-Storage(Volume(10|ROOT-->Pool(200),
> Volume(11|DATADISK-->Pool(200))]
>
> 2013-06-20 17:03:20,141 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Starting router VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:03:20,144 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Stopped to Starting with
> event: StartRequestedvm's original host id: null new host id: null host id
> before state transition: null
>
> 2013-06-20 17:03:20,144 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully transitioned to start state for
> VM[DomainRouter|r-6-VM] reservation id =
> ee074068-816a-4022-ba18-61f62d24ae71
>
> 2013-06-20 17:03:20,216 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Trying to deploy VM, vm has dcId: 1 and podId: 1
>
> 2013-06-20 17:03:20,216 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Deploy avoids pods: null, clusters: null, hosts:
> null
>
> 2013-06-20 17:03:20,219 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Root volume is ready, need to place VM in volume's
> cluster
>
> 2013-06-20 17:03:20,219 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Vol[8|vm=6|ROOT] is READY, changing deployment
> plan
> to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
>
> 2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
>
> 2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Trying to allocate a host and storage pools from
> dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 134217728
>
> 2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?:
> Yes
>
> 2013-06-20 17:03:20,220 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Searching resources only under specified Cluster:
> 1
>
> 2013-06-20 17:03:20,225 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
>
> 2013-06-20 17:03:20,225 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
>
> 2013-06-20 17:03:20,225 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc:
> 1
> pod:1 cluster:1
>
> 2013-06-20 17:03:20,226 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
> hosts to check for allocation: [Host[-1-Routing], Host[-2-Routing]]
>
> 2013-06-20 17:03:20,228 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
> allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
>
> 2013-06-20 17:03:20,228 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for speed=500Mhz,
> Ram=128
>
> 2013-06-20 17:03:20,229 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 1 has
> enough capacity for requested CPU: 500 and requested RAM: 134217728 ,
> cpuOverprovisioningFactor: 1.0
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 12804 and CPU after applying overprovisioning: 12804
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 12304 ,
> Requested CPU: 500
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 16326500352 ,
> Requested RAM: 134217728
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 1, used: 500, reserved: 0, actual total: 12804, total with
> overprovisioning: 12804; requested cpu:500,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:20,231 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 1, used: 268435456, reserved: 0, total: 16594935808; requested mem:
> 134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:20,231 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 1
>
> 2013-06-20 17:03:20,232 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Checking if host: 2 has
> enough capacity for requested CPU: 500 and requested RAM: 134217728 ,
> cpuOverprovisioningFactor: 1.0
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 12804 and CPU after applying overprovisioning: 12804
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free CPU: 11304 ,
> Requested CPU: 500
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Free RAM: 14447452160 ,
> Requested RAM: 134217728
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 2, used: 1500, reserved: 0, actual total: 12804, total with
> overprovisioning: 12804; requested cpu:500,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:20,234 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 2, used: 2147483648, reserved: 0, total: 16594935808; requested mem:
> 134217728,alloc_from_last_host?:false ,considerReservedCapacity?: true
>
> 2013-06-20 17:03:20,234 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 2
>
> 2013-06-20 17:03:20,234 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning
> 2
> suitable hosts
>
> 2013-06-20 17:03:20,240 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking suitable pools for volume (Id, Type):
> (8,ROOT)
>
> 2013-06-20 17:03:20,240 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Volume is in READY state and has pool already
> allocated, checking if pool can be reused, poolId: 200
>
> 2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Planner need not allocate a pool for this volume
> since its READY
>
> 2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
>
> 2013-06-20 17:03:20,241 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking if host: 1 can access any suitable
> storage
> pool for volume: ROOT
>
> 2013-06-20 17:03:20,242 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Host: 1 can access pool: 200
>
> 2013-06-20 17:03:20,242 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Found a potential host id: 1 name:
> node1.cloud.com
> and associated storage pools for this VM
>
> 2013-06-20 17:03:20,243 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) 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-06-20 17:03:20,243 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Deployment found - P0=VM[DomainRouter|r-6-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-06-20 17:03:20,331 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Starting to Starting
> with
> event: OperationRetryvm's original host id: null new host id: 1 host id
> before state transition: null
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
> applying overprovisioning: 12804
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) We are allocating VM, increasing the used capacity
> of this host:1
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Current Used CPU: 500 , Free CPU:12304 ,Requested
> CPU: 500
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Current Used RAM: 268435456 , Free RAM:16326500352
> ,Requested RAM: 134217728
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) CPU STATS after allocation: for host: 1, old used:
> 500, old reserved: 0, actual total: 12804, total with overprovisioning:
> 12804; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
>
> 2013-06-20 17:03:20,336 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) RAM STATS after allocation: for host: 1, old used:
> 268435456, old reserved: 0, total: 16594935808; new used: 402653184,
> reserved: 0; requested mem: 134217728,alloc_from_last:false
>
> 2013-06-20 17:03:20,406 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) VM is being created in podId: 1
>
> 2013-06-20 17:03:20,409 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is acquired for network id 200 as a part of
> network implement
>
> 2013-06-20 17:03:20,409 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Network id=200 is already implemented
>
> 2013-06-20 17:03:20,410 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is released for network id 200 as a part of
> network implement
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking JuniperSRX to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Netscaler to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking F5BigIP to prepare for
> Nic[13-6-null-10.168.
> 4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Ovs to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,476 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking BareMetal to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,477 WARN [network.element.VpcVirtualRouterElement]
> (Job-Executor-18:job-18) Network Ntwk[200|Public|1] is not associated with
> any VPC
>
> 2013-06-20 17:03:20,477 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking NiciraNvp to prepare for
> Nic[13-6-null-10.168.4.122]
>
> 2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is acquired for network id 204 as a part of
> network implement
>
> 2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Network id=204 is already implemented
>
> 2013-06-20 17:03:20,479 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is released for network id 204 as a part of
> network implement
>
> 2013-06-20 17:03:20,536 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking JuniperSRX to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Netscaler to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking F5BigIP to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Ovs to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking BareMetal to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,651 WARN [network.element.VpcVirtualRouterElement]
> (Job-Executor-18:job-18) Network Ntwk[204|Guest|8] is not associated with
> any VPC
>
> 2013-06-20 17:03:20,651 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking NiciraNvp to prepare for
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:03:20,652 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:03:20,653 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is acquired for network id 202 as a part of
> network implement
>
> 2013-06-20 17:03:20,654 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Network id=202 is already implemented
>
> 2013-06-20 17:03:20,654 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is released for network id 202 as a part of
> network implement
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking JuniperSRX to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Netscaler to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking F5BigIP to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Ovs to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,835 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalDhcpServer to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking BareMetal to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking SecurityGroupProvider to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VpcVirtualRouter to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,836 WARN [network.element.VpcVirtualRouterElement]
> (Job-Executor-18:job-18) Network Ntwk[202|Control|3] is not associated with
> any VPC
>
> 2013-06-20 17:03:20,836 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking NiciraNvp to prepare for
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-169.254.3.18]
>
> 2013-06-20 17:03:20,837 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) Checking if we need to prepare 1 volumes for
> VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:03:20,837 DEBUG [cloud.storage.StorageManagerImpl]
> (Job-Executor-18:job-18) No need to recreate the volume: Vol[8|vm=6|ROOT],
> since it already has a pool assigned: 200, adding disk to VM
>
> 2013-06-20 17:03:20,844 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Boot Args for VM[DomainRouter|r-6-VM]: template=domP name=r-6-VM
> eth2ip=10.
> 168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254 eth0ip=10.1.1.1
> eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
> eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
> dns1=202.106.196.115 dns2=202.106.46.151
>
> 2013-06-20 17:03:20,934 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 1 ip(s) to apply as a part of domR VM[DomainRouter|r-6-VM] start.
>
> 2013-06-20 17:03:20,946 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Resending ipAssoc, port forwarding, load balancing rules as a part of
> Virtual router start
>
> 2013-06-20 17:03:20,955 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 static nat(s) to apply as a part of domR VM[DomainRouter|r-6-VM]
> start.
>
> 2013-06-20 17:03:20,955 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 firewall rule(s) to apply as a part of domR VM[DomainRouter|r-6-VM]
> start.
>
> 2013-06-20 17:03:20,955 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 port forwarding rule(s) to apply as a part of domR
> VM[DomainRouter|r-6-VM] start.
>
> 2013-06-20 17:03:20,955 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 static nat rule(s) to apply as a part of domR
> VM[DomainRouter|r-6-VM] start.
>
> 2013-06-20 17:03:20,955 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 vpn(s) to apply as a part of domR VM[DomainRouter|r-6-VM] start.
>
> 2013-06-20 17:03:20,956 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Found 0 load balancing rule(s) to apply as a part of domR
> VM[DomainRouter|r-6-VM] start.
>
> 2013-06-20 17:03:20,957 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Reapplying dhcp entries as a part of domR VM[DomainRouter|r-6-VM] start...
>
> 2013-06-20 17:03:20,959 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Reapplying vm data (userData and metaData) entries as a part of domR
> VM[DomainRouter|r-6-VM] start...
>
> 2013-06-20 17:03:21,021 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060602: Sending { Cmd , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 100111,
>
> [{"StartCommand":{"vm":{"id":6,"name":"r-6-VM","type":"DomainRouter","cpus":
>
> 1,"speed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"De
> bian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-6-VM
> eth2ip=10.168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254
> eth0ip=10.1.
> 1.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
> eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
> dns1=202.106.196.115
>
> dns2=202.106.46.151","rebootOnCrash":false,"enableHA":true,"limitCpuUse":fal
>
> se,"vncPassword":"42d9b2291d8e0084","params":{},"uuid":"b8d04faa-e563-4a00-a
>
> 706-a34c600c1326","disks":[{"id":8,"name":"ROOT-6","mountPoint":"/primary","
>
> path":"3e015950-9ce7-4fe7-9783-cfaf6be94738","size":725811200,"type":"ROOT",
>
> "storagePoolType":"NetworkFilesystem","storagePoolUuid":"b1f7df2b-d05e-3a37-
>
> 8103-c5c6be9880c6","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":20
>
> 0,"defaultNic":true,"uuid":"7c8daa7b-0bb6-47b3-a97e-f4c3ca848930","ip":"10.1
>
> 68.4.122","netmask":"255.255.255.0","gateway":"10.168.4.254","mac":"06:22:12
>
> :00:00:13","dns1":"202.106.196.115","dns2":"202.106.46.151","broadcastType":
>
> "Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan
>
> ://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps"
>
> :200,"defaultNic":false,"uuid":"6f9f396a-6f4f-4348-ac50-59d92390a5e2","ip":"
>
> 10.1.1.1","netmask":"255.255.255.0","mac":"02:00:44:6e:00:04","dns1":"202.10
>
> 6.196.115","dns2":"202.106.46.151","broadcastType":"Vlan","type":"Guest","br
>
> oadcastUri":"vlan://170","isolationUri":"vlan://170","isSecurityGroupEnabled
>
> ":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"ddf4d
>
> 867-3e08-45dc-ba33-d8649920c85a","ip":"169.254.3.18","netmask":"255.255.0.0"
>
> ,"gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:12","broadcastType":"LinkLoca
>
> l","type":"Control","isSecurityGroupEnabled":false}]},"wait":0}},{"check.Che
>
> ckSshCommand":{"ip":"169.254.3.18","port":3922,"interval":6,"retries":100,"n
>
> ame":"r-6-VM","wait":0}},{"GetDomRVersionCmd":{"accessDetails":{"router.ip":
> "169.254.3.18","router.name
> ":"r-6-VM"},"wait":0}},{},{"routing.IpAssocComman
>
> d":{"ipAddresses":[{"accountId":2,"publicIp":"10.168.4.122","sourceNat":true
>
> ,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGate
>
> way":"10.168.4.254","vlanNetmask":"255.255.255.0","vifMacAddress":"06:fb:96:
>
> 00:00:13","networkRate":200,"trafficType":"Public"}],"accessDetails":{"route
>
> r.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.3
> .18","router.name":"r-6-VM"},"wait":0}}] }
>
> 2013-06-20 17:03:24,895 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-7:null) Ping from 4
>
> 2013-06-20 17:03:27,691 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) StorageCollector is running...
>
> 2013-06-20 17:03:27,744 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 4-1147995179: Received: { Ans: , MgmtId:
> 119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:03:27,920 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 2-1927415091: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:03:28,636 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:03:28,879 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:03:29,786 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:03:33,312 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-5:null) Ping from 5
>
> 2013-06-20 17:03:46,559 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-8:null) Ping from 2
>
> 2013-06-20 17:03:58,001 DEBUG [agent.transport.Request]
> (AgentManager-Handler-6:null) Seq 1-1689060602: Processing: { Ans: ,
> MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
>
> [{"StartAnswer":{"vm":{"id":6,"name":"r-6-VM","type":"DomainRouter","cpus":1
>
> ,"speed":500,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"Deb
> ian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-6-VM
> eth2ip=10.168.4.122 eth2mask=255.255.255.0 gateway=10.168.4.254
> eth0ip=10.1.
> 1.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1
> eth1ip=169.254.3.18 eth1mask=255.255.0.0 type=router disable_rp_filter=true
> dns1=202.106.196.115
>
> dns2=202.106.46.151","rebootOnCrash":false,"enableHA":true,"limitCpuUse":fal
>
> se,"vncPassword":"42d9b2291d8e0084","params":{},"uuid":"b8d04faa-e563-4a00-a
>
> 706-a34c600c1326","disks":[{"id":8,"name":"ROOT-6","mountPoint":"/primary","
>
> path":"3e015950-9ce7-4fe7-9783-cfaf6be94738","size":725811200,"type":"ROOT",
>
> "storagePoolType":"NetworkFilesystem","storagePoolUuid":"b1f7df2b-d05e-3a37-
>
> 8103-c5c6be9880c6","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":20
>
> 0,"defaultNic":true,"uuid":"7c8daa7b-0bb6-47b3-a97e-f4c3ca848930","ip":"10.1
>
> 68.4.122","netmask":"255.255.255.0","gateway":"10.168.4.254","mac":"06:22:12
>
> :00:00:13","dns1":"202.106.196.115","dns2":"202.106.46.151","broadcastType":
>
> "Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan
>
> ://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps"
>
> :200,"defaultNic":false,"uuid":"6f9f396a-6f4f-4348-ac50-59d92390a5e2","ip":"
>
> 10.1.1.1","netmask":"255.255.255.0","mac":"02:00:44:6e:00:04","dns1":"202.10
>
> 6.196.115","dns2":"202.106.46.151","broadcastType":"Vlan","type":"Guest","br
>
> oadcastUri":"vlan://170","isolationUri":"vlan://170","isSecurityGroupEnabled
>
> ":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"ddf4d
>
> 867-3e08-45dc-ba33-d8649920c85a","ip":"169.254.3.18","netmask":"255.255.0.0"
>
> ,"gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:12","broadcastType":"LinkLoca
>
> l","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0
>
> }},{"check.CheckSshAnswer":{"result":true,"wait":0}},{"GetDomRVersionAnswer"
> :{"result":false,"details":"GetDomRVersionCmd
> failed","wait":0}},{"Answer":{"result":false,"details":"Stopped by previous
> failure","wait":0}},{"Answer":{"result":false,"details":"Stopped by
> previous
> failure","wait":0}}] }
>
> 2013-06-20 17:03:58,001 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-6:null) Seq 1-1689060602: No more commands found
>
> 2013-06-20 17:03:58,001 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060602: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 110, { StartAnswer,
> CheckSshAnswer,
> GetDomRVersionAnswer, Answer, Answer } }
>
> 2013-06-20 17:03:58,062 WARN
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Unable to get the template/scripts version of router r-6-VM due to:
> GetDomRVersionCmd failed
>
> 2013-06-20 17:03:58,062 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) The guru did not like the answers so stopping
> VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:03:58,064 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060603: Sending { Cmd , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"r-6-VM","wait":0}}] }
>
> 2013-06-20 17:03:58,636 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:03:58,877 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:03:59,786 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:04:01,195 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) HostStatsCollector is running...
>
> 2013-06-20 17:04:01,759 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 1-1689060604: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:04:02,189 DEBUG [agent.transport.Request]
> (AgentManager-Handler-9:null) Seq 1-1689060603: Processing: { Ans: ,
> MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
>
> 2013-06-20 17:04:02,189 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-9:null) Seq 1-1689060603: No more commands found
>
> 2013-06-20 17:04:02,189 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060603: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>
> 2013-06-20 17:04:02,189 ERROR [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Failed to start instance VM[DomainRouter|r-6-VM]
>
> com.cloud.utils.exception.ExecutionException: Unable to start
> VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
> l.java:814)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
> 472)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNet
> workApplianceManagerImpl.java:2352)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRout
> er(VirtualNetworkApplianceManagerImpl.java:1597)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(Vir
> tualNetworkApplianceManagerImpl.java:1697)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRou
> terInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
>
> at
>
> com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElemen
> t.java:172)
>
> at
>
> com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(Ne
> tworkManagerImpl.java:2033)
>
> at
>
> com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.jav
> a:1965)
>
> at
> com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34)
>
> at
> com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.
> java:2110)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
> l.java:752)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
> 472)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:29
> 29)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:26
> 01)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:25
> 89)
>
> at
> com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
>
> at
> com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
>
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
>
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
>
> 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:11
> 10)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
> 03)
>
> at java.lang.Thread.run(Thread.java:679)
>
> 2013-06-20 17:04:02,250 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Cleaning up resources for the vm
> VM[DomainRouter|r-6-VM] in Starting state
>
> 2013-06-20 17:04:02,252 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060605: Sending { Cmd , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"r-6-VM","wait":0}}] }
>
> 2013-06-20 17:04:02,355 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 2-1927415092: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
>
> 2013-06-20 17:04:02,356 DEBUG [agent.transport.Request]
> (AgentManager-Handler-2:null) Seq 1-1689060605: Processing: { Ans: ,
> MgmtId: 119004504374952, via: 1, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
>
> 2013-06-20 17:04:02,356 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-2:null) Seq 1-1689060605: No more commands found
>
> 2013-06-20 17:04:02,356 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 1-1689060605: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
>
> 2013-06-20 17:04:02,360 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Successfully updated user statistics as a part of domR
> VM[DomainRouter|r-6-VM] reboot/stop
>
> 2013-06-20 17:04:02,459 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking JuniperSRX to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Netscaler to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking F5BigIP to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Ovs to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalDhcpServer to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking BareMetal to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking SecurityGroupProvider to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VpcVirtualRouter to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,526 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking NiciraNvp to release
> Nic[11-6-ee074068-816a-4022-ba18-61f62d24ae71-10.1.1.1]
>
> 2013-06-20 17:04:02,679 DEBUG [network.guru.ControlNetworkGuru]
> (Job-Executor-18:job-18) Released nic: NicProfile[12-6-null-null-null
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking JuniperSRX to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Netscaler to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking F5BigIP to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VirtualRouter to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking Ovs to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking ExternalDhcpServer to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking BareMetal to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking SecurityGroupProvider to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking CiscoNexus1000vVSM to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking VpcVirtualRouter to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,728 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Asking NiciraNvp to release
> Nic[12-6-ee074068-816a-4022-ba18-61f62d24ae71-null]
>
> 2013-06-20 17:04:02,779 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully released network resources for the vm
> VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:04:02,779 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully cleanued up resources for the vm
> VM[DomainRouter|r-6-VM] in Starting state
>
> 2013-06-20 17:04:02,882 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Starting to Stopped with
> event: OperationFailedvm's original host id: null new host id: null host id
> before state transition: 1
>
> 2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
> applying overprovisioning: 12804
>
> 2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) release cpu from host: 1, old used: 1000,reserved:
> 0, actual total: 12804, total with overprovisioning: 12804; new used:
> 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
>
> 2013-06-20 17:04:02,886 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) release mem from host: 1, old used:
> 402653184,reserved: 0, total: 16594935808; new used: 268435456,reserved:0;
> movedfromreserved: false,moveToReserveredfalse
>
> 2013-06-20 17:04:02,939 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Cleaning up because we're unable to implement the
> network Ntwk[204|Guest|8]
>
> 2013-06-20 17:04:03,015 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Releasing 0 port forwarding rules for network
> id=204 as a part of shutdownNetworkRules
>
> 2013-06-20 17:04:03,015 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) There are no rules to forward to the network
> elements
>
> 2013-06-20 17:04:03,016 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Releasing 0 static nat rules for network id=204 as
> a part of shutdownNetworkRules
>
> 2013-06-20 17:04:03,016 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) There are no rules to forward to the network
> elements
>
> 2013-06-20 17:04:03,017 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) There are no rules to forward to the network
> elements
>
> 2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Releasing 0 firewall rules for network id=204 as a
> part of shutdownNetworkRules
>
> 2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) There are no rules to forward to the network
> elements
>
> 2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Releasing 0 Network ACLs for network id=204 as a
> part of shutdownNetworkRules
>
> 2013-06-20 17:04:03,018 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) There are no rules to forward to the network
> elements
>
> 2013-06-20 17:04:03,019 DEBUG [network.rules.RulesManagerImpl]
> (Job-Executor-18:job-18) Found 0 static nat rules to apply for network id
> 204
>
> 2013-06-20 17:04:03,028 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Router r-6-VM is in Stopped, so not sending apply ip association commands
> to
> the backend
>
> 2013-06-20 17:04:03,030 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Sending network shutdown to VirtualRouter
>
> 2013-06-20 17:04:03,031 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (Job-Executor-18:job-18)
> Stopping router VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:04:03,032 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) VM is already stopped: VM[DomainRouter|r-6-VM]
>
> 2013-06-20 17:04:03,033 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Network id=204 is shutdown successfully, cleaning
> up corresponding resources now.
>
> 2013-06-20 17:04:03,034 DEBUG [network.guru.GuestNetworkGuru]
> (Job-Executor-18:job-18) Releasing vnet for the network id=204
>
> 2013-06-20 17:04:03,090 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-18:job-18) Lock is released for network id 204 as a part of
> network implement
>
> 2013-06-20 17:04:03,090 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Unable to contact resource.
>
> com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
> unreachable: Host 1: Unable to start instance due to Unable to start
> VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
> l.java:847)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
> 472)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNet
> workApplianceManagerImpl.java:2352)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRout
> er(VirtualNetworkApplianceManagerImpl.java:1597)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(Vir
> tualNetworkApplianceManagerImpl.java:1697)
>
> at
>
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRou
> terInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
>
> at
>
> com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElemen
> t.java:172)
>
> at
>
> com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(Ne
> tworkManagerImpl.java:2033)
>
> at
>
> com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.jav
> a:1965)
>
> at
> com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34)
>
> at
> com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.
> java:2110)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
> l.java:752)
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:
> 472)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:29
> 29)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:26
> 01)
>
> at
>
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:25
> 89)
>
> at
> com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
>
> at
> com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
>
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
>
> at
> com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
>
> 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:11
> 10)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
> 03)
>
> at java.lang.Thread.run(Thread.java:679)
>
> Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
> VM[DomainRouter|r-6-VM] due to error in finalizeStart, not retrying
>
> at
>
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImp
> l.java:814)
>
> ... 33 more
>
> 2013-06-20 17:04:03,139 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Cleaning up resources for the vm VM[User|test] in
> Starting state
>
> 2013-06-20 17:04:03,140 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 2-1927415093: Sending { Cmd , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 100111,
> [{"StopCommand":{"isProxy":false,"vmName":"i-2-7-VM","wait":0}}] }
>
> 2013-06-20 17:04:03,245 DEBUG [agent.transport.Request]
> (AgentManager-Handler-13:null) Seq 2-1927415093: Processing: { Ans: ,
> MgmtId: 119004504374952, via: 2, Ver: v1, Flags: 110,
> [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
>
> 2013-06-20 17:04:03,245 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-13:null) Seq 2-1927415093: No more commands found
>
> 2013-06-20 17:04:03,245 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-18) Seq 2-1927415093: Received: { Ans: , MgmtId:
> 119004504374952, via: 2, Ver: v1, Flags: 110, { StopAnswer } }
>
> 2013-06-20 17:04:03,249 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully released network resources for the vm
> VM[User|test]
>
> 2013-06-20 17:04:03,249 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-18:job-18) Successfully cleanued up resources for the vm
> VM[User|test] in Starting state
>
> 2013-06-20 17:04:03,250 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) DeploymentPlanner allocation algorithm: random
>
> 2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Trying to allocate a host and storage pools from
> dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
>
> 2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Is ROOT volume READY (pool already allocated)?: No
>
> 2013-06-20 17:04:03,251 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Searching all possible resources under this Zone:
> 1
>
> 2013-06-20 17:04:03,252 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Listing clusters in order of aggregate capacity,
> that have (atleast one host with) enough CPU and RAM capacity under this
> Zone: 1
>
> 2013-06-20 17:04:03,253 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) CPUOverprovisioningFactor considered: 1.0
>
> 2013-06-20 17:04:03,258 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Checking resources in Cluster: 1 under Pod: 1
>
> 2013-06-20 17:04:03,258 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Calling HostAllocators to find suitable hosts
>
> 2013-06-20 17:04:03,258 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for hosts in dc:
> 1
> pod:1 cluster:1
>
> 2013-06-20 17:04:03,259 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) FirstFitAllocator has 2
> hosts to check for allocation: [Host[-1-Routing], Host[-2-Routing]]
>
> 2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Found 2 hosts for
> allocation after prioritization: [Host[-1-Routing], Host[-2-Routing]]
>
> 2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Looking for
> speed=1000Mhz,
> Ram=1024
>
> 2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host name:
> node1.cloud.com, hostId: 1 is in avoid set, skipping this and trying other
> available hosts
>
> 2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host name:
> node1.cloud.com, hostId: 2 is in avoid set, skipping this and trying other
> available hosts
>
> 2013-06-20 17:04:03,261 DEBUG [allocator.impl.FirstFitAllocator]
> (Job-Executor-18:job-18 FirstFitRoutingAllocator) Host Allocator returning
> 0
> suitable hosts
>
> 2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) No suitable hosts found
>
> 2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) No suitable hosts found under this Cluster: 1
>
> 2013-06-20 17:04:03,261 DEBUG [cloud.deploy.FirstFitPlanner]
> (Job-Executor-18:job-18) Could not find suitable Deployment Destination for
> this VM under any clusters, returning.
>
> 2013-06-20 17:04:03,397 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) VM state transitted from :Starting to Stopped with
> event: OperationFailedvm's original host id: null new host id: null host id
> before state transition: 2
>
> 2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) Hosts's actual total CPU: 12804 and CPU after
> applying overprovisioning: 12804
>
> 2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) release cpu from host: 2, old used: 1500,reserved:
> 0, actual total: 12804, total with overprovisioning: 12804; new used:
> 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
>
> 2013-06-20 17:04:03,401 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) release mem from host: 2, old used:
> 2147483648,reserved: 0, total: 16594935808; new used:
> 1073741824,reserved:0;
> movedfromreserved: false,moveToReserveredfalse
>
> 2013-06-20 17:04:03,458 DEBUG [cloud.vm.UserVmManagerImpl]
> (Job-Executor-18:job-18) Destroying vm VM[User|test] as it failed to create
>
> 2013-06-20 17:04:03,581 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-18:job-18) 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
>
> 2013-06-20 17:04:04,198 INFO [api.commands.DeployVMCmd]
> (Job-Executor-18:job-18)
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[User|test]Scope=interface com.cloud.dc.DataCenter; id=1
>
> 2013-06-20 17:04:04,199 WARN [cloud.api.ApiDispatcher]
> (Job-Executor-18:job-18) class com.cloud.api.ServerApiException : Unable to
> create a deployment for VM[User|test]
>
> 2013-06-20 17:04:04,199 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-18:job-18) Complete async job-18, jobStatus: 2, resultCode:
> 530, result: Error Code: 533 Error text: Unable to create a deployment for
> VM[User|test]
>
> 2013-06-20 17:04:04,646 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-11:null) Async job-18 completed
>
> 2013-06-20 17:04:04,663 DEBUG [cloud.vm.UserVmManagerImpl]
> (catalina-exec-4:null) THE WHERE CLAUSE IS:user_vm.id = ?
>
> 2013-06-20 17:04:12,539 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-3:null) Ping from 1
>
> 2013-06-20 17:04:16,809 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-14:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:04:17,264 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) VmStatsCollector is running...
>
> 2013-06-20 17:04:17,545 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-2:null) Service SecurityGroup is not supported in the
> network
> id=204
>
> 2013-06-20 17:04:17,993 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-16:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:04:19,138 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-21:null) Service SecurityGroup is not supported in the
> network id=204
>
> 2013-06-20 17:04:20,282 DEBUG [cloud.network.NetworkManagerImpl]
> (catalina-exec-3:null) Service SecurityGroup is not supported in the
> network
> id=204
>
> 2013-06-20 17:04:24,895 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-1:null) Ping from 4
>
> 2013-06-20 17:04:27,920 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-3:null) StorageCollector is running...
>
> 2013-06-20 17:04:27,975 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 4-1147995180: Received: { Ans: , MgmtId:
> 119004504374952, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:04:28,040 DEBUG [agent.transport.Request]
> (StatsCollector-3:null) Seq 1-1689060606: Received: { Ans: , MgmtId:
> 119004504374952, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
>
> 2013-06-20 17:04:28,636 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
>
> 2013-06-20 17:04:28,878 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
>
> 2013-06-20 17:04:29,786 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 1 routers.
>
> 2013-06-20 17:04:33,313 DEBUG [agent.manager.AgentManagerImpl]
> (AgentManager-Handler-7:null) Ping from 5
>
>