You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Likitha Shetty (JIRA)" <ji...@apache.org> on 2014/01/22 13:16:26 UTC
[jira] [Updated] (CLOUDSTACK-5927) [UPGRADE] Storage garbage
collector tries to destroy the SSVM/CPVM root disk that is in use
[ https://issues.apache.org/jira/browse/CLOUDSTACK-5927?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Likitha Shetty updated CLOUDSTACK-5927:
---------------------------------------
Summary: [UPGRADE] Storage garbage collector tries to destroy the SSVM/CPVM root disk that is in use (was: [UPGRADE] Storage garbage collector is trying to destroy the SSVM/CPVM root disk that is in use)
> [UPGRADE] Storage garbage collector tries to destroy the SSVM/CPVM root disk that is in use
> -------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-5927
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5927
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Affects Versions: 4.3.0
> Reporter: Likitha Shetty
> Assignee: Likitha Shetty
> Priority: Critical
> Fix For: 4.3.0
>
>
> Steps to reproduce
> ====================
> 1-prepare a 4.2.1 setup with vmware EXI5.1
> 2-deploy some vms
> 3-upgrade to ccp 4.3 beta build
> 4-stop start system vms
> Expected
> ========
> stop start vms should work as expected and the root volume of the started vm should be from the new template
> Actual
> =======
> htting exceptions during storage garbage collection
> Observation
> ===========
> 1
> ===
> i stopped router vm again and try to start , router vms failed to start
> because
> StartCommand failed due to Exception: java.lang.RuntimeException
> Message: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.vmdk was not found
> java.lang.RuntimeException: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.vmdk was not found
> Logs:
> ======
> system vms
> ------------
> 2014-01-21 16:19:37,321 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-aca3e39e ctx-0309374b) ===END=== 10.105.180.13 – GET command=queryAsyncJobResult&jobId=9794da0c-1cf8-4a78-99b5-58021b7346a7&response=json&sessionkey=yBXOfAfOxr1AxfKp12GZhmA4tjE%3D&_=1390319833126
> 2014-01-21 16:19:37,351 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-1:ctx-7a9c245d 10.147.40.8) Found file ROOT-1-flat.vmdk in datastore at [b420e50b06603053ab6814850b01c333] s-1-VM/
> 2014-01-21 16:19:37,363 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-1:ctx-7a9c245d 10.147.40.8) Search file ROOT-1-flat.vmdk on [b420e50b06603053ab6814850b01c333] s-1-VM
> 2014-01-21 16:19:37,503 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-1:ctx-7a9c245d 10.147.40.8) File [b420e50b06603053ab6814850b01c333] s-1-VM/ROOT-1-flat.vmdk exists on datastore
> 2014-01-21 16:19:37,705 ERROR [c.c.s.r.VmwareStorageProcessor] (DirectAgent-1:ctx-7a9c245d 10.147.40.8) delete volume failed due to Exception: java.lang.RuntimeException
> Message: Cannot delete file [b420e50b06603053ab6814850b01c333] s-1-VM/ROOT-1-flat.vmdk
> java.lang.RuntimeException: Cannot delete file [b420e50b06603053ab6814850b01c333] s-1-VM/ROOT-1-flat.vmdk
> at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:336)
> at com.cloud.hypervisor.vmware.mo.DatastoreMO.deleteFile(DatastoreMO.java:175)
> at com.cloud.storage.resource.VmwareStorageLayoutHelper.deleteVolumeVmdkFiles(VmwareStorageLayoutHelper.java:276)
> at com.cloud.storage.resource.VmwareStorageProcessor.deleteVolume(VmwareStorageProcessor.java:1549)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:120)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:54)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:550)
> 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$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)
> 2014-01-21 16:19:37,707 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-1:ctx-7a9c245d) Seq 4-1019412823: Response Received:
> 2014-01-21 16:19:37,708 DEBUG [c.c.a.t.Request] (DirectAgent-1:ctx-7a9c245d) Seq 4-1019412823: Processing: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"delete volume failed due to Exception: java.lang.RuntimeException\nMessage: Cannot delete file [b420e50b06603053ab6814850b01c333] s-1-VM/ROOT-1-flat.vmdk\n","wait":0}}] }
> 2014-01-21 16:19:37,708 DEBUG [c.c.a.t.Request] (StorageManager-Scavenger-1:ctx-bad27911) Seq 4-1019412823: Received: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10,
> { Answer } }
> 2
> —
> 2014-01-21 16:19:47,237 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-232:ctx-3d554e1a 10.147.40.8) File [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk exists on datastore
> 2014-01-21 16:19:47,260 ERROR [c.c.s.r.VmwareStorageProcessor] (DirectAgent-232:ctx-3d554e1a 10.147.40.8) delete volume failed due to Exception: java.lang.RuntimeException
> Message: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk
> java.lang.RuntimeException: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk
> at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:336)
> at com.cloud.hypervisor.vmware.mo.DatastoreMO.deleteFile(DatastoreMO.java:175)
> at com.cloud.storage.resource.VmwareStorageLayoutHelper.deleteVolumeVmdkFiles(VmwareStorageLayoutHelper.java:276)
> at com.cloud.storage.resource.VmwareStorageProcessor.deleteVolume(VmwareStorageProcessor.java:1549)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:120)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:54)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:550)
> 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$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)
> 2014-01-21 16:19:47,263 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-232:ctx-3d554e1a) Seq 4-1019412824: Response Received:
> 2014-01-21 16:19:47,263 DEBUG [c.c.a.t.Request] (DirectAgent-232:ctx-3d554e1a) Seq 4-1019412824: Processing: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"delete volume failed due to Exception: java.lang.RuntimeException\nMessage: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk\n","wait":0}}] }
> 2014-01-21 16:19:47,264 DEBUG [c.c.a.t.Request] (StorageManager-Scavenger-1:ctx-bad27911) Seq 4-1019412824: Received: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10, { Answer }
> }
> router vms
> ------------
> 2014-01-21 16:19:47,237 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-232:ctx-3d554e1a 10.147.40.8) File [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk exists on datastore
> 2014-01-21 16:19:47,260 ERROR [c.c.s.r.VmwareStorageProcessor] (DirectAgent-232:ctx-3d554e1a 10.147.40.8) delete volume failed due to Exception: java.lang.RuntimeException
> Message: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk
> java.lang.RuntimeException: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk
> at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:336)
> at com.cloud.hypervisor.vmware.mo.DatastoreMO.deleteFile(DatastoreMO.java:175)
> at com.cloud.storage.resource.VmwareStorageLayoutHelper.deleteVolumeVmdkFiles(VmwareStorageLayoutHelper.java:276)
> at com.cloud.storage.resource.VmwareStorageProcessor.deleteVolume(VmwareStorageProcessor.java:1549)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:120)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:54)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:550)
> 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$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)
> 2014-01-21 16:19:47,263 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-232:ctx-3d554e1a) Seq 4-1019412824: Response Received:
> 2014-01-21 16:19:47,263 DEBUG [c.c.a.t.Request] (DirectAgent-232:ctx-3d554e1a) Seq 4-1019412824: Processing: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"delete volume failed due to Exception: java.lang.RuntimeException\nMessage: Cannot delete file [b420e50b06603053ab6814850b01c333] v-2-VM/ROOT-2-flat.vmdk\n","wait":0}}] }
> 2014-01-21 16:19:47,264 DEBUG [c.c.a.t.Request] (StorageManager-Scavenger-1:ctx-bad27911) Seq 4-1019412824: Received: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 10,
> { Answer }
> }
> Router vm failed to start
> =========================
> 014-01-22 05:56:39,618 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-8138: Sending Seq 3-8138: { Ans: , MgmtId: 7145449848920, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-01-22 05:56:39,673 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-312:ctx-b4dabd99 10.147.40.8) StartCommand failed due to Exception: java.lang.RuntimeException
> Message: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.vmdk was not found
> java.lang.RuntimeException: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.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:2954)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:504)
> 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$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)
> 2014-01-22 05:56:39,678 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-312:ctx-b4dabd99) Seq 4-1019414064: Cancelling because one of the answers is false and it is stop on error.
> 2014-01-22 05:56:39,679 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-312:ctx-b4dabd99) Seq 4-1019414064: Response Received:
> 2014-01-22 05:56:39,681 DEBUG [c.c.a.t.Request] (DirectAgent-312:ctx-b4dabd99) Seq 4-1019414064: Processing: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":4,"name":"r-4-VM","bootloader":"HVM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":134217728,"maxRam":134217728,"hostName":"r-4-VM","arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-4-VM eth2ip=10.147.55.5 eth2mask=255.255.255.0 gateway=10.147.55.1 eth0ip=10.1.1.1 eth0mask=255.255.255.0 domain=cs2cloud.internal dhcprange=10.1.1.1 eth1ip=10.147.41.215 eth1mask=255.255.254.0 mgmtcidr=10.147.38.0/24 localgw=10.147.40.1 type=router disable_rp_filter=true extra_pubnics=2 dns1=10.140.50.6","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"2afb7fe717a18f1e","params":
> {"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"}
> ,"uuid":"98942dd7-8ae2-4fd7-8af7-4f6a3b3f8a7d","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f1cf7e15-0345-4a07-8d48-aabb72ea2e59","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b420e50b-0660-3053-ab68-14850b01c333","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/prashant/pm4","port":2049,"url":"NetworkFilesystem://10.147.28.7//export/home/prashant/pm4/?ROLE=Primary&STOREUUID=b420e50b-0660-3053-ab68-14850b01c333"}},"name":"ROOT-4","size":2097152000,"path":"ROOT-4","volumeId":10,"vmName":"r-4-VM","accountId":2,"chainInfo":"
> {\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[b420e50b06603053ab6814850b01c333] r-4-VM/ROOT-4.vmdk\"]}
> ","format":"OVA","id":10,"deviceId":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-4","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"10.147.28.7","volumeSize":"2097152000"}}],"nics":[
> {"deviceId":2,"networkRateMbps":200,"defaultNic":true,"uuid":"b7f441f6-769b-4eac-9cd7-667a604a90e1","ip":"10.147.55.5","netmask":"255.255.255.0","gateway":"10.147.55.1","mac":"06:94:64:00:00:0d","dns1":"10.140.50.6","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://55","isolationUri":"vlan://55","isSecurityGroupEnabled":false}
> ,
> {"deviceId":0,"networkRateMbps":200,"defaultNic":false,"uuid":"0da8327c-e0b1-4426-b8d3-bf28addeed5f","ip":"10.1.1.1","netmask":"255.255.255.0","mac":"02:00:7f:9b:00:02","dns1":"10.140.50.6","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1104","isolationUri":"vlan://1104","isSecurityGroupEnabled":false}
> ,
> {"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"3e9ad6a2-5686-4966-8144-c7afa24445c8","ip":"10.147.41.215","netmask":"255.255.254.0","gateway":"10.147.40.1","mac":"02:00:4a:f5:00:0a","broadcastType":"Native","type":"Control","isSecurityGroupEnabled":false}
> ]},"result":false,"details":"StartCommand failed due to Exception: java.lang.RuntimeException\nMessage: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.vmdk was not found\n","wait":0}}] }
> 2014-01-22 05:56:39,682 DEBUG [c.c.a.t.Request] (Job-Executor-14:ctx-676a27c3 ctx-b611a5f6) Seq 4-1019414064: Received: { Ans: , MgmtId: 7145449848920, via: 4, Ver: v1, Flags: 110,
> { StartAnswer }
> }
> 2014-01-22 05:56:39,686 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-312:ctx-b4dabd99) Seq 4-1019414064: No more commands found
> 2014-01-22 05:56:39,693 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-14:ctx-676a27c3 ctx-b611a5f6) Unable to start VM on Host[-4-Routing] due to StartCommand failed due to Exception: java.lang.RuntimeException
> Message: File []/vmfs/volumes/719f4910-4b868123/r-4-VM/ROOT-4.vmdk was not found
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)