You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Abhinandan Prateek (JIRA)" <ji...@apache.org> on 2013/07/24 12:35:48 UTC
[jira] [Commented] (CLOUDSTACK-3732) vm deployement fails in
vmware cluster;Mismatch in storage pool Pool[1|NetworkFilesystem] assigned
by deploymentPlanner and the one associated d with volume
Vol[16|vm=13|ROOT]
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3732?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13718209#comment-13718209 ]
Abhinandan Prateek commented on CLOUDSTACK-3732:
------------------------------------------------
Can we check if copy volume works for VMWare in general ?
> vm deployement fails in vmware cluster;Mismatch in storage pool Pool[1|NetworkFilesystem] assigned by deploymentPlanner and the one associated d with volume Vol[16|vm=13|ROOT]
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-3732
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3732
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Management Server
> Affects Versions: 4.2.0
> Environment: vmware ; branch 4.2
> Reporter: prashant kumar mishra
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: Logs_DB.rar
>
>
> Steps to reproduce
> ------------------------------
> 1-prepare CS setup ->one cluster (cl1)->one esxi5.1->one primary storage(primary) -->one secondary storage
> 2-deploy a vm
> 3-add another cluster say cl2 --> with esxi4.1 host ,vcenter server 5.1-->with one primary storage(primary2)
> 4-disable cluster 1(cl1)
> 5-deploy a vm with new network and small SO
> expected
> --------------
> VM should come up successfully
> actual
> ----------
> VR is coming up in disabled cluster and user vm deployment failing
> My observation
> ==============
> while deployment of VR
> ------------------------------------
> 1-primary2 unreachable
> 013-07-23 10:53:36,839 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Unable to create Vol[17|vm=14|ROOT]:Unable to execute PrimaryStorageDownloadCommand due to exception
> 2013-07-23 10:53:36,839 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Unable to contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:2] is unreachable: Unable to create Vol[17|vm=14|ROOT]:Unable to execute PrimaryStorageDownloadCommand due to exception
> 2-Even cluster one (cl1) is in disable state deployment planner chose cl1 for VR
> Checking resources in Cluster: 3 under Pod: 1
> 2013-07-23 10:53:37,029 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:3
> 2013-07-23 10:53:37,036 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-6-Routing]]
> 2013-07-23 10:53:37,043 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-6-Routing]]
> 2013-07-23 10:53:37,043 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=128
> 2013-07-23 10:53:37,043 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Host name: 10.147.40.8, hostId: 6 is in avoid set, skipping this and trying other available hosts
> 2013-07-23 10:53:37,043 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
> 2013-07-23 10:53:37,043 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) No suitable hosts found
> 2013-07-23 10:53:37,043 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) No suitable hosts found under this Cluster: 3
> 2013-07-23 10:53:37,052 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Checking resources in Cluster: 2 under Pod: 1
> 2013-07-23 10:53:37,052 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:2
> 2013-07-23 10:53:37,059 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2013-07-23 10:53:37,065 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2013-07-23 10:53:37,065 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=128
> 3-
> 2013-07-23 10:53:37,171 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Deployment found - P0=VM[DomainRouter|r-14-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(2)-Host(1)-Storage(Volume(17|ROOT-->Pool(1))]
> User VM
> --------------
> 1-
> 013-07-23 10:57:17,765 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_faaee9c4@aed41bc
> 2013-07-23 10:57:17,766 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:3, requested cpu: 500, requested ram: 536870912
> 2013-07-23 10:57:17,766 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Is ROOT volume READY (pool already allocated)?: Yes
> 2013-07-23 10:57:17,766 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Searching resources only under specified Cluster: 3
> 2013-07-23 10:57:17,788 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Checking resources in Cluster: 3 under Pod: 1
> 2013-07-23 10:57:17,789 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:3
> 2013-07-23 10:57:17,796 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-6-Routing]]
> 2013-07-23 10:57:17,802 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-6-Routing]]
> 2013-07-23 10:57:17,802 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
> 2013-07-23 10:57:17,802 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Host name: 10.147.40.8, hostId: 6 is in avoid set, skipping this and trying other available hosts
> 2013-07-23 10:57:17,802 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ] FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
> 2013-07-23 10:57:17,803 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) No suitable hosts found
> 2013-07-23 10:57:17,803 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) No suitable hosts found under this Cluster: 3
> 2013-07-23 10:57:17,809 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Could not find suitable Deployment Destination for this VM under any clusters, returning.
> 2013-07-23 10:57:17,810 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Searching resources only under specified Cluster: 3
> 2013-07-23 10:57:17,812 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) The specified cluster is in avoid set, returning.
> 2013-07-23 10:57:17,835 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Deploy avoids pods: null, clusters: [3], hosts: [6]
> 2013-07-23 10:57:17,837 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_faaee9c4@aed41bc
> 2013-07-23 10:57:17,837 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
> 2-Asking VirtualRouter to prepare for Nic[30-13-c18b2f60-c507-4da4-827e-78a5ffb8058c-10.1.1.220]
> 2013-07-23 10:57:18,152 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Lock is acquired for network id 205 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(2)-Host(1)-Storage(Volume(16|ROOT-->Pool(1))]
> 3-migrate volume initiated because of mismatch and it picked wrong PS(primary2) for copying volume to secondary storage
> 2013-07-23 10:57:21,572 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Checking if we need to prepare 1 volumes for VM[User|newvm]
> 2013-07-23 10:57:21,575 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Mismatch in storage pool Pool[1|NetworkFilesystem] assigned by deploymentPlanner and the one associated with volume Vol[16|vm=13|ROOT]
> 2013-07-23 10:57:21,575 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Shared volume Vol[16|vm=13|ROOT] will be migrated on storage pool Pool[1|NetworkFilesystem] assigned by deploymentPlanner
> 2013-07-23 10:57:21,643 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) copyAsync inspecting src type VOLUME copyAsync inspecting dest type VOLUME
> 2013-07-23 10:57:21,645 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 10.252.192.53 -- GET command=listRouters&listAll=true&page=1&pagesize=20&response=json&sessionkey=F8Cw9e7dmEvSRFlZRi1DKxUgHPQ%3D&_=1374571988383
> 2013-07-23 10:57:21,660 DEBUG [cache.allocator.StorageCacheRandomAllocator] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Can't find cache storage in zone: 1
> 2013-07-23 10:57:21,708 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 10.252.192.53 -- GET command=listRouters&listAll=true&page=1&pagesize=20&response=json&sessionkey=F8Cw9e7dmEvSRFlZRi1DKxUgHPQ%3D&_=1374571988383
> 2013-07-23 10:57:21,770 DEBUG [agent.manager.AgentAttache] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Request seq: 1718157356
> 2013-07-23 10:57:21,771 DEBUG [agent.manager.AgentAttache] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) waiting to send 1718157356
> 2013-07-23 10:57:21,771 DEBUG [agent.manager.AgentAttache] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) entering synchronize block for sending 1718157356
> 2013-07-23 10:57:21,773 DEBUG [agent.transport.Request] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Seq 5-1718157356: Sending { Cmd , MgmtId: 7635042566263, via: 5, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a3ac26fc-92da-476c-8e45-c2421e24e041","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bd186911-97af-371a-9b26-fac999fc98a4","id":2,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/prashant/primary2","port":2049}},"name":"ROOT-13","size":0,"path":"ROOT-13-16","volumeId":16,"vmName":"i-2-13-VM","accountId":2,"format":"OVA","id":16}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a3ac26fc-92da-476c-8e45-c2421e24e041","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/prashant/secondary.4.2.vmware","_role":"Image"}},"name":"ROOT-13","size":0,"path":"volumes/2/16","volumeId":16,"vmName":"i-2-13-VM","accountId":2,"format":"OVA","id":16}},"executeInSequence":false,"wait":10800}}] }
> 2013-07-23 10:57:21,792 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 10.252.192.53 -- GET command=listRouters&listAll=true&page=1&pagesize=20&projectid=-1&response=json&sessionkey=F8Cw9e7dmEvSRFlZRi1DKxUgHPQ%3D&_=1374571988599
> 2013-07-23 10:57:21,811 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 10.252.192.53 -- GET command=listRouters&listAll=true&page=1&pagesize=20&projectid=-1&response=json&sessionkey=F8Cw9e7dmEvSRFlZRi1DKxUgHPQ%3D&_=1374571988599
> 2013-07-23 10:57:21,818 DEBUG [agent.transport.Request] (AgentManager-Handler-6:null) Seq 5-1718157356: Processing: { Ans: , MgmtId: 7635042566263, via: 5, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:105)\n\tat com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(PremiumSecondaryStorageResource.java:56)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}}] }
> 2013-07-23 10:57:21,819 DEBUG [agent.transport.Request] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) Seq 5-1718157356: Received: { Ans: , MgmtId: 7635042566263, via: 5, Ver: v1, Flags: 10, { Answer } }
> 2013-07-23 10:57:21,819 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-10:job-43 = [ 05569d7e-8630-4481-a7cf-2d4831ba38fe ]) copy to image store failed: java.lang.NullPointerException
> DB
> =========
> mysql> select * from storage_pool\G;
> *************************** 1. row ***************************
> id: 1
> name: primary
> uuid: 8db52c2d-88f9-3b9d-9b81-f72fcb8097c2
> pool_type: NetworkFilesystem
> port: 2049
> data_center_id: 1
> pod_id: 1
> cluster_id: 2
> used_bytes: 2074777964544
> capacity_bytes: 5902284800000
> host_address: 10.147.28.7
> user_info: NULL
> path: /export/home/prashant/primary
> created: 2013-07-22 15:57:53
> removed: NULL
> update_time: NULL
> status: Up
> storage_provider_name: DefaultPrimary
> scope: CLUSTER
> hypervisor: NULL
> managed: 0
> capacity_iops: NULL
> *************************** 2. row ***************************
> id: 2
> name: primary2
> uuid: bd186911-97af-371a-9b26-fac999fc98a4
> pool_type: NetworkFilesystem
> port: 2049
> data_center_id: 1
> pod_id: 1
> cluster_id: 3
> used_bytes: 2064452661248
> capacity_bytes: 5902284800000
> host_address: 10.147.28.7
> user_info: NULL
> path: /export/home/prashant/primary2
> created: 2013-07-23 14:02:59
> removed: NULL
> update_time: NULL
> status: Up
> storage_provider_name: DefaultPrimary
> scope: CLUSTER
> hypervisor: NULL
> managed: 0
> capacity_iops: NULL
> 2-
> mysql> select * from volumes where id = 18\G;
> *************************** 1. row ***************************
> id: 18
> account_id: 2
> domain_id: 1
> pool_id: 1
> last_pool_id: 2
> instance_id: 13
> device_id: 0
> name: ROOT-13
> uuid: 881d0e45-0986-4ba1-b1d9-b286df54930f
> size: 0
> folder: /export/home/prashant/primary (should be in /export/home/prashant/primary2)
> path: ROOT-13-16
> pod_id: 1
> data_center_id: 1
> iscsi_name: NULL
> host_ip: NULL
> volume_type: ROOT
> pool_type: NULL
> disk_offering_id: 1
> template_id: 7
> first_snapshot_backup_uuid: NULL
> recreatable: 0
> created: 2013-07-23 14:57:21
> attached: NULL
> updated: 2013-07-23 14:57:27
> removed: 2013-07-23 14:57:27
> state: Expunged
> chain_info: NULL
> update_count: 6
> disk_type: NULL
> display_volume: 0
> format: NULL
> min_iops: NULL
> max_iops: NULL
> 1 row in set (0.00 sec)
> ERROR:
> No query specified
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira