cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Parth Jagirdar (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-5778) Contrail:MS: Restart Xen host results in failure to start System VM's and Guest VM's
Date Fri, 03 Jan 2014 23:32:50 GMT
Parth Jagirdar created CLOUDSTACK-5778:
------------------------------------------

             Summary: 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


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)

Mime
View raw message