You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Parth Jagirdar (JIRA)" <ji...@apache.org> on 2014/02/13 19:41:23 UTC
[jira] [Closed] (CLOUDSTACK-5778) Contrail:MS: Restart Xen host
results in failure to start System VM's and Guest VM's
[ https://issues.apache.org/jira/browse/CLOUDSTACK-5778?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Parth Jagirdar closed CLOUDSTACK-5778.
--------------------------------------
> Contrail:MS: Restart Xen host results in failure to start System VM's and Guest VM's
> ------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-5778
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5778
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Contrail, Management Server, XenServer
> Affects Versions: 4.2.0
> Environment: Contrail, Xenserver
> Reporter: Parth Jagirdar
> Priority: Blocker
> Fix For: 4.3.0
>
>
> Restarting a Xenserver host results in failure to start Systems VM and Guest VM's.
> Host restart should not affect functionality and normal operation must resume once Host is Up.
> 2014-01-03 15:23:29,233 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START=== 10.215.2.19 -- GET command=listZones&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791421073
> 2014-01-03 15:23:29,242 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END=== 10.215.2.19 -- GET command=listZones&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791421073
> 2014-01-03 15:23:29,276 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===START=== 10.215.2.19 -- GET command=listPods&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421135
> 2014-01-03 15:23:29,284 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null) ===END=== 10.215.2.19 -- GET command=listPods&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421135
> 2014-01-03 15:23:29,293 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===START=== 10.215.2.19 -- GET command=listClusters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421151
> 2014-01-03 15:23:29,303 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===END=== 10.215.2.19 -- GET command=listClusters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421151
> 2014-01-03 15:23:29,322 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START=== 10.215.2.19 -- GET command=listHosts&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&type=routing&page=1&pagesize=1&_=1388791421167
> 2014-01-03 15:23:29,328 DEBUG [api.query.QueryManagerImpl] (catalina-exec-17:null) >>>Searching for hosts>>>
> 2014-01-03 15:23:29,334 DEBUG [api.query.QueryManagerImpl] (catalina-exec-17:null) >>>Generating Response>>>
> 2014-01-03 15:23:29,338 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END=== 10.215.2.19 -- GET command=listHosts&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&type=routing&page=1&pagesize=1&_=1388791421167
> 2014-01-03 15:23:29,343 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===START=== 10.215.2.19 -- GET command=listStoragePools&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421213
> 2014-01-03 15:23:29,354 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null) ===END=== 10.215.2.19 -- GET command=listStoragePools&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421213
> 2014-01-03 15:23:29,361 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===START=== 10.215.2.19 -- GET command=listImageStores&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&type=SecondaryStorage&page=1&pagesize=1&_=1388791421229
> 2014-01-03 15:23:29,371 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null) ===END=== 10.215.2.19 -- GET command=listImageStores&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&type=SecondaryStorage&page=1&pagesize=1&_=1388791421229
> 2014-01-03 15:23:29,377 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START=== 10.215.2.19 -- GET command=listSystemVms&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421245
> 2014-01-03 15:23:29,423 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END=== 10.215.2.19 -- GET command=listSystemVms&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pagesize=1&_=1388791421245
> 2014-01-03 15:23:29,428 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START=== 10.215.2.19 -- GET command=listRouters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&projectid=-1&page=1&pagesize=1&_=1388791421291
> 2014-01-03 15:23:29,437 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END=== 10.215.2.19 -- GET command=listRouters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&projectid=-1&page=1&pagesize=1&_=1388791421291
> 2014-01-03 15:23:29,441 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START=== 10.215.2.19 -- GET command=listRouters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&listAll=true&page=1&pagesize=1&_=1388791421307
> 2014-01-03 15:23:29,450 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END=== 10.215.2.19 -- GET command=listRouters&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&listAll=true&page=1&pagesize=1&_=1388791421307
> 2014-01-03 15:23:29,457 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===START=== 10.215.2.19 -- GET command=listCapacity&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791421323
> 2014-01-03 15:23:29,471 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null) ===END=== 10.215.2.19 -- GET command=listCapacity&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791421323
> 2014-01-03 15:23:31,014 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running...
> 2014-01-03 15:23:31,022 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-355:null) Seq 1-477823131: Executing request
> 2014-01-03 15:23:31,226 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-355:null) Seq 1-477823131: Response Received:
> 2014-01-03 15:23:31,226 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-477823131: Received: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-01-03 15:23:31,671 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===START=== 10.215.2.19 -- GET command=listSystemVms&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pageSize=20&listAll=true&_=1388791423522
> 2014-01-03 15:23:31,717 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===END=== 10.215.2.19 -- GET command=listSystemVms&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&page=1&pageSize=20&listAll=true&_=1388791423522
> 2014-01-03 15:23:31,725 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 10.215.2.19 -- GET command=listHosts&listAll=true&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791423585
> 2014-01-03 15:23:31,731 DEBUG [api.query.QueryManagerImpl] (catalina-exec-24:null) >>>Searching for hosts>>>
> 2014-01-03 15:23:31,738 DEBUG [api.query.QueryManagerImpl] (catalina-exec-24:null) >>>Generating Response>>>
> 2014-01-03 15:23:31,743 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 10.215.2.19 -- GET command=listHosts&listAll=true&response=json&sessionkey=lhySlIIDUvWHZ5yKeVK55FnVmbc%3D&_=1388791423585
> 2014-01-03 15:23:42,609 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
> 2014-01-03 15:23:42,613 INFO [storage.endpoint.DefaultEndPointSelector] (StatsCollector-3:null) No running ssvm is found, so command will be sent to LocalHostEndPoint
> 2014-01-03 15:23:42,619 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-73:null) Seq 1-477823132: Executing request
> 2014-01-03 15:23:43,026 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-73:null) Seq 1-477823132: Response Received:
> 2014-01-03 15:23:43,026 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-477823132: Received: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2014-01-03 15:23:46,794 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2014-01-03 15:23:46,799 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No running secondary storage vms found in datacenter id=1, starting one
> 2014-01-03 15:23:46,803 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) No stopped secondary storage vm is available, need to allocate a new secondary storage vm
> 2014-01-03 15:23:46,804 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Assign secondary storage vm from a newly started instance for request from data center : 1
> 2014-01-03 15:23:46,816 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Found existing network configuration for offering [Network Offering [1-Public-System-Public-Network]: Ntwk[200|Public|1]
> 2014-01-03 15:23:46,816 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Releasing lock for Acct[b412405a-677a-11e3-b51d-4eed0dafe36c-system]
> 2014-01-03 15:23:46,820 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Found existing network configuration for offering [Network Offering [3-Control-System-Control-Network]: Ntwk[202|Control|3]
> 2014-01-03 15:23:46,820 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Releasing lock for Acct[b412405a-677a-11e3-b51d-4eed0dafe36c-system]
> 2014-01-03 15:23:46,823 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Found existing network configuration for offering [Network Offering [2-Management-System-Management-Network]: Ntwk[201|Management|2]
> 2014-01-03 15:23:46,823 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Releasing lock for Acct[b412405a-677a-11e3-b51d-4eed0dafe36c-system]
> 2014-01-03 15:23:46,826 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Found existing network configuration for offering [Network Offering [4-Storage-System-Storage-Network]: Ntwk[203|Storage|4]
> 2014-01-03 15:23:46,826 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Releasing lock for Acct[b412405a-677a-11e3-b51d-4eed0dafe36c-system]
> 2014-01-03 15:23:46,833 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Allocating entries for VM: VM[SecondaryStorageVm|s-3052-VM]
> 2014-01-03 15:23:46,837 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Allocating nics for VM[SecondaryStorageVm|s-3052-VM]
> 2014-01-03 15:23:46,837 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-3052-VM] in network Ntwk[200|Public|1] with requested profile NicProfile[0-0-null-null-null
> 2014-01-03 15:23:46,849 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-3052-VM] in network Ntwk[202|Control|3] with requested profile null
> 2014-01-03 15:23:46,855 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-3052-VM] in network Ntwk[201|Management|2] with requested profile null
> 2014-01-03 15:23:46,862 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-3052-VM] in network Ntwk[203|Storage|4] with requested profile null
> 2014-01-03 15:23:46,869 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Allocating disks for VM[SecondaryStorageVm|s-3052-VM]
> 2014-01-03 15:23:46,875 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Allocation completed for VM: VM[SecondaryStorageVm|s-3052-VM]
> 2014-01-03 15:23:46,877 DEBUG [cloud.alert.SecondaryStorageVmAlertAdapter] (secstorage-1:null) received secondary storage vm alert
> 2014-01-03 15:23:46,877 DEBUG [cloud.alert.SecondaryStorageVmAlertAdapter] (secstorage-1:null) New secondary storage vm created, zone: default, secStorageVm: s-3052-VM, public IP: null, private IP: null
> 2014-01-03 15:23:46,901 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) 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
> 2014-01-03 15:23:46,901 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully transitioned to start state for VM[SecondaryStorageVm|s-3052-VM] reservation id = fcf22fde-9dbf-475d-9586-8b0c755087e1
> 2014-01-03 15:23:46,904 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Trying to deploy VM, vm has dcId: 1 and podId: null
> 2014-01-03 15:23:46,904 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-01-03 15:23:46,906 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-01-03 15:23:46,907 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_2f3b9de3@3d4e8624
> 2014-01-03 15:23:46,907 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
> 2014-01-03 15:23:46,907 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
> 2014-01-03 15:23:46,907 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching all possible resources under this Zone: 1
> 2014-01-03 15:23:46,908 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2014-01-03 15:23:46,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Checking resources in Cluster: 1 under Pod: 1
> 2014-01-03 15:23:46,915 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2014-01-03 15:23:46,918 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2014-01-03 15:23:46,920 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2014-01-03 15:23:46,920 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=256
> 2014-01-03 15:23:46,925 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 268435456 , cpuOverprovisioningFactor: 1.0
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free CPU: 8544 , Requested CPU: 500
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Free RAM: 16190149632 , Requested RAM: 268435456
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 500, actual total: 9044, total with overprovisioning: 9044; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-01-03 15:23:46,927 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 16190149632; requested mem: 268435456,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-01-03 15:23:46,927 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
> 2014-01-03 15:23:46,927 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2014-01-03 15:23:46,929 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Checking suitable pools for volume (Id, Type): (3054,ROOT)
> 2014-01-03 15:23:46,929 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) We need to allocate new storagepool for this volume
> 2014-01-03 15:23:46,929 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Calling StoragePoolAllocators to find suitable pools
> 2014-01-03 15:23:46,930 DEBUG [storage.allocator.LocalStoragePoolAllocator] (secstorage-1:null) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2014-01-03 15:23:46,930 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (secstorage-1:null) ClusterScopeStoragePoolAllocator looking for storage pool
> 2014-01-03 15:23:46,930 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (secstorage-1:null) Looking for pools in dc: 1 pod:1 cluster:1
> 2014-01-03 15:23:46,933 DEBUG [storage.allocator.AbstractStoragePoolAllocator] (secstorage-1:null) Checking if storage pool is suitable, name: null ,poolId: 6
> 2014-01-03 15:23:46,937 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking pool 6 for storage, totalSize: 11810778316800, usedBytes: 7338807951360, usedPct: 0.6213653117949951, disable threshold: 0.85
> 2014-01-03 15:23:46,956 DEBUG [cloud.storage.StorageManagerImpl] (secstorage-1:null) Checking pool: 6 for volume allocation [Vol[3054|vm=3052|ROOT]], maxSize : 23621556633600, totalAllocatedSize : 136873805824, askingSize : 565240320, allocated disable threshold: 0.85
> 2014-01-03 15:23:46,956 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (secstorage-1:null) FirstFitStoragePoolAllocator returning 1 suitable storage pools
> 2014-01-03 15:23:46,956 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-01-03 15:23:46,956 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
> 2014-01-03 15:23:46,957 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Host: 1 can access pool: 6
> 2014-01-03 15:23:46,958 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Found a potential host id: 1 name: xenserver-contrail and associated storage pools for this VM
> 2014-01-03 15:23:46,960 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(3054|ROOT-->Pool(6))]
> 2014-01-03 15:23:46,960 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Deployment found - P0=VM[SecondaryStorageVm|s-3052-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(3054|ROOT-->Pool(6))]
> 2014-01-03 15:23:46,979 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2014-01-03 15:23:46,979 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capacity for zone default
> 2014-01-03 15:23:46,982 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
> 2014-01-03 15:23:46,989 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) 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
> 2014-01-03 15:23:46,991 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 1 new host id: null host id before state transition: null
> 2014-01-03 15:23:46,991 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 0f42170e-c8e0-469e-b730-af34e7afcf55
> 2014-01-03 15:23:46,999 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1
> 2014-01-03 15:23:46,999 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) We are allocating VM, increasing the used capacity of this host:1
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used CPU: 0 , Free CPU:8544 ,Requested CPU: 500
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Current Used RAM: 0 , Free RAM:16190149632 ,Requested RAM: 268435456
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) CPU STATS after allocation: for host: 1, old used: 0, old reserved: 500, actual total: 9044, total with overprovisioning: 9044; new used:500, reserved:500; requested cpu:500,alloc_from_last:false
> 2014-01-03 15:23:47,000 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) RAM STATS after allocation: for host: 1, old used: 0, old reserved: 0, total: 16190149632; new used: 268435456, reserved: 0; requested mem: 268435456,alloc_from_last:false
> 2014-01-03 15:23:47,003 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
> 2014-01-03 15:23:47,003 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) VM is being created in podId: 1
> 2014-01-03 15:23:47,003 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
> 2014-01-03 15:23:47,004 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-01-03 15:23:47,006 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_2f3b9de3@3d4e8624
> 2014-01-03 15:23:47,006 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
> 2014-01-03 15:23:47,006 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
> 2014-01-03 15:23:47,006 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) This VM has last host_id specified, trying to choose the same host: 1
> 2014-01-03 15:23:47,008 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=200 is already implemented
> 2014-01-03 15:23:47,013 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We need to allocate to the last host again, so checking if there is enough reserved capacity
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Reserved CPU: 500 , Requested CPU: 500
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Reserved RAM: 0 , Requested RAM: 1073741824
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) STATS: Failed to alloc resource from host: 1 reservedCpu: 500, requested cpu: 500, reservedMem: 0, requested mem: 1073741824
> 2014-01-03 15:23:47,016 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Host does not have enough reserved RAM available, cannot allocate to this host.
> 2014-01-03 15:23:47,016 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) The last host of this VM does not have enough capacity
> 2014-01-03 15:23:47,016 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Cannot choose the last host to deploy this VM
> 2014-01-03 15:23:47,017 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
> 2014-01-03 15:23:47,023 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1
> 2014-01-03 15:23:47,023 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2014-01-03 15:23:47,028 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to prepare for Nic[12191-3052-null-10.223.138.2]
> 2014-01-03 15:23:47,028 DEBUG [contrail.management.ContrailElement] (secstorage-1:null) NetworkElement prepare: null, traffic type: Public
> 2014-01-03 15:23:47,028 DEBUG [contrail.management.ContrailElement] (secstorage-1:null) network: 200
> 2014-01-03 15:23:47,029 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2014-01-03 15:23:47,032 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2014-01-03 15:23:47,032 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024
> 2014-01-03 15:23:47,033 DEBUG [contrail.model.InstanceIpModel] (secstorage-1:null) vmiModel has 1 IP addresses
> 2014-01-03 15:23:47,033 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine/0f5bc126-9723-4585-adf8-225a049faf1a
> 2014-01-03 15:23:47,037 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,037 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /virtual-machines, {"virtual-machine":{"name":"s-3052-VM","uuid":"0f5bc126-9723-4585-adf8-225a049faf1a","fq_name":["s-3052-VM"]}}
> 2014-01-03 15:23:47,038 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
> 2014-01-03 15:23:47,042 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,042 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 8044 , Requested CPU: 500
> 2014-01-03 15:23:47,043 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 15921714176 , Requested RAM: 1073741824
> 2014-01-03 15:23:47,043 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2014-01-03 15:23:47,043 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 500, reserved: 500, actual total: 9044, total with overprovisioning: 9044; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-01-03 15:23:47,043 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 268435456, reserved: 0, total: 16190149632; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-01-03 15:23:47,043 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
> 2014-01-03 15:23:47,043 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2014-01-03 15:23:47,044 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,045 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Create virtual-machine uuid: 0f5bc126-9723-4585-adf8-225a049faf1a
> 2014-01-03 15:23:47,045 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/52038987-3f6e-4502-9233-b6f820c3eaf5
> 2014-01-03 15:23:47,046 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (2,ROOT)
> 2014-01-03 15:23:47,046 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Volume has pool already allocated, checking if pool can be reused, poolId: 6
> 2014-01-03 15:23:47,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Planner need not allocate a pool for this volume since its READY
> 2014-01-03 15:23:47,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-01-03 15:23:47,049 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,049 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking if host: 1 can access any suitable storage pool for volume: ROOT
> 2014-01-03 15:23:47,050 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /virtual-machine-interfaces, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["06:75:6a:00:00:1f"]},"virtual_network_refs":[{"to":["default-domain","default-project","__default_Public__"],"attr":null,"href":null,"uuid":null}],"name":"s-3052-VM-2","uuid":"52038987-3f6e-4502-9233-b6f820c3eaf5","fq_name":["s-3052-VM","s-3052-VM-2"],"parent_type":"virtual-machine"}}
> 2014-01-03 15:23:47,051 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Host: 1 can access pool: 6
> 2014-01-03 15:23:47,052 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Found a potential host id: 1 name: xenserver-contrail and associated storage pools for this VM
> 2014-01-03 15:23:47,055 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) 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()]
> 2014-01-03 15:23:47,055 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deployment found - P0=VM[ConsoleProxy|v-2-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()]
> 2014-01-03 15:23:47,060 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,061 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Create virtual-machine-interface uuid: 52038987-3f6e-4502-9233-b6f820c3eaf5
> 2014-01-03 15:23:47,061 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/52038987-3f6e-4502-9233-b6f820c3eaf5
> 2014-01-03 15:23:47,071 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,071 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1097, Etag: "2014-01-03T23:23:47.056795", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,073 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["s-3052-VM-2"]}
> 2014-01-03 15:23:47,079 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,080 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /instance-ips, {"instance-ip":{"instance_ip_address":"10.223.138.2","virtual_network_refs":[{"to":["default-domain","default-project","__default_Public__"],"attr":null,"href":null,"uuid":null}],"virtual_machine_interface_refs":[{"to":["s-3052-VM","s-3052-VM-2"],"attr":null,"href":null,"uuid":null}],"name":"s-3052-VM-2","fq_name":["s-3052-VM-2"]}}
> 2014-01-03 15:23:47,084 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 1 new host id: 1 host id before state transition: null
> 2014-01-03 15:23:47,087 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM starting again on the last host it was stopped on
> 2014-01-03 15:23:47,099 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:1
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 500 , Free CPU:8044 ,Requested CPU: 500
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 268435456 , Free RAM:15921714176 ,Requested RAM: 1073741824
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Reserved CPU: 500 , Requested CPU: 500
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Reserved RAM: 0 , Requested RAM: 1073741824
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 500, actual total: 9044, total with overprovisioning: 9044; new used:1000, reserved:500; requested cpu:500,alloc_from_last:true
> 2014-01-03 15:23:47,100 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 1, old used: 268435456, old reserved: 0, total: 16190149632; new used: 1342177280, reserved: 0; requested mem: 1073741824,alloc_from_last:true
> 2014-01-03 15:23:47,105 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 1
> 2014-01-03 15:23:47,108 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,108 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Create instance-ip uuid: e5394ddc-3c64-4a7a-84aa-c0c0871a79b5
> 2014-01-03 15:23:47,109 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /instance-ip/e5394ddc-3c64-4a7a-84aa-c0c0871a79b5
> 2014-01-03 15:23:47,113 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=200 is already implemented
> 2014-01-03 15:23:47,123 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,123 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1062, Etag: "2014-01-03T23:23:47.101849", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,129 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=202 is already implemented
> 2014-01-03 15:23:47,140 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to prepare for Nic[5-2-null-10.223.138.3]
> 2014-01-03 15:23:47,140 DEBUG [contrail.management.ContrailElement] (consoleproxy-1:null) NetworkElement prepare: null, traffic type: Public
> 2014-01-03 15:23:47,141 DEBUG [contrail.management.ContrailElement] (consoleproxy-1:null) network: 200
> 2014-01-03 15:23:47,146 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: PUT, /virtual-machine/c3a85f91-1a28-4691-8533-777da913d1bf, {"virtual-machine":{"virtual_machine_interfaces":[{"to":["v-2-VM","v-2-VM-2"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9","uuid":"62126b4a-a56c-4614-8a3e-28fb3e93a4b9"},{"to":["v-2-VM","v-2-VM-0"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183","uuid":"9d74dbb2-9ebf-402a-8020-9cdc9c728183"},{"to":["v-2-VM","v-2-VM-1"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/d1afd8fd-f9c6-4a3a-9b1d-cee78a4f3a53","uuid":"d1afd8fd-f9c6-4a3a-9b1d-cee78a4f3a53"}],"name":"v-2-VM","uuid":"c3a85f91-1a28-4691-8533-777da913d1bf","fq_name":["v-2-VM"]}}
> 2014-01-03 15:23:47,163 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,164 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9
> 2014-01-03 15:23:47,181 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,181 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to prepare for Nic[12192-3052-fcf22fde-9dbf-475d-9586-8b0c755087e1-169.254.2.126]
> 2014-01-03 15:23:47,181 DEBUG [contrail.management.ContrailElement] (secstorage-1:null) NetworkElement prepare: null, traffic type: Control
> 2014-01-03 15:23:47,181 DEBUG [contrail.management.ContrailElement] (secstorage-1:null) network: 202
> 2014-01-03 15:23:47,183 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: PUT, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["06:18:60:00:00:20"]},"virtual_network_refs":[{"to":["default-domain","default-project","__default_Public__"],"attr":null,"href":"http://127.0.0.1:8082/virtual-network/76fef243-4ade-491e-ba74-d69302e78cd3","uuid":"76fef243-4ade-491e-ba74-d69302e78cd3"}],"name":"v-2-VM-2","uuid":"62126b4a-a56c-4614-8a3e-28fb3e93a4b9","fq_name":["v-2-VM","v-2-VM-2"],"parent_type":"virtual-machine","parent_uuid":"c3a85f91-1a28-4691-8533-777da913d1bf"}}
> 2014-01-03 15:23:47,187 DEBUG [contrail.model.InstanceIpModel] (secstorage-1:null) vmiModel has 1 IP addresses
> 2014-01-03 15:23:47,199 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,199 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9
> 2014-01-03 15:23:47,206 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,207 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1685, Etag: "2014-01-03T23:23:47.196956", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,208 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["v-2-VM-2"]}
> 2014-01-03 15:23:47,218 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,218 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Data: {"uuid": "8161e983-d8d7-45eb-ac42-2db62391dabf"}
> 2014-01-03 15:23:47,218 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/8161e983-d8d7-45eb-ac42-2db62391dabf
> 2014-01-03 15:23:47,229 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,232 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/8161e983-d8d7-45eb-ac42-2db62391dabf
> 2014-01-03 15:23:47,242 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,242 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1050, Etag: "2013-12-26T21:53:15.239500", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,243 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: PUT, /virtual-machine/0f5bc126-9723-4585-adf8-225a049faf1a, {"virtual-machine":{"name":"s-3052-VM","uuid":"0f5bc126-9723-4585-adf8-225a049faf1a","fq_name":["s-3052-VM"]}}
> 2014-01-03 15:23:47,247 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
> 2014-01-03 15:23:47,258 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,258 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/1fa80370-6f3a-4bf6-a89c-a6bf3249ac69
> 2014-01-03 15:23:47,262 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,262 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /virtual-machine-interfaces, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["0e:00:a9:fe:02:7e"]},"virtual_network_refs":[{"to":["default-domain","default-project","__link_local__"],"attr":null,"href":null,"uuid":null}],"name":"s-3052-VM-0","uuid":"1fa80370-6f3a-4bf6-a89c-a6bf3249ac69","fq_name":["s-3052-VM","s-3052-VM-0"],"parent_type":"virtual-machine"}}
> 2014-01-03 15:23:47,276 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,277 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Create virtual-machine-interface uuid: 1fa80370-6f3a-4bf6-a89c-a6bf3249ac69
> 2014-01-03 15:23:47,277 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/1fa80370-6f3a-4bf6-a89c-a6bf3249ac69
> 2014-01-03 15:23:47,281 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,282 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1093, Etag: "2014-01-03T23:23:47.272755", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,283 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["s-3052-VM-0"]}
> 2014-01-03 15:23:47,287 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,288 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /instance-ips, {"instance-ip":{"instance_ip_address":"169.254.2.126","virtual_network_refs":[{"to":["default-domain","default-project","__link_local__"],"attr":null,"href":null,"uuid":null}],"virtual_machine_interface_refs":[{"to":["s-3052-VM","s-3052-VM-0"],"attr":null,"href":null,"uuid":null}],"name":"s-3052-VM-0","fq_name":["s-3052-VM-0"]}}
> 2014-01-03 15:23:47,293 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to prepare for Nic[6-2-0f42170e-c8e0-469e-b730-af34e7afcf55-169.254.0.237]
> 2014-01-03 15:23:47,293 DEBUG [contrail.management.ContrailElement] (consoleproxy-1:null) NetworkElement prepare: null, traffic type: Control
> 2014-01-03 15:23:47,293 DEBUG [contrail.management.ContrailElement] (consoleproxy-1:null) network: 202
> 2014-01-03 15:23:47,298 DEBUG [contrail.model.InstanceIpModel] (consoleproxy-1:null) vmiModel has 1 IP addresses
> 2014-01-03 15:23:47,301 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,302 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Create instance-ip uuid: e22875b6-9248-451a-9543-05feb723cae7
> 2014-01-03 15:23:47,302 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /instance-ip/e22875b6-9248-451a-9543-05feb723cae7
> 2014-01-03 15:23:47,307 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,307 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1060, Etag: "2014-01-03T23:23:47.296093", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,308 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/52038987-3f6e-4502-9233-b6f820c3eaf5
> 2014-01-03 15:23:47,322 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,324 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: PUT, /virtual-machine-interface/52038987-3f6e-4502-9233-b6f820c3eaf5, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["06:75:6a:00:00:1f"]},"virtual_network_refs":[{"to":["default-domain","default-project","__default_Public__"],"attr":null,"href":"http://127.0.0.1:8082/virtual-network/76fef243-4ade-491e-ba74-d69302e78cd3","uuid":"76fef243-4ade-491e-ba74-d69302e78cd3"}],"name":"s-3052-VM-2","uuid":"52038987-3f6e-4502-9233-b6f820c3eaf5","fq_name":["s-3052-VM","s-3052-VM-2"],"parent_type":"virtual-machine","parent_uuid":"0f5bc126-9723-4585-adf8-225a049faf1a"}}
> 2014-01-03 15:23:47,337 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,337 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/52038987-3f6e-4502-9233-b6f820c3eaf5
> 2014-01-03 15:23:47,345 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,345 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1698, Etag: "2014-01-03T23:23:47.333388", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,348 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["s-3052-VM-2"]}
> 2014-01-03 15:23:47,356 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,357 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) << Response Data: {"uuid": "e5394ddc-3c64-4a7a-84aa-c0c0871a79b5"}
> 2014-01-03 15:23:47,357 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /instance-ip/e5394ddc-3c64-4a7a-84aa-c0c0871a79b5
> 2014-01-03 15:23:47,370 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,371 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: PUT, /virtual-machine/c3a85f91-1a28-4691-8533-777da913d1bf, {"virtual-machine":{"virtual_machine_interfaces":[{"to":["v-2-VM","v-2-VM-2"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9","uuid":"62126b4a-a56c-4614-8a3e-28fb3e93a4b9"},{"to":["v-2-VM","v-2-VM-0"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183","uuid":"9d74dbb2-9ebf-402a-8020-9cdc9c728183"},{"to":["v-2-VM","v-2-VM-1"],"attr":null,"href":"http://127.0.0.1:8082/virtual-machine-interface/d1afd8fd-f9c6-4a3a-9b1d-cee78a4f3a53","uuid":"d1afd8fd-f9c6-4a3a-9b1d-cee78a4f3a53"}],"name":"v-2-VM","uuid":"c3a85f91-1a28-4691-8533-777da913d1bf","fq_name":["v-2-VM"]}}
> 2014-01-03 15:23:47,386 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,387 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9
> 2014-01-03 15:23:47,399 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,401 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: PUT, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["06:18:60:00:00:20"]},"virtual_network_refs":[{"to":["default-domain","default-project","__default_Public__"],"attr":null,"href":"http://127.0.0.1:8082/virtual-network/76fef243-4ade-491e-ba74-d69302e78cd3","uuid":"76fef243-4ade-491e-ba74-d69302e78cd3"}],"name":"v-2-VM-2","uuid":"62126b4a-a56c-4614-8a3e-28fb3e93a4b9","fq_name":["v-2-VM","v-2-VM-2"],"parent_type":"virtual-machine","parent_uuid":"c3a85f91-1a28-4691-8533-777da913d1bf"}}
> 2014-01-03 15:23:47,422 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,422 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/62126b4a-a56c-4614-8a3e-28fb3e93a4b9
> 2014-01-03 15:23:47,436 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,436 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1685, Etag: "2014-01-03T23:23:47.414378", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,438 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["v-2-VM-2"]}
> 2014-01-03 15:23:47,446 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,446 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Data: {"uuid": "8161e983-d8d7-45eb-ac42-2db62391dabf"}
> 2014-01-03 15:23:47,446 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/8161e983-d8d7-45eb-ac42-2db62391dabf
> 2014-01-03 15:23:47,455 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,456 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/8161e983-d8d7-45eb-ac42-2db62391dabf
> 2014-01-03 15:23:47,472 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,472 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1050, Etag: "2013-12-26T21:53:15.239500", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,473 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183
> 2014-01-03 15:23:47,477 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,478 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: POST, /virtual-machine-interfaces, {"virtual-machine-interface":{"virtual_machine_interface_mac_addresses":{"mac_address":["0e:00:a9:fe:00:ed"]},"virtual_network_refs":[{"to":["default-domain","default-project","__link_local__"],"attr":null,"href":null,"uuid":null}],"name":"v-2-VM-0","uuid":"9d74dbb2-9ebf-402a-8020-9cdc9c728183","fq_name":["v-2-VM","v-2-VM-0"],"parent_type":"virtual-machine"}}
> 2014-01-03 15:23:47,496 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,496 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Create virtual-machine-interface uuid: 9d74dbb2-9ebf-402a-8020-9cdc9c728183
> 2014-01-03 15:23:47,497 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183
> 2014-01-03 15:23:47,512 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,512 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1084, Etag: "2014-01-03T23:23:47.489703", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,514 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: POST, /fqname-to-id, {"type":"instance-ip","fq_name":["v-2-VM-0"]}
> 2014-01-03 15:23:47,518 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 404 Not Found
> 2014-01-03 15:23:47,518 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /instance-ip/e5394ddc-3c64-4a7a-84aa-c0c0871a79b5
> 2014-01-03 15:23:47,528 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,529 DEBUG [contrail.api.ApiConnector] (secstorage-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1062, Etag: "2014-01-03T23:23:47.101849", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,530 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: POST, /instance-ips, {"instance-ip":{"instance_ip_address":"169.254.0.237","virtual_network_refs":[{"to":["default-domain","default-project","__link_local__"],"attr":null,"href":null,"uuid":null}],"virtual_machine_interface_refs":[{"to":["v-2-VM","v-2-VM-0"],"attr":null,"href":null,"uuid":null}],"name":"v-2-VM-0","fq_name":["v-2-VM-0"]}}
> 2014-01-03 15:23:47,535 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Network id=201 is already implemented
> 2014-01-03 15:23:47,549 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,550 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Create instance-ip uuid: 28d6c792-85a2-4c61-88a1-b8d576b09114
> 2014-01-03 15:23:47,550 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/28d6c792-85a2-4c61-88a1-b8d576b09114
> 2014-01-03 15:23:47,562 DEBUG [db.Transaction.Transaction] (secstorage-1:null) Rolling back the transaction: Time = 2 Name = -SystemVmLoadScanner$1.run:70-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:293-ThreadPoolExecutor.runWorker:1145-ThreadPoolExecutor$Worker.run:615-Thread.run:724; called by -Transaction.rollback:898-DataCenterIpAddressDaoImpl.takeIpAddress:59-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-DataCenterDaoImpl.allocatePrivateIpAddress:248-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-PodBasedNetworkGuru.reserve:119-NetworkManagerImpl.prepareNic:2157-NetworkManagerImpl.prepare:2127-VirtualMachineManagerImpl.advanceStart:886-VirtualMachineManagerImpl.start:578-VirtualMachineManagerImpl.start:571-SecondaryStorageManagerImpl.startSecStorageVm:267
> 2014-01-03 15:23:47,563 INFO [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Insufficient capacity
> com.cloud.exception.InsufficientAddressCapacityException: Unable to get a management ip addressScope=interface com.cloud.dc.Pod; id=1
> at com.cloud.network.guru.PodBasedNetworkGuru.reserve(PodBasedNetworkGuru.java:121)
> at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2157)
> at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2127)
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:886)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-01-03 15:23:47,567 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,567 DEBUG [contrail.api.ApiConnector] (consoleproxy-1:null) Response: HTTP/1.1 200 OK [Content-Length: 1046, Etag: "2014-01-03T23:23:47.540171", Content-Type: application/json, Date: Fri, 03 Jan 2014 23:23:47 GMT]
> 2014-01-03 15:23:47,571 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-3052-VM] in Starting state
> 2014-01-03 15:23:47,573 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
> 2014-01-03 15:23:47,573 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-477823133: Sending { Cmd , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-3052-VM","wait":0}}] }
> 2014-01-03 15:23:47,574 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-477823133: Executing: { Cmd , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-3052-VM","wait":0}}] }
> 2014-01-03 15:23:47,575 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-358:null) Seq 1-477823133: Executing request
> 2014-01-03 15:23:47,613 DEBUG [db.Transaction.Transaction] (consoleproxy-1:null) Rolling back the transaction: Time = 1 Name = -SystemVmLoadScanner$1.run:70-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:293-ThreadPoolExecutor.runWorker:1145-ThreadPoolExecutor$Worker.run:615-Thread.run:724; called by -Transaction.rollback:898-DataCenterIpAddressDaoImpl.takeIpAddress:59-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-DataCenterDaoImpl.allocatePrivateIpAddress:248-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-PodBasedNetworkGuru.reserve:119-NetworkManagerImpl.prepareNic:2157-NetworkManagerImpl.prepare:2127-VirtualMachineManagerImpl.advanceStart:886-VirtualMachineManagerImpl.start:578-VirtualMachineManagerImpl.start:571-ConsoleProxyManagerImpl.startProxy:556
> 2014-01-03 15:23:47,614 INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Insufficient capacity
> com.cloud.exception.InsufficientAddressCapacityException: Unable to get a management ip addressScope=interface com.cloud.dc.Pod; id=1
> at com.cloud.network.guru.PodBasedNetworkGuru.reserve(PodBasedNetworkGuru.java:121)
> at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2157)
> at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2127)
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:886)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:928)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1672)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-01-03 15:23:47,618 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
> 2014-01-03 15:23:47,621 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-477823134: Waiting for Seq 477823133 Scheduling: { Cmd , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"v-2-VM","wait":0}}] }
> 2014-01-03 15:23:47,672 INFO [xen.resource.CitrixResourceBase] (DirectAgent-358:null) VM does not exist on XenServerd95f29d2-e140-4481-a055-1aebc3b30420
> 2014-01-03 15:23:47,673 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-358:null) Seq 1-477823133: Response Received:
> 2014-01-03 15:23:47,673 DEBUG [agent.transport.Request] (DirectAgent-358:null) Seq 1-477823133: Processing: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
> 2014-01-03 15:23:47,673 DEBUG [agent.manager.AgentAttache] (DirectAgent-358:null) Seq 1-477823134: Sending now. is current sequence.
> 2014-01-03 15:23:47,673 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-477823133: Received: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
> 2014-01-03 15:23:47,673 DEBUG [agent.transport.Request] (DirectAgent-358:null) Seq 1-477823134: Executing: { Cmd , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"v-2-VM","wait":0}}] }
> 2014-01-03 15:23:47,673 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-358:null) Seq 1-477823134: Executing request
> 2014-01-03 15:23:47,684 DEBUG [network.guru.ControlNetworkGuru] (secstorage-1:null) Released nic: NicProfile[12192-3052-null-null-null
> 2014-01-03 15:23:47,691 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to release Nic[12192-3052-fcf22fde-9dbf-475d-9586-8b0c755087e1-null]
> 2014-01-03 15:23:47,695 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /instance-ip/e22875b6-9248-451a-9543-05feb723cae7
> 2014-01-03 15:23:47,701 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,702 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: DELETE, /instance-ip/e22875b6-9248-451a-9543-05feb723cae7
> 2014-01-03 15:23:47,712 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,712 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: GET, /virtual-machine-interface/1fa80370-6f3a-4bf6-a89c-a6bf3249ac69
> 2014-01-03 15:23:47,719 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,720 INFO [contrail.api.ApiConnector] (secstorage-1:null) >> Request: DELETE, /virtual-machine-interface/1fa80370-6f3a-4bf6-a89c-a6bf3249ac69
> 2014-01-03 15:23:47,731 INFO [contrail.api.ApiConnector] (secstorage-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,737 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=fcf22fde-9dbf-475d-9586-8b0c755087e1, instance=12193
> 2014-01-03 15:23:47,738 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[12193-3052-null-null-null
> 2014-01-03 15:23:47,755 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to release Nic[12193-3052-fcf22fde-9dbf-475d-9586-8b0c755087e1-null]
> 2014-01-03 15:23:47,761 INFO [xen.resource.CitrixResourceBase] (DirectAgent-358:null) VM does not exist on XenServerd95f29d2-e140-4481-a055-1aebc3b30420
> 2014-01-03 15:23:47,761 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-358:null) Seq 1-477823134: Response Received:
> 2014-01-03 15:23:47,761 DEBUG [agent.transport.Request] (DirectAgent-358:null) Seq 1-477823134: Processing: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] }
> 2014-01-03 15:23:47,761 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-477823134: Received: { Ans: , MgmtId: 86780043846508, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
> 2014-01-03 15:23:47,762 DEBUG [agent.manager.AgentAttache] (DirectAgent-358:null) Seq 1-477823134: No more commands found
> 2014-01-03 15:23:47,765 DEBUG [db.Transaction.Transaction] (secstorage-1:null) Rolling back the transaction: Time = 2 Name = -SystemVmLoadScanner$1.run:70-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:293-ThreadPoolExecutor.runWorker:1145-ThreadPoolExecutor$Worker.run:615-Thread.run:724; called by -Transaction.rollback:898-Transaction.removeUpTo:841-Transaction.close:665-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:2385-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.cleanup:1123-VirtualMachineManagerImpl.advanceStart:995-VirtualMachineManagerImpl.start:578-VirtualMachineManagerImpl.start:571-SecondaryStorageManagerImpl.startSecStorageVm:267
> 2014-01-03 15:23:47,766 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully released network resources for the vm VM[SecondaryStorageVm|s-3052-VM]
> 2014-01-03 15:23:47,766 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-3052-VM] in Starting state
> 2014-01-03 15:23:47,768 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Deploy avoids pods: [1], clusters: null, hosts: [1]
> 2014-01-03 15:23:47,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_2f3b9de3@3d4e8624
> 2014-01-03 15:23:47,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
> 2014-01-03 15:23:47,771 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
> 2014-01-03 15:23:47,771 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching all possible resources under this Zone: 1
> 2014-01-03 15:23:47,772 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2014-01-03 15:23:47,774 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[6-2-null-null-null
> 2014-01-03 15:23:47,780 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Checking resources in Cluster: 1 under Pod: 1
> 2014-01-03 15:23:47,780 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to release Nic[6-2-0f42170e-c8e0-469e-b730-af34e7afcf55-null]
> 2014-01-03 15:23:47,780 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2014-01-03 15:23:47,784 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2014-01-03 15:23:47,785 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /instance-ip/28d6c792-85a2-4c61-88a1-b8d576b09114
> 2014-01-03 15:23:47,790 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2014-01-03 15:23:47,790 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=256
> 2014-01-03 15:23:47,790 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host name: xenserver-contrail, hostId: 1 is in avoid set, skipping this and trying other available hosts
> 2014-01-03 15:23:47,791 DEBUG [allocator.impl.FirstFitAllocator] (secstorage-1:FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
> 2014-01-03 15:23:47,791 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) No suitable hosts found
> 2014-01-03 15:23:47,791 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) No suitable hosts found under this Cluster: 1
> 2014-01-03 15:23:47,794 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,795 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: DELETE, /instance-ip/28d6c792-85a2-4c61-88a1-b8d576b09114
> 2014-01-03 15:23:47,795 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (secstorage-1:null) Could not find suitable Deployment Destination for this VM under any clusters, returning.
> 2014-01-03 15:23:47,796 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Searching all possible resources under this Zone: 1
> 2014-01-03 15:23:47,797 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2014-01-03 15:23:47,801 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) Removing from the clusterId list these clusters from avoid set: [1]
> 2014-01-03 15:23:47,801 DEBUG [cloud.deploy.FirstFitPlanner] (secstorage-1:null) No clusters found after removing disabled clusters and clusters in avoid list, returning.
> 2014-01-03 15:23:47,807 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,807 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: GET, /virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183
> 2014-01-03 15:23:47,813 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,815 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) >> Request: DELETE, /virtual-machine-interface/9d74dbb2-9ebf-402a-8020-9cdc9c728183
> 2014-01-03 15:23:47,823 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) 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
> 2014-01-03 15:23:47,830 INFO [contrail.api.ApiConnector] (consoleproxy-1:null) << Response Status: HTTP/1.1 200 OK
> 2014-01-03 15:23:47,834 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,834 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total RAM: 16190149248 and RAM after applying overprovisioning: 16190149632
> 2014-01-03 15:23:47,834 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release cpu from host: 1, old used: 1000,reserved: 500, actual total: 9044, total with overprovisioning: 9044; new used: 500,reserved:500; movedfromreserved: false,moveToReserveredfalse
> 2014-01-03 15:23:47,834 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 1, old used: 1342177280,reserved: 0, total: 16190149632; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2014-01-03 15:23:47,838 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=0f42170e-c8e0-469e-b730-af34e7afcf55, instance=7
> 2014-01-03 15:23:47,839 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[7-2-null-null-null
> 2014-01-03 15:23:47,846 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ContrailElementImpl_EnhancerByCloudStack_a60033ba to release Nic[7-2-0f42170e-c8e0-469e-b730-af34e7afcf55-null]
> 2014-01-03 15:23:47,850 WARN [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-3052-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-01-03 15:23:47,854 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 3052, will recycle it and start a new one
> 2014-01-03 15:23:47,855 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
> 2014-01-03 15:23:47,860 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-2-VM]
> 2014-01-03 15:23:47,861 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
> 2014-01-03 15:23:47,872 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster
> 2014-01-03 15:23:47,872 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[2|vm=2|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
> 2014-01-03 15:23:47,874 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: [1], clusters: null, hosts: [1]
> 2014-01-03 15:23:47,876 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_2f3b9de3@3d4e8624
> 2014-01-03 15:23:47,876 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 1073741824
> 2014-01-03 15:23:47,876 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes
> 2014-01-03 15:23:47,876 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) This VM has last host_id specified, trying to choose the same host: 1
> 2014-01-03 15:23:47,878 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) The last host of this VM is in avoid set
> 2014-01-03 15:23:47,878 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Cannot choose the last host to deploy this VM
> 2014-01-03 15:23:47,878 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Cluster: 1
> 2014-01-03 15:23:47,879 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) The specified cluster is in avoid set, returning.
> 2014-01-03 15:23:47,880 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: [1], clusters: null, hosts: [1]
> 2014-01-03 15:23:47,881 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_2f3b9de3@3d4e8624
> 2014-01-03 15:23:47,882 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 1073741824
> 2014-01-03 15:23:47,882 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: No
> 2014-01-03 15:23:47,882 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) This VM has last host_id specified, trying to choose the same host: 1
> 2014-01-03 15:23:47,884 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) The last host of this VM is in avoid set
> 2014-01-03 15:23:47,884 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Cannot choose the last host to deploy this VM
> 2014-01-03 15:23:47,884 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching resources only under specified Pod: 1
> 2014-01-03 15:23:47,884 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) The specified pod is in avoid set, returning.
> 2014-01-03 15:23:47,904 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 1 new host id: null host id before state transition: 1
> 2014-01-03 15:23:47,910 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 9044 and CPU after applying overprovisioning: 9044
> 2014-01-03 15:23:47,910 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total RAM: 16190149248 and RAM after applying overprovisioning: 16190149632
> 2014-01-03 15:23:47,911 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 500, actual total: 9044, total with overprovisioning: 9044; new used: 0,reserved:500; movedfromreserved: false,moveToReserveredfalse
> 2014-01-03 15:23:47,911 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 16190149632; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2014-01-03 15:23:47,914 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:928)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1672)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-01-03 15:23:49,260 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running...
> 2014-01-03 15:23:49,575 DEBUG [cloud.network.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running...
> 2014-01-03 15:23:49,685 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
> 2014-01-03 15:23:49,694 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2014-01-03 15:23:49,695 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2014-01-03 15:23:49,725 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers.
> 2014-01-03 15:23:49,725 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2014-01-03 15:23:49,726 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2014-01-03 15:23:49,909 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2014-01-03 23:23:49 GMT
> 2014-01-03 15:23:49,910 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2014-01-03 23:23:49 GMT
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)