You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Sailaja Mada (JIRA)" <ji...@apache.org> on 2013/10/21 10:01:48 UTC

[jira] [Closed] (CLOUDSTACK-4905) [VMWARE]System Vm's are failing to start with permission issue while unpacking the OVA file

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-4905?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Sailaja Mada closed CLOUDSTACK-4905.
------------------------------------

    Resolution: Invalid

Secondary storage was seeded with wrong template.  After seeding correct template, System VM's got started. Hence closing it as invalid.

> [VMWARE]System Vm's are failing to start with permission issue while unpacking the OVA file
> -------------------------------------------------------------------------------------------
>
>                 Key: CLOUDSTACK-4905
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4905
>             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: Sailaja Mada
>            Priority: Blocker
>             Fix For: 4.2.1
>
>         Attachments: logs.rar
>
>
> Steps:.
> 1. Install and configure Adv zone with VMWARE 5.0 ESXi server
> Observation:
> [VMWARE]System Vm's are failing to start with permission issue while unpacking the OVA file
> 2013-10-18 17:17:54,640 INFO  [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Template routing-8 is not setup yet, setup template from secondary storage with uuid name: 9bf83394f9cb38b7a438edd0e0a4c019
> 2013-10-18 17:17:54,671 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented
> 2013-10-18 17:17:54,720 INFO  [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Executing copyTemplateFromSecondaryToPrimary. secondaryStorage: nfs://10.102.192.100/cpg_vol/sailaja/dixonss1, templatePathAtSecondaryStorage: template/tmpl/1/8/, templateName: routing-8
> 2013-10-18 17:17:54,730 DEBUG [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) Executing: sudo mount -t nfs 10.102.192.100:/cpg_vol/sailaja/dixonss1 /var/cloudstack/mnt/VM/187767034175903.70267e11
> 2013-10-18 17:17:54,820 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented
> 2013-10-18 17:17:54,979 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[7-2-f701c522-8ba7-45e0-84e8-b7cece900016-10.102.195.146-null for VM[ConsoleProxy|v-2-VM]
> 2013-10-18 17:17:54,992 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-2-VM]
> 2013-10-18 17:17:55,060 DEBUG [storage.image.TemplateDataFactoryImpl] (consoleproxy-1:null) template 8 is already in store:1, type:Image
> 2013-10-18 17:17:55,086 DEBUG [storage.image.TemplateDataFactoryImpl] (consoleproxy-1:null) template 8 is already in store:1, type:Primary
> 2013-10-18 17:17:55,094 DEBUG [storage.volume.VolumeServiceImpl] (consoleproxy-1:null) Found template routing-8 in storage pool 1 with VMTemplateStoragePool id: 1
> 2013-10-18 17:17:55,125 DEBUG [storage.volume.VolumeServiceImpl] (consoleproxy-1:null) Acquire lock on VMTemplateStoragePool 1 with timeout 3600 seconds
> 2013-10-18 17:17:55,232 DEBUG [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) Execution is successful.
> 2013-10-18 17:17:55,232 DEBUG [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) Executing: sudo chmod -R 777 /var/cloudstack/mnt/VM/187767034175903.70267e11
> 2013-10-18 17:17:55,289 DEBUG [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) Exit value is 1
> 2013-10-18 17:17:55,289 DEBUG [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) chmod: changing permissions of `/var/cloudstack/mnt/VM/187767034175903.70267e11/.snapshot': Read-only file system
> 2013-10-18 17:17:55,289 WARN  [vmware.manager.VmwareManagerImpl] (DirectAgent-1:10.102.192.23) Unable to set permissions for /var/cloudstack/mnt/VM/187767034175903.70267e11 due to chmod: changing permissions of `/var/cloudstack/mnt/VM/187767034175903.70267e11/.snapshot': Read-only file system
> 2013-10-18 17:17:55,289 INFO  [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Secondary storage mount point: /var/cloudstack/mnt/VM/187767034175903.70267e11
> 2013-10-18 17:17:55,294 INFO  [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Executing command: tar --no-same-owner -xf /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> 2013-10-18 17:17:55,294 DEBUG [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Executing: tar --no-same-owner -xf /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> 2013-10-18 17:17:55,313 WARN  [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Exception: tar --no-same-owner -xf /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> java.io.IOException: Cannot run program "tar" (in directory "/var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8"): java.io.IOException: error=2, No such file or directory
>         at java.lang.ProcessBuilder.start(ProcessBuilder.java:475)
>         at com.cloud.utils.script.Script.execute(Script.java:183)
>         at com.cloud.utils.script.Script.execute(Script.java:161)
>         at com.cloud.storage.resource.VmwareStorageProcessor.copyTemplateFromSecondaryToPrimary(VmwareStorageProcessor.java:148)
>         at com.cloud.storage.resource.VmwareStorageProcessor.copyTemplateToPrimaryStorage(VmwareStorageProcessor.java:225)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:70)
>         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)
> Caused by: java.io.IOException: java.io.IOException: error=2, No such file or directory
>         at java.lang.UNIXProcess.<init>(UNIXProcess.java:164)
>         at java.lang.ProcessImpl.start(ProcessImpl.java:81)
>         at java.lang.ProcessBuilder.start(ProcessBuilder.java:468)
>         ... 17 more
> 2013-10-18 17:17:55,316 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> 2013-10-18 17:17:55,318 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-1:10.102.192.23) Unable to copy template to primary storage due to exception:Exception: java.lang.Exception
> Message: Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> java.lang.Exception: Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
>         at com.cloud.storage.resource.VmwareStorageProcessor.copyTemplateFromSecondaryToPrimary(VmwareStorageProcessor.java:152)
>         at com.cloud.storage.resource.VmwareStorageProcessor.copyTemplateToPrimaryStorage(VmwareStorageProcessor.java:225)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:70)
>         at com.cloud.storage.resource.VmwareStorageSubsystemCommandHandler.execute(VmwareStorageSubsystemCommandHandler.java:155)
>         at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
>  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-18 17:17:55,319 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-1:null) Seq 1-187498505: Response Received:
> 2013-10-18 17:17:55,320 DEBUG [agent.transport.Request] (DirectAgent-1:null) Seq 1-187498505: Processing:  { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unable to copy template to primary storage due to exception:Exception: java.lang.Exception\nMessage: Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova\n","wait":0}}] }
> 2013-10-18 17:17:55,320 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-187498505: Received:  { Ans: , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
> 2013-10-18 17:17:55,324 DEBUG [agent.manager.AgentAttache] (DirectAgent-1:null) Seq 1-187498505: No more commands found
> 2013-10-18 17:17:55,342 INFO  [storage.volume.VolumeServiceImpl] (secstorage-1:null) releasing lock for VMTemplateStoragePool 1
> 2013-10-18 17:17:55,343 WARN  [utils.db.Merovingian2] (secstorage-1:null) Was unable to find lock for the key template_spool_ref1 and thread id 376211979
> 2013-10-18 17:17:55,343 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Unable to create Vol[1|vm=1|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception
> Message: Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
> 2013-10-18 17:17:55,344 INFO  [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[1|vm=1|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception
> Message: Unable to unpack snapshot OVA file at: /var/cloudstack/mnt/VM/187767034175903.70267e11/template/tmpl/1/8//routing-8.ova
>         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:889)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571)
>         at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267)
>         at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696)
>         at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300)
>         at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
>         at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
>         at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
>         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-18 17:17:55,363 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-1-VM] in Starting state
> 2013-10-18 17:17:55,366 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-187498506: Sending  { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-1-VM","wait":0}}] }
> 2013-10-18 17:17:55,367 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-187498506: Executing:  { Cmd , MgmtId: 187767034175903, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-1-VM","wait":0}}] }
> 2013-10-18 17:17:55,367 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-6:null) Seq 1-187498506: Executing request
> 2013-10-18 17:17:55,367 INFO  [vmware.resource.VmwareResource] (DirectAgent-6:10.102.192.23) Executing resource StopCommand: {"isProxy":false,"executeInSequence":true,"vmName":"s-1-VM","wait":0}



--
This message was sent by Atlassian JIRA
(v6.1#6144)