sadhu suresh created CLOUDSTACK-5020:
----------------------------------------
Summary: fail to recreate system VM in a specific scenario during
storage maintenance
Key: CLOUDSTACK-5020
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5020
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: VMware
Affects Versions: 4.2.1
Reporter: sadhu suresh
fail to recreate to system vm(eg console proxy root volume) and fails with
Root-2 volume already exits error when it try to start the system vm during
storage maintenance.
some times during storage maintenance , CS fail to delete root voulme of a
systemvm and recreate the system vm's volume in another storage and
corresponding volume exits in previous storage .
when we put second primary storage in maintenance mode and it tries to recreate
system vm in primary storage 1 but same volume(existing volume due to failure
will exits in primary storage1) already exits and its fail to start due below
error:
"
Unable to create Vol[89|vm=2|ROOT]:java.lang.RuntimeException: The name
'ROOT-2' already exists.
"
steps:
1.deploy advanced zone with vmware +2 host
2.enabled ha on cluster(from vcenter)
3.deploy few vm from cs
4.add one more primary storage
5.put first primary storage in to maintenance mode
6.once its successful,cancel the maintenance ode
7.put second primary storage into maintenance mode
second scenario::
1.put enable.ha.storage.migration to false
2.put first primary storage in to maintenance mode
3.once its successful,cancel the maintenance ode
4.put second primary storage into maintenance mode
content of management log:
***************************
2013-11-01 17:30:38,636 INFO [vmware.mo.DatastoreMO]
(DirectAgent-39:10.147.40.30) Search file ROOT-2-delta.vmdk on
[9142ce532cf63ce68edf4c43061121ad]
2013-11-01 17:30:38,668 INFO [vmware.mo.DatastoreMO]
(DirectAgent-39:10.147.40.30) File [9142ce532cf63ce68edf4c43061121ad]
ROOT-2-delta.vmdk does not exist on datastore
2013-11-01 17:30:38,677 INFO [vmware.mo.DatastoreMO]
(DirectAgent-39:10.147.40.30) Search file ROOT-2-delta.vmdk on
[9142ce532cf63ce68edf4c43061121ad]
2013-11-01 17:30:38,709 INFO [vmware.mo.DatastoreMO]
(DirectAgent-39:10.147.40.30) File [9142ce532cf63ce68edf4c43061121ad]
ROOT-2-delta.vmdk does not exist on datastore
2013-11-01 17:30:38,710 INFO [vmware.mo.DatastoreMO]
(DirectAgent-39:10.147.40.30) Searching file ROOT-2-delta.vmdk in
[9142ce532cf63ce68edf4c43061121ad]
2013-11-01 17:30:38,852 WARN [storage.resource.VmwareStorageLayoutHelper]
(DirectAgent-39:10.147.40.30) Unable to locate VMDK file: ROOT-2-delta.vmdk
2013-11-01 17:30:38,852 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-39:null) Seq 4-1510146130: Response Received:
2013-11-01 17:30:38,853 DEBUG [agent.transport.Request] (DirectAgent-39:null)
Seq 4-1510146130: Processing: { Ans: , MgmtId: 7363452993625, via: 4, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"Success","wait":0}}] }
2013-11-01 17:30:38,853 DEBUG [agent.transport.Request]
(StorageManager-Scavenger-1:null) Seq 4-1510146130: Received: { Ans: , MgmtId:
7363452993625, via: 4, Ver: v1, Flags: 10, { Answer } }
2013-11-01 17:30:38,869 INFO [storage.volume.VolumeServiceImpl]
(StorageManager-Scavenger-1:null) Volume 83 is not referred anywhere, remove it
from volumes table
2013-11-01 17:30:44,168 INFO [storage.resource.VmwareStorageProcessor]
(DirectAgent-3:10.147.40.30) Move volume out of volume-wrapper VM
2013-11-01 17:30:44,354 ERROR [storage.resource.VmwareStorageProcessor]
(DirectAgent-3:10.147.40.30) clone volume from base image failed due to
Exception: java.lang.RuntimeException
Message: File [722e618184973d319933a0a267ae376c] ROOT-2/ROOT-2.vmdk was not
found
java.lang.RuntimeException: File [722e618184973d319933a0a267ae376c]
ROOT-2/ROOT-2.vmdk was not found
at
com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:411)
at
com.cloud.hypervisor.vmware.mo.DatastoreMO.moveDatastoreFile(DatastoreMO.java:235)
at
com.cloud.storage.resource.VmwareStorageProcessor.createVMFullClone(VmwareStorageProcessor.java:308)
at
com.cloud.storage.resource.VmwareStorageProcessor.cloneVolumeFromBaseTemplate(VmwareStorageProcessor.java:382)
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-11-01 17:30:44,356 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-3:null) Seq 4-1510146125: Response Received:
2013-11-01 17:30:44,356 DEBUG [agent.transport.Request] (DirectAgent-3:null)
Seq 4-1510146125: Processing: { Ans: , MgmtId: 7363452993625, via: 4, Ver: v1,
Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException:
File [722e618184973d319933a0a267ae376c] ROOT-2/ROOT-2.vmdk was not
found","wait":0}}] }
2013-11-01 17:30:44,357 DEBUG [agent.transport.Request] (Job-Executor-7:job-295
= [ 3850fe84-ac4b-4b26-9abf-cd5c6e3cbadd ]) Seq 4-1510146125: Received: { Ans:
, MgmtId: 7363452993625, via: 4, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2013-11-01 17:30:44,361 DEBUG [agent.manager.AgentAttache] (DirectAgent-3:null)
Seq 4-1510146125: No more commands found
2013-11-01 17:30:44,368 WARN [storage.datastore.ObjectInDataStoreManagerImpl]
(Job-Executor-7:job-295 = [ 3850fe84-ac4b-4b26-9abf-cd5c6e3cbadd ]) Unsupported
data object (VOLUME,
org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@4891af8), no need
to delete from object in store ref table
2013-11-01 17:30:44,370 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-7:job-295 = [ 3850fe84-ac4b-4b26-9abf-cd5c6e3cbadd ]) Unable to
create Vol[89|vm=2|ROOT]:java.lang.RuntimeException: File
[722e618184973d319933a0a267ae376c] ROOT-2/ROOT-2.vmdk was not found
2013-11-01 17:30:44,375 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-295 = [ 3850fe84-ac4b-4b26-9abf-cd5c6e3cbadd ]) Unable to
contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
unreachable: Unable to create Vol[89|vm=2|ROOT]:java.lang.RuntimeException:
File [722e618184973d319933a0a267ae376c] ROOT-2/ROOT-2.vmdk was not found
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2580)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2631)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:712)
at
com.cloud.storage.StoragePoolAutomationImpl.maintain(StoragePoolAutomationImpl.java:250)
at
org.apache.cloudstack.storage.datastore.lifecycle.CloudStackPrimaryDataStoreLifeCycleImpl.maintain(CloudStackPrimaryDataStoreLifeCycleImpl.java:435)
at
com.cloud.storage.StorageManagerImpl.preparePrimaryStorageForMaintenance(StorageManagerImpl.java:1379)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.storage.StorageManagerImpl.preparePrimaryStorageForMaintenance(StorageManagerImpl.java:179)
at
org.apache.cloudstack.api.command.admin.storage.PreparePrimaryStorageForMaintenanceCmd.execute(PreparePrimaryStorageForMaintenanceCmd.java:102)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
....
,,,,,
07,345 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is
being created in podId: 1
2013-11-01 17:31:07,355 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=200 is already implemented
2013-11-01 17:31:07,389 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=202 is already implemented
2013-11-01 17:31:07,422 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Network id=201 is already implemented
2013-11-01 17:31:07,454 DEBUG [network.guru.PodBasedNetworkGuru]
(consoleproxy-1:null) Allocated a nic
NicProfile[7-2-9b9add98-aa49-42f8-9e7e-cea991ab1e49-10.147.40.159-null for
VM[ConsoleProxy|v-2-VM]
2013-11-01 17:31:07,465 DEBUG [cloud.storage.VolumeManagerImpl]
(consoleproxy-1:null) Checking if we need to prepare 1 volumes for
VM[ConsoleProxy|v-2-VM]
2013-11-01 17:31:07,481 DEBUG [storage.image.TemplateDataFactoryImpl]
(consoleproxy-1:null) template 8 is already in store:1, type:Image
2013-11-01 17:31:07,488 DEBUG [storage.image.TemplateDataFactoryImpl]
(consoleproxy-1:null) template 8 is already in store:1, type:Primary
2013-11-01 17:31:07,525 DEBUG [storage.motion.AncientDataMotionStrategy]
(consoleproxy-1:null) copyAsync inspecting src type TEMPLATE copyAsync
inspecting dest type VOLUME
2013-11-01 17:31:07,544 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-1512833105: Sending { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1,
Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"62b98e5419753ca0a727d73fff2d95b3","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-4.2-vh7.ova","uuid":"aee4482e-40c6-11e3-b6b3-06b270000059","id":8,"format":"OVA","accountId":1,"checksum":"8fde62b1089e5844a9cd3b9b953f9596","hvm":false,"displayText":"SystemVM
Template
(vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"722e6181-8497-3d31-9933-a0a267ae376c","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/talluri/vmware.campo/primary","port":2049}},"name":"routing-8","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7b64af46-64f6-44f0-91e5-ff3b03323b5c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"722e6181-8497-3d31-9933-a0a267ae376c","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/talluri/vmware.campo/primary","port":2049}},"name":"ROOT-2","size":0,"volumeId":89,"vmName":"v-2-VM","accountId":1,"format":"OVA","id":89,"hypervisorType":"VMware"}},"executeInSequence":true,"wait":0}}]
}
2013-11-01 17:31:07,546 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-1512833105: Executing: { Cmd , MgmtId: 7363452993625, via: 1, Ver: v1,
Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"62b98e5419753ca0a727d73fff2d95b3","origUrl":"http://download.cloud.com/templates/4.2/systemvmtemplate-4.2-vh7.ova","uuid":"aee4482e-40c6-11e3-b6b3-06b270000059","id":8,"format":"OVA","accountId":1,"checksum":"8fde62b1089e5844a9cd3b9b953f9596","hvm":false,"displayText":"SystemVM
Template
(vSphere)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"722e6181-8497-3d31-9933-a0a267ae376c","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/talluri/vmware.campo/primary","port":2049}},"name":"routing-8","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"7b64af46-64f6-44f0-91e5-ff3b03323b5c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"722e6181-8497-3d31-9933-a0a267ae376c","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/talluri/vmware.campo/primary","port":2049}},"name":"ROOT-2","size":0,"volumeId":89,"vmName":"v-2-VM","accountId":1,"format":"OVA","id":89,"hypervisorType":"VMware"}},"executeInSequence":true,"wait":0}}]
}
2013-11-01 17:31:07,546 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-40:null) Seq 1-1512833105: Executing request
2013-11-01 17:31:07,712 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-11-01 17:31:07,716 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-11-01 17:31:07,732 INFO [vmware.mo.DatastoreMO]
(DirectAgent-40:10.147.40.29) Folder ROOT-2 exists on datastore
2013-11-01 17:31:07,732 INFO [storage.resource.VmwareStorageProcessor]
(DirectAgent-40:10.147.40.29) deleting files in folder ROOT-2
2013-11-01 17:31:07,737 INFO [storage.resource.VmwareStorageProcessor]
(DirectAgent-40:10.147.40.29) creating full clone from template
2013-11-01 17:31:07,829 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-11-01 17:31:07,832 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-11-01 17:31:08,135 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:null) Checking if any host reservation can be
released ...
2013-11-01 17:31:08,137 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Running Capacity Checker ...
2013-11-01 17:31:08,138 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) recalculating system capacity
2013-11-01 17:31:08,138 DEBUG [cloud.alert.AlertManagerImpl]
(CapacityChecker:null) Executing cpu/ram capacity update
2013-11-01 17:31:08,145 ERROR [storage.resource.VmwareStorageProcessor]
(DirectAgent-40:10.147.40.29) 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:411)
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:382)
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-11-01 17:31:08,154 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-40:null) Seq 1-1512833105: Response Received:
2013-11-01 17:31:08,155 DEBUG [agent.transport.Request] (DirectAgent-40:null)
Seq 1-1512833105: Processing: { Ans: , MgmtId: 7363452993625, 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-11-01 17:31:08,158 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-1512833105: Received: { Ans: , MgmtId: 7363452993625, via: 1, Ver: v1,
Flags: 110, { CopyCmdAnswer } }
2013-11-01 17:31:08,165 DEBUG [agent.manager.AgentAttache]
(DirectAgent-40:null) Seq 1-1512833105: No more commands found
2013-11-01 17:31:08,175 WARN [storage.datastore.ObjectInDataStoreManagerImpl]
(consoleproxy-1:null) Unsupported data object (VOLUME,
org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@6e3345cb), no need
to delete from object in store ref table
2013-11-01 17:31:08,176 DEBUG [cloud.storage.VolumeManagerImpl]
(consoleproxy-1:null) Unable to create
Vol[89|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-11-01 17:31:08,176 INFO [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Unable to contact resource.
--
This message was sent by Atlassian JIRA
(v6.1#6144)
