[CLOUDSTACK-4875] VMWARE: vCenter 5.5 - SYSTEM VM: Unable to create deployment for VM

• Type: Bug
• Status: Closed
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 4.2.1
• Fix Version/s: 4.3.0
• Component/s: SystemVM, VMware
• Security Level: Public (Anyone can view this level - this is the default.)
• Environment: Master with vCenter 5.5 / ESXi 5.5
• Assignee: Likitha Shetty
• Reporter: Parth Brahmbhatt
• Created: 15/Oct/13 21:11
• Updated: 21/Jan/14 22:26
• Resolved: 17/Dec/13 13:45

Description

Unable to launch system VM's

See attached logs

2013-10-15 13:31:40,061 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: File [803eb6157bb83df98d96c4da27252fa8] ROOT-2/ROOT-2.vmdk was not found
2013-10-15 13:31:40,061 INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: File [803eb6157bb83df98d96c4da27252fa8] ROOT-2/ROOT-2.vmdk was not found
at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2566)
at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2617)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889)
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$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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-15 13:31:40,068 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state

type TEMPLATE copyAsync inspecting dest type VOLUME
2013-10-15 13:33:00,630 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-401276957: Waiting for Seq 401276956 Scheduling: { Cmd , MgmtId: 15929225863658, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"b8766e32c0c838539a8f75c2cc62a30b","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-4.2-vh7.ova","uuid":"e1eb1bf2-35c3-11e3-a10c-0e7ccfd961ea","id":8,"format":"OVA","accountId":1,"checksum":"8fde62b1089e5844a9cd3b9b953f9596","hvm":false,"displayText":"SystemVM Template (vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"803eb615-7bb8-3df9-8d96-c4da27252fa8","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/49.211/primary","port":2049}},"name":"routing-8","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6d6ab2fd-6866-4dcb-bc2f-b52b65ccc104","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"803eb615-7bb8-3df9-8d96-c4da27252fa8","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/49.211/primary","port":2049}},"name":"ROOT-4","size":0,"volumeId":4,"vmName":"s-4-VM","accountId":1,"format":"OVA","id":4,"hypervisorType":"VMware"}},"executeInSequence":true,"wait":0}}] }
2013-10-15 13:33:02,064 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-30:10.223.248.194) clone volume from base image failed due to Exception: java.lang.RuntimeException
Message: The name 'ROOT-2' already exists.

java.lang.RuntimeException: The name 'ROOT-2' already exists.
at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:412)
at com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createFullClone(VirtualMachineMO.java:602)
at com.cloud.storage.resource.VmwareStorageProcessor.createVMFullClone(VmwareStorageProcessor.java:296)
at com.cloud.storage.resource.VmwareStorageProcessor.cloneVolumeFromBaseTemplate(VmwareStorageProcessor.java:387)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:73)
at com.cloud.storage.resource.VmwareStorageSubsystemCommandHandler.execute(VmwareStorageSubsystemCommandHandler.java:155)
at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:559)
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-15 13:33:02,065 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-30:null) Seq 1-401276956: Response Received:
2013-10-15 13:33:02,065 DEBUG [agent.transport.Request] (DirectAgent-30:null) Seq 1-401276956: Processing: { Ans: , MgmtId: 15929225863658, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-2' already exists.","wait":0}}] }
2013-10-15 13:33:02,065 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-401276956: Received: { Ans: , MgmtId: 15929225863658, via: 1, Ver: v1, Flags: 110,

{ CopyCmdAnswer }

}
2013-10-15 13:33:02,068 DEBUG [agent.manager.AgentAttache] (DirectAgent-30:null) Seq 1-401276957: Sending now. is current sequence.
2013-10-15 13:33:02,074 WARN [storage.datastore.ObjectInDataStoreManagerImpl] (consoleproxy-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@4198553e), no need to delete from object in store ref table
2013-10-15 13:33:02,074 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-10-15 13:33:02,074 INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2566)
at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2617)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889)
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$201(ScheduledThreadPoolExecutor.java:165)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
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-15 13:33:02,075 DEBUG [agent.transport.Request] (DirectAgent-30:null) Seq 1-401276957: Executing: { Cmd , MgmtId: 15929225863658, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"b8766e32c0c838539a8f75c2cc62a30b","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-4.2-vh7.ova","uuid":"e1eb1bf2-35c3-11e3-a10c-0e7ccfd961ea","id":8,"format":"OVA","accountId":1,"checksum":"8fde62b1089e5844a9cd3b9b953f9596","hvm":false,"displayText":"SystemVM Template (vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"803eb615-7bb8-3df9-8d96-c4da27252fa8","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/49.211/primary","port":2049}},"name":"routing-8","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6d6ab2fd-6866-4dcb-bc2f-b52b65ccc104","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"803eb615-7bb8-3df9-8d96-c4da27252fa8","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/parth/49.211/primary","port":2049}},"name":"ROOT-4","size":0,"volumeId":4,"vmName":"s-4-VM","accountId":1,"format":"OVA","id":4,"hypervisorType":"VMware"}},"executeInSequence":true,"wait":0}}] }
2013-10-15 13:33:02,077 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-6:null) Seq 1-401276957: Executing request
2013-10-15 13:33:02,081 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-2-VM] in Starting state
2013-10-15 13:33:02,084 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-401276958: Waiting for Seq 401276957 Scheduling: { Cmd , MgmtId: 15929225863658, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"v-2-VM","wait":0}}] }
2013-10-15 13:33:02,308 INFO [vmware.mo.DatastoreMO] (DirectAgent-6:10.223.248.194) Fo

Issue Links

• relates to: CLOUDSTACK-4860 [VMware] Vcenter 5.5 ESXi 5.5 hosts SSVM CPVM fail to come up to running state