cloudstack-users-cn mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Lucien" <lihang_...@126.com>
Subject hi,新建的vm不成功!
Date Thu, 20 Jun 2013 02:38:47 GMT
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


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message