把二级存储重新挂上

> On Nov 27, 2014, at 10:15 AM, xusz <xusz@chinanetcenter.com> wrote:
> 
> 
> 
> 
> 
> 
> 
> HI ALL 
> 
> 上次在平台上删除了二级存储，发现模板里面虚拟机的镜像都变成打X状态，现在启动
> 虚拟机的时候都不能起来，求助大家排查是什么问题。谢谢
> 
> 
> 
> 
> 
> 14-11-27 10:11:33,089 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (HA-Worker-1:work-14354) Deploy avoids pods: null, clusters: null, hosts:
> null
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (HA-Worker-1:work-14354) Root volume is ready, need to place VM in volume's
> cluster
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (HA-Worker-1:work-14354) Vol[7333|vm=7162|ROOT] is READY, changing
> deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 10
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) DeploymentPlanner allocation algorithm: random
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Trying to allocate a host and storage pools from
> dc:1, pod:1,cluster:10, requested cpu: 2000, requested ram: 2147483648
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Is ROOT volume READY (pool already allocated)?: Yes
> 
> 2014-11-27 10:11:33,091 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) This VM has last host_id specified, trying to
> choose the same host: 89
> 
> 2014-11-27 10:11:33,094 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Checking if host: 89 has enough capacity for
> requested CPU: 2000 and requested RAM: 2147483648 ,
> cpuOverprovisioningFactor: 2.0
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Hosts's actual total CPU: 36256 and CPU after
> applying overprovisioning: 72512
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) We need to allocate to the last host again, so
> checking if there is enough reserved capacity
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) We need to allocate to the last host again, so
> checking if there is enough reserved capacity
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Reserved CPU: 0 , Requested CPU: 2000
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Reserved CPU: 0 , Requested CPU: 2000
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Reserved RAM: 0 , Requested RAM: 2147483648
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) STATS: Failed to alloc resource from host: 89
> reservedCpu: 0, requested cpu: 2000, reservedMem: 0, requested mem:
> 2147483648
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Host does not have enough reserved CPU available,
> cannot allocate to this host.
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) The last host of this VM does not have enough
> capacity
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Cannot choose the last host to deploy this VM 
> 
> 2014-11-27 10:11:33,096 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Searching resources only under specified Cluster:
> 10
> 
> 2014-11-27 10:11:33,100 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Checking resources in Cluster: 10 under Pod: 1
> 
> 2014-11-27 10:11:33,100 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Calling HostAllocators to find suitable hosts
> 
> 2014-11-27 10:11:33,100 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Looking for hosts in dc: 1
> pod:1  cluster:10
> 
> 2014-11-27 10:11:33,101 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) FirstFitAllocator has 1
> hosts to check for allocation: [Host[-89-Routing]]
> 
> 2014-11-27 10:11:33,102 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Found 1 hosts for
> allocation after prioritization: [Host[-89-Routing]]
> 
> 2014-11-27 10:11:33,102 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Looking for speed=2000Mhz,
> Ram=2048
> 
> 2014-11-27 10:11:33,104 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Checking if host: 89 has
> enough capacity for requested CPU: 2000 and requested RAM: 2147483648 ,
> cpuOverprovisioningFactor: 2.0
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Hosts's actual total CPU:
> 36256 and CPU after applying overprovisioning: 72512
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Free CPU: 54512 ,
> Requested CPU: 2000
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Free RAM: 5816790400 ,
> Requested RAM: 2147483648
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Host has enough CPU and
> RAM available
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) STATS: Can alloc CPU from
> host: 89, used: 18000, reserved: 0, actual total: 36256, total with
> overprovisioning: 72512; requested cpu:2000,alloc_from_last_host?:false
> ,considerReservedCapacity?: true
> 
> 2014-11-27 10:11:33,105 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) STATS: Can alloc MEM from
> host: 89, used: 18656264192, reserved: 0, total: 24473054592; requested mem:
> 2147483648,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 
> 2014-11-27 10:11:33,105 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Found a suitable host,
> adding to list: 89
> 
> 2014-11-27 10:11:33,105 DEBUG [allocator.impl.FirstFitAllocator]
> (HA-Worker-1:work-14354 FirstFitRoutingAllocator) Host Allocator returning 1
> suitable hosts
> 
> 2014-11-27 10:11:33,106 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Checking suitable pools for volume (Id, Type):
> (7333,ROOT)
> 
> 2014-11-27 10:11:33,106 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Volume is in READY state and has pool already
> allocated, checking if pool can be reused, poolId: 514
> 
> 2014-11-27 10:11:33,107 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Planner need not allocate a pool for this volume
> since its READY
> 
> 2014-11-27 10:11:33,107 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Trying to find a potenial host and associated
> storage pools from the suitable host/pool lists for this VM
> 
> 2014-11-27 10:11:33,107 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Checking if host: 89 can access any suitable
> storage pool for volume: ROOT
> 
> 2014-11-27 10:11:33,108 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Host: 89 can access pool: 514
> 
> 2014-11-27 10:11:33,108 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Found a potential host id: 89 name: xenserver203
> and associated storage pools for this VM
> 
> 2014-11-27 10:11:33,109 DEBUG [cloud.deploy.FirstFitPlanner]
> (HA-Worker-1:work-14354) Returning Deployment Destination:
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id)
> )] : Dest[Zone(1)-Pod(1)-Cluster(10)-Host(89)-Storage()]
> 
> 2014-11-27 10:11:33,109 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (HA-Worker-1:work-14354) Deployment found  -
> P0=VM[User|9ef850c6-d899-4080-b7fc-af9b39125408],
> P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(
> Id))] : Dest[Zone(1)-Pod(1)-Cluster(10)-Host(89)-Storage()]
> 
> 2014-11-27 10:11:33,153 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) VM state transitted from :Starting to Starting with
> event: OperationRetryvm's original host id: 89 new host id: 89 host id
> before state transition: null
> 
> 2014-11-27 10:11:33,154 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) VM starting again on the last host it was stopped
> on
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Hosts's actual total CPU: 36256 and CPU after
> applying overprovisioning: 72512
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) We are allocating VM, increasing the used capacity
> of this host:89
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) We are allocating VM, increasing the used capacity
> of this host:89
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Current Used CPU: 18000 , Free CPU:54512 ,Requested
> CPU: 2000
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Current Used RAM: 18656264192 , Free RAM:5816790400
> ,Requested RAM: 2147483648
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) We are allocating VM to the last host again, so
> adjusting the reserved capacity if it is not less than required
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Reserved CPU: 0 , Requested CPU: 2000
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) Reserved RAM: 0 , Requested RAM: 2147483648
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) CPU STATS after allocation: for host: 89, old used:
> 18000, old reserved: 0, actual total: 36256, total with overprovisioning:
> 72512; new used:20000, reserved:0; requested cpu:2000,alloc_from_last:true
> 
> 2014-11-27 10:11:33,157 DEBUG [cloud.capacity.CapacityManagerImpl]
> (HA-Worker-1:work-14354) RAM STATS after allocation: for host: 89, old used:
> 18656264192, old reserved: 0, total: 24473054592; new used: 20803747840,
> reserved: 0; requested mem: 2147483648,alloc_from_last:true
> 
> 2014-11-27 10:11:33,188 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (HA-Worker-1:work-14354) VM is being created in podId: 1
> 
> 2014-11-27 10:11:33,191 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Lock is acquired for network id 204 as a part of
> network implement
> 
> 2014-11-27 10:11:33,191 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Network id=204 is already implemented
> 
> 2014-11-27 10:11:33,191 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Lock is released for network id 204 as a part of
> network implement
> 
> 2014-11-27 10:11:33,226 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Changing active number of nics for network id=204
> on 1
> 
> 2014-11-27 10:11:33,249 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Asking JuniperSRX to prepare for
> Nic[26254-7162-b817996e-d3f0-4e62-b6e5-3bef8ca02848-192.168.3.246]
> 
> 2014-11-27 10:11:33,251 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Asking Netscaler to prepare for
> Nic[26254-7162-b817996e-d3f0-4e62-b6e5-3bef8ca02848-192.168.3.246]
> 
> 2014-11-27 10:11:33,252 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Asking F5BigIP to prepare for
> Nic[26254-7162-b817996e-d3f0-4e62-b6e5-3bef8ca02848-192.168.3.246]
> 
> 2014-11-27 10:11:33,254 DEBUG [cloud.network.NetworkManagerImpl]
> (HA-Worker-1:work-14354) Asking VirtualRouter to prepare for
> Nic[26254-7162-b817996e-d3f0-4e62-b6e5-3bef8ca02848-192.168.3.246]
> 
> 2014-11-27 10:11:33,462 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (HA-Worker-1:work-14354)
> Lock is acquired for network id 204 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id)
> )] : Dest[Zone(1)-Pod(1)-Cluster(10)-Host(89)-Storage()]
> 
> 2014-11-27 10:11:33,465 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (HA-Worker-1:work-14354)
> Lock is released for network id 204 as a part of router startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id)
> )] : Dest[Zone(1)-Pod(1)-Cluster(10)-Host(89)-Storage()]
> 
> 2014-11-27 10:11:33,472 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl] (HA-Worker-1:work-14354)
> Applying dhcp entry in network Ntwk[204|Guest|6]
> 
> 2014-11-27 10:11:33,486 DEBUG [agent.manager.ClusteredAgentAttache]
> (HA-Worker-1:work-14354) Seq 89-2067791929: Forwarding Seq 89-2067791929:  {
> Cmd , MgmtId: 110480925280, via: 89, Ver: v1, Flags: 100111,
> [{"routing.DhcpEntryCommand":{"vmMac":"06:57:b0:00:00:79","vmIpAddress":"192
> .168.3.246","vmName":"9ef850c6-d899-4080-b7fc-af9b39125408","defaultRouter":
> "192.168.3.51","defaultDns":"192.168.3.172","accessDetails":{"router.guest.i
> p":"192.168.3.172","zone.network.type":"Basic","router.name":"r-7170-VM","ro
> uter.ip":"169.254.1.106"},"wait":0}}] } to 165036460088
> 
> 2014-11-27 10:11:43,397 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone
> host is ready, but secondary storage vm template: 1 is not ready on
> secondary storage: 27
> 
> 2014-11-27 10:11:43,397 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is not ready to launch secondary storage VM yet
> 
> 2014-11-27 10:11:47,741 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers. 
> 
> 2014-11-27 10:11:53,388 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-332:null) Ping from 76
> 
> 2014-11-27 10:11:53,396 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-31:null) Ping from 43
> 
> 2014-11-27 10:11:54,182 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-303:null) Seq 76-2043346946: Executing request
> 
> 2014-11-27 10:11:54,340 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-404:null) Seq 43-396689410: Executing request
> 
> 2014-11-27 10:11:54,654 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-303:null) Seq 76-2043346946: Response Received: 
> 
> 2014-11-27 10:11:54,655 DEBUG [agent.transport.Request]
> (DirectAgent-303:null) Seq 76-2043346946: Processing:  { Ans: , MgmtId:
> 110480925280, via: 76, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":4,"_newStates":{},"_isExecuted":false,"r
> esult":true,"wait":0}}] }
> 
> 2014-11-27 10:11:54,919 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-404:null) Seq 43-396689410: Response Received: 
> 
> 2014-11-27 10:11:54,919 DEBUG [agent.transport.Request]
> (DirectAgent-404:null) Seq 43-396689410: Processing:  { Ans: , MgmtId:
> 110480925280, via: 43, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"r
> esult":true,"wait":0}}] }
> 
> 2014-11-27 10:12:13,397 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is ready to launch secondary storage VM
> 
> 2014-11-27 10:12:17,741 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers. 
> 
> 2014-11-27 10:12:43,396 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone
> host is ready, but secondary storage vm template: 1 is not ready on
> secondary storage: 95
> 
> 2014-11-27 10:12:43,397 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is not ready to launch secondary storage VM yet
> 
> 2014-11-27 10:12:43,397 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is not ready to launch secondary storage VM yet
> 
> 2014-11-27 10:12:47,741 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers. 
> 
> 2014-11-27 10:12:53,388 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-201:null) Ping from 43
> 
> 2014-11-27 10:12:53,388 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-250:null) Ping from 76
> 
> 2014-11-27 10:12:53,388 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-250:null) Ping from 76
> 
> 2014-11-27 10:12:54,182 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-36:null) Seq 76-2043346946: Executing request
> 
> 2014-11-27 10:12:54,339 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-250:null) Seq 43-396689410: Executing request
> 
> 2014-11-27 10:12:54,654 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-36:null) Seq 76-2043346946: Response Received: 
> 
> 2014-11-27 10:12:54,655 DEBUG [agent.transport.Request]
> (DirectAgent-36:null) Seq 76-2043346946: Processing:  { Ans: , MgmtId:
> 110480925280, via: 76, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":4,"_newStates":{},"_isExecuted":false,"r
> esult":true,"wait":0}}] }
> 
> 2014-11-27 10:12:54,906 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-250:null) Seq 43-396689410: Response Received: 
> 
> 2014-11-27 10:12:54,906 DEBUG [agent.transport.Request]
> (DirectAgent-250:null) Seq 43-396689410: Processing:  { Ans: , MgmtId:
> 110480925280, via: 43, Ver: v1, Flags: 10,
> [{"ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"r
> esult":true,"wait":0}}] }
> 
> 2014-11-27 10:13:13,396 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone
> host is ready, but secondary storage vm template: 1 is not ready on
> secondary storage: 8
> 
> 2014-11-27 10:13:13,396 DEBUG
> [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
> is not ready to launch secondary storage VM yet
> 
> aryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch
> secondary storage VM yet
> 
> 2014-11-27 10:13:17,741 DEBUG
> [network.router.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:null) Found 0 routers.
> 
> 
> 
> 
> 
>