[CLOUDSTACK-5929] [VM Sync] - Vmware - Even when starting Vm fails, startVirtualMachine async job reports succees.

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 4.3.0
• Fix Version/s: 4.4.0
• Component/s: Management Server
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: Build from 4.3
• Assignee: Kelven Yang
• Reporter: Sangeetha Hariharan
• Created: 22/Jan/14 18:52
• Updated: 06/May/14 23:35
• Resolved: 06/May/14 23:35

Description

Set up:
Advanced zone set up with 2 Vmware (ESXI 5.1) hosts.

PreReq:
Have few Vms deployed using Cloudstack.
Steps:
Outside of Cloudstack , Stop Vm.
Destroy an existing VM using "Delete from Disk" option .

This result in VM being marked in "Stopped" state.
Try starting this VM from CloudStack , this fails to start which is as expected.
But the startVm job reports success.

2014-01-22 13:01:03,367 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-242:ctx-319b84f0 10.223.57.4) StartCommand failed due to Excepti
on: java.lang.RuntimeException
Message: File []/vmfs/volumes/7f09fdfe-d72413eb/i-4-7-MyTestVM/ROOT-7.vmdk was not found

java.lang.RuntimeException: File []/vmfs/volumes/7f09fdfe-d72413eb/i-4-7-MyTestVM/ROOT-7.vmdk was not found
at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:336)
at com.cloud.hypervisor.vmware.mo.VirtualMachineMO.configureVm(VirtualMachineMO.java:860)
at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2988)
at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:525)
at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:216)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
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$201(ScheduledThreadPoolExecutor.java:178)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
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:722)
2014-01-22 13:01:03,369 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-242:ctx-319b84f0) Seq 2-1175063498: Response Received:
2014-01-22 13:01:03,376 DEBUG [c.c.a.t.Request] (DirectAgent-242:ctx-319b84f0) Seq 2-1175063498: Processing: { Ans: , MgmtId: 95307354844397, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":7,"name":"i-4-7-MyTestVM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":100,"maxSpeed":100,"minRam":134217728,"maxRam":134217728,"hostName":"TestVM-1","arch":"x86_64","os":"CentOS 5.3 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"dd7efb1af282259f","params":

{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","Message.ReservedCapacityFreed.Flag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"}

,"uuid":"0b7cc2df-8d7b-49bf-b4a6-54f01710d4e9","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"050f70ca-5834-4786-a81f-c81e056f77ce","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a0c555cc-695c-3343-bfa0-3413a91dbfed","id":1,"poolType":"NetworkFilesystem","host":"10.223.57.195","path":"/export/home/vmware/primary","port":2049,"url":"NetworkFilesystem://10.223.57.195//export/home/vmware/primary/?ROLE=Primary&STOREUUID=a0c555cc-695c-3343-bfa0-3413a91dbfed"}},"name":"ROOT-7","size":2147483648,"path":"ROOT-7","volumeId":7,"vmName":"i-4-7-MyTestVM","accountId":4,"chainInfo":"

{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[a0c555cc695c 3343bfa03413a91dbfed] i-4-7-MyTestVM/ROOT-7.vmdk\"]}

","format":"OVA","id":7,"deviceId":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-7","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.223.57.195","volumeSize":"2147483648"}},{"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":"a50efe59-1224-4a6b-b46e-d189ee9c89fc","ip":"10.1.1.107","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:49:22:00:01","dns1":"10.223.240.232","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2126","isolationUri":"vlan://2126","isSecurityGroupEnabled":false}

]},"result":false,"details":"StartCommand failed due to Exception: java.lang.RuntimeException\nMessage: File []/vmfs/volumes/7f09fdfe-d72413eb/i-4-7-MyTestVM/ROOT-7.vmdk was not found\n","wait":0}}] }
2014-01-22 13:01:03,376 DEBUG [c.c.a.t.Request] (Job-Executor-131:ctx-f421344c ctx-cd8886c2) Seq 2-1175063498: Received: { Ans: , MgmtId: 95307354844397, via: 2, Ver: v1, Flags: 10,

{ StartAnswer }

}
2014-01-22 13:01:03,380 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-131:ctx-f421344c ctx-cd8886c2) Unable to start VM on Host[-2-Routing] due to StartCommand failed due to Exception: java.lang.RuntimeException