[
https://issues.apache.org/jira/browse/CLOUDSTACK-5008?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13819145#comment-13819145
]
Sateesh Chodapuneedi edited comment on CLOUDSTACK-5008 at 11/11/13 5:40 PM:
----------------------------------------------------------------------------
The reported bug is not reproducible with specified steps from bug description,
i.e. first cold migration of volume did not cause failure in VM start
operation. But VM start operation after second migration of volume back to same
primary storage pool did. The exception observed is,
2013-11-11 17:29:38,889 INFO [vmware.mo.DatastoreMO]
(DirectAgent-218:10.102.192.3) Folder i-2-3-VM exists on datastore
2013-11-11 17:29:38,889 WARN [vmware.resource.VmwareResource]
(DirectAgent-218:10.102.192.3) WARN!!! Folder already exists on datastore for
new VM i-2-3-VM, erase it
2013-11-11 17:29:38,893 INFO [vmware.mo.HypervisorHostHelper]
(DirectAgent-218:10.102.192.3) Create blank VM. cpuCount: 1, cpuSpeed(MHz):
500, mem(Mb): 512
2013-11-11 17:29:39,123 WARN [vmware.resource.VmwareResource]
(DirectAgent-218:10.102.192.3) StartCommand failed due to Exception:
java.lang.RuntimeException
Message: The name 'i-2-3-VM' already exists.
java.lang.RuntimeException: The name 'i-2-3-VM' already exists.
at
com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:411)
Currently debugging this issue in my setup. Will update the root cause shortly.
was (Author: sateeshc):
The reported bug is not reproducible with specified steps from bug description,
i.e. first cold migration of volume did not cause failure in VM start
operation. But second migration of volume back to same primary storage pool
did. The exception observed is,
2013-11-11 17:29:38,889 INFO [vmware.mo.DatastoreMO]
(DirectAgent-218:10.102.192.3) Folder i-2-3-VM exists on datastore
2013-11-11 17:29:38,889 WARN [vmware.resource.VmwareResource]
(DirectAgent-218:10.102.192.3) WARN!!! Folder already exists on datastore for
new VM i-2-3-VM, erase it
2013-11-11 17:29:38,893 INFO [vmware.mo.HypervisorHostHelper]
(DirectAgent-218:10.102.192.3) Create blank VM. cpuCount: 1, cpuSpeed(MHz):
500, mem(Mb): 512
2013-11-11 17:29:39,123 WARN [vmware.resource.VmwareResource]
(DirectAgent-218:10.102.192.3) StartCommand failed due to Exception:
java.lang.RuntimeException
Message: The name 'i-2-3-VM' already exists.
java.lang.RuntimeException: The name 'i-2-3-VM' already exists.
at
com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:411)
Currently debugging this issue in my setup. Will update the root cause shortly.
> [VMWARE]Failed to start the VM after performing Cold Migration of Volume to
> Second Zone wide primary Storage
> ------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-5008
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5008
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Storage Controller, VMware
> Affects Versions: 4.2.1
> Reporter: Sailaja Mada
> Assignee: Sateesh Chodapuneedi
> Priority: Critical
> Fix For: 4.2.1
>
> Attachments: migrationlogs.rar
>
>
> Steps:
> 1. Configure Adv zone with VMWARE ESXi 5.0 Update 2 hypervisor
> 2. Configure two Zone wide primary storages
> 3. Have 2 VMWARE clusters each with 5.0 Update2 ESXi hosts
> 4. Deploy VM using user account
> 5. Attach 3 DATA volumes. Write DATA onto first DISK
> 6. Stop the VM
> 7. Migrate the DATA DISK 1 to second zone wide primary storage
> 8. Tried to start the VM after migration is completed.
> Observation:
> [VMWARE]Failed to start the VM after performing Cold Migration of Volume to
> Second Zone wide primary Storage
> 2013-10-30 19:49:49,187 WARN [vmware.resource.VmwareResource]
> (DirectAgent-267:10.102.192.19) StartCommand failed due to Exception:
> java.lang.RuntimeException
> Message: File
> []/vmfs/volumes/371681b9-ed4b0743/i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk
> was not found
> java.lang.RuntimeException: File
> []/vmfs/volumes/371681b9-ed4b0743/i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk
> was not found
> at
> com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:411)
> at
> com.cloud.hypervisor.vmware.mo.VirtualMachineMO.configureVm(VirtualMachineMO.java:843)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2966)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:513)
> at
> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-10-30 19:49:49,194 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-267:null) Seq 8-1057948407: Response Received:
> 2013-10-30 19:49:49,198 DEBUG [agent.transport.Request]
> (DirectAgent-267:null) Seq 8-1057948407: Processing: { Ans: , MgmtId:
> 94838926819810, via: 8, Ver: v1, Flags: 110,
> [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":10,"name":"i-4-10-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"hostName":"sharedinst1","arch":"x86_64","os":"CentOS
> 5.3
> (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"4f62f2fc9be065a7","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","Message.ReservedCapacityFreed.Flag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"faa8546b-85e5-4fa1-8a7a-c0fbb476c649","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a6d0d1ac-2791-40f0-a9f5-26b524a45972","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"29cbd2fe-d168-3f80-b380-08ca5c399ba7","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newps1","port":2049}},"name":"ROOT-10","size":2147483648,"path":"ROOT-10","volumeId":10,"vmName":"i-4-10-VM","accountId":4,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[29cbd2fed1683f80b38008ca5c399ba7]
>
> i-4-10-VM/ROOT-10.vmdk\"]}","format":"OVA","id":10,"hypervisorType":"VMware"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b57572c-5f4e-42f9-9d9d-01b1e96698ea","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"29cbd2fe-d168-3f80-b380-08ca5c399ba7","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newps1","port":2049}},"name":"newd1","size":5368709120,"path":"0a46a41a02e045d0a310d4b2d9e56b9f","volumeId":18,"vmName":"i-4-10-VM","accountId":4,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:1\",\"diskChain\":[\"[29cbd2fed1683f80b38008ca5c399ba7]
>
> i-4-10-VM/0a46a41a02e045d0a310d4b2d9e56b9f.vmdk\"]}","format":"OVA","id":18,"hypervisorType":"VMware"}},"diskSeq":2,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b58f7371-2570-49c2-b9f3-0ef412e2a260","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"29cbd2fe-d168-3f80-b380-08ca5c399ba7","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/newps1","port":2049}},"name":"newd2","size":5368709120,"path":"eee0f43fdfbc4572821c5f5a9fc32678","volumeId":19,"vmName":"i-4-10-VM","accountId":4,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:2\",\"diskChain\":[\"[29cbd2fed1683f80b38008ca5c399ba7]
>
> i-4-10-VM/eee0f43fdfbc4572821c5f5a9fc32678.vmdk\"]}","format":"OVA","id":19,"hypervisorType":"VMware"}},"diskSeq":4,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"313118e2-a6a0-43ad-acbb-a5fe0ac3de1d","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"25505c51-4b14-3f06-b3fe-9c36fe69a753","id":2,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/cluster2ps1","port":2049}},"name":"DATA-10","size":5368709120,"path":"75a1abccb8684639a12f615116e68b24","volumeId":20,"vmName":"i-4-10-VM","accountId":4,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[29cbd2fed1683f80b38008ca5c399ba7]
>
> i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk\"]}","format":"OVA","id":20,"hypervisorType":"VMware"}},"diskSeq":1,"type":"DATADISK"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"a5507bf6-5ccd-4d33-b21e-41acbfd7b027","ip":"10.102.198.12","netmask":"255.255.255.128","gateway":"10.102.198.1","mac":"06:cd:f4:00:00:23","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://110","isolationUri":"vlan://110","isSecurityGroupEnabled":false}]},"result":false,"details":"StartCommand
> failed due to Exception: java.lang.RuntimeException\nMessage: File
> []/vmfs/volumes/371681b9-ed4b0743/i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk
> was not found\n","wait":0}}] }
> 2013-10-30 19:49:49,198 DEBUG [agent.transport.Request]
> (Job-Executor-126:job-103 = [ 3c563876-b27a-4bf3-bc90-dbf2aaa98628 ]) Seq
> 8-1057948407: Received: { Ans: , MgmtId: 94838926819810, via: 8, Ver: v1,
> Flags: 110, { StartAnswer } }
> 2013-10-30 19:49:49,200 DEBUG [agent.manager.AgentAttache]
> (DirectAgent-267:null) Seq 8-1057948407: No more commands found
> 2013-10-30 19:49:49,204 INFO [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-126:job-103 = [ 3c563876-b27a-4bf3-bc90-dbf2aaa98628 ]) Unable
> to start VM on Host[-8-Routing] due to StartCommand failed due to Exception:
> java.lang.RuntimeException
> Message: File
> []/vmfs/volumes/371681b9-ed4b0743/i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk
> was not found
> 2013-10-30 19:49:49,214 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-126:job-103 = [ 3c563876-b27a-4bf3-bc90-dbf2aaa98628 ])
> Cleaning up resources for the vm VM[User|sharedinst1] in Starting state
> 2013-10-30 19:49:49,216 DEBUG [agent.transport.Request]
> (Job-Executor-126:job-103 = [ 3c563876-b27a-4bf3-bc90-dbf2aaa98628 ]) Seq
> 8-1057948408: Sending { Cmd , MgmtId: 94838926819810, via: 8, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-4-10-VM","wait":0}}]
> }
> 2013-10-30 19:49:49,216 DEBUG [agent.transport.Request]
> (Job-Executor-126:job-103 = [ 3c563876-b27a-4bf3-bc90-dbf2aaa98628 ]) Seq
> 8-1057948408: Executing: { Cmd , MgmtId: 94838926819810, via: 8, Ver: v1,
> Flags: 100111,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-4-10-VM","wait":0}}]
> }
> 2013-10-30 19:49:49,216 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-197:null) Seq 8-1057948408: Executing request
> 2013-10-30 19:49:49,217 INFO [vmware.resource.VmwareResource]
> (DirectAgent-197:10.102.192.19) Executing resource StopCommand:
> {"isProxy":false,"executeInSequence":true,"vmName":"i-4-10-VM","wait":0}
> 2013-10-30 19:49:50,841 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-366:null) Ping from 7
> 2013-10-30 19:49:50,980 WARN [vmware.resource.VmwareResource]
> (DirectAgent-122:10.102.192.20) StartCommand failed due to Exception:
> java.lang.RuntimeException
> Message: The name 'i-4-10-VM' already exists.
> java.lang.RuntimeException: The name 'i-4-10-VM' already exists.
> at
> com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:411)
> at com.cloud.hypervisor.vmware.mo.HostMO.createVm(HostMO.java:574)
> at
> com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.createBlankVm(HypervisorHostHelper.java:1184)
> at
> com.cloud.hypervisor.vmware.mo.HostMO.createBlankVm(HostMO.java:761)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2717)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:513)
> at
> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-10-30 19:37:43,310 INFO [cloud.server.ManagementServerImpl]
> (catalina-exec-16:null) Volume Vol[11|vm=10|DATADISK] isn't attached to any
> running vm. Looking for storage pools in the cluster to which this volumes
> can be migrated.
> 2013-10-30 19:37:45,696 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
> ===START=== 10.104.255.45 -- GET
> command=migrateVolume&livemigrate=true&storageid=25505c51-4b14-3f06-b3fe-9c36fe69a753&volumeid=5f4fef52-c7e3-4a44-bb86-40005f2fa763&response=json&sessionkey=aBW1O134QVprgEZEHjdVdGfH6cY%3D&_=1383142396380
> 2013-10-30 19:37:45,770 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-21:null) submit async job-102 = [
> 0af73b05-444e-4a19-a82a-045852e8e61b ], details: AsyncJobVO {id:102, userId:
> 2, accountId: 2, sessionKey: null, instanceType: None, instanceId: null, cmd:
> org.apache.cloudstack.api.command.user.volume.MigrateVolumeCmd,
> cmdOriginator: null, cmdInfo:
> {"response":"json","sessionkey":"aBW1O134QVprgEZEHjdVdGfH6cY\u003d","cmdEventType":"VOLUME.MIGRATE","ctxUserId":"2","storageid":"25505c51-4b14-3f06-b3fe-9c36fe69a753","livemigrate":"true","httpmethod":"GET","volumeid":"5f4fef52-c7e3-4a44-bb86-40005f2fa763","_":"1383142396380","ctxAccountId":"2","ctxStartEventId":"403"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 94838926819810,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-10-30 19:37:45,772 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
> ===END=== 10.104.255.45 -- GET
> command=migrateVolume&livemigrate=true&storageid=25505c51-4b14-3f06-b3fe-9c36fe69a753&volumeid=5f4fef52-c7e3-4a44-bb86-40005f2fa763&response=json&sessionkey=aBW1O134QVprgEZEHjdVdGfH6cY%3D&_=1383142396380
> mysql> select * from volumes where
> uuid='5f4fef52-c7e3-4a44-bb86-40005f2fa763'\G;
> *************************** 1. row ***************************
> id: 11
> account_id: 4
> domain_id: 1
> pool_id: 1
> last_pool_id: NULL
> instance_id: 10
> device_id: 1
> name: DATA-10
> uuid: 5f4fef52-c7e3-4a44-bb86-40005f2fa763
> size: 5368709120
> folder: NULL
> path: 9db1d292e0394eb39e69c8adee09e26c
> pod_id: NULL
> data_center_id: 2
> iscsi_name: NULL
> host_ip: NULL
> volume_type: DATADISK
> pool_type: NULL
> disk_offering_id: 3
> template_id: NULL
> first_snapshot_backup_uuid: NULL
> recreatable: 0
> created: 2013-10-30 05:52:24
> attached: NULL
> updated: 2013-10-30 14:16:29
> removed: 2013-10-30 14:16:29
> state: Expunged
> chain_info:
> {"diskDeviceBusName":"scsi0:0","diskChain":["[29cbd2fed1683f80b38008ca5c399ba7]
> i-4-10-VM/9db1d292e0394eb39e69c8adee09e26c.vmdk"]}
> update_count: 8
> disk_type: NULL
> vm_snapshot_chain_size: NULL
> iso_id: NULL
> display_volume: 0
> format: OVA
> min_iops: NULL
> max_iops: NULL
> 1 row in set (0.00 sec)
> ERROR:
> No query specified
> mysql>
--
This message was sent by Atlassian JIRA
(v6.1#6144)
