It's been logged: https://issues.apache.org/jira/browse/CLOUDSTACK-5382<%22>
On 4 December 2013 21:48, Nitin Mehta <nitin.me...@citrix.com> wrote: > Sean - I can confirm from the code that what you have seen is a valid bug. > But should be a problem only for templates occurring in multiple zones. > Would you mind filing a bug for this please ? > > Thanks, > -Nitin > > On 04/12/13 1:44 PM, "Sean Hamilton" <s...@seanhamilton.co.uk> wrote: > > >We're seeing a bug where cloudstack tries to spool a template from any > >secondary storage in any zone in a region to primary storage. > > > >DB selects show a rand() at the end, it took a few attempts to get the > >template onto primary storage. > > > >Must be a bug. > > > >> On 4 Dec 2013, at 13:23, John Skinner <john.skin...@appcore.com> wrote: > >> > >> I did confirm that the template does exist in the directory. > >>> On Dec 3, 2013, at 11:05 PM, Sanjeev Neelarapu > >>><sanjeev.neelar...@citrix.com> wrote: > >>> > >>> Hi, > >>> > >>> Can you make sure that the template with which you are trying to > >>>deploy a VM is present on the secondary Storage inside 244 directory? > >>> > >>> -Sanjeev > >>> -----Original Message----- > >>> From: John Skinner [mailto:john.skin...@appcore.com] > >>> Sent: Wednesday, December 04, 2013 12:55 AM > >>> To: users@cloudstack.apache.org > >>> Subject: Unable to execute PrimaryStorageDownloadCommand > >>> > >>> Environment running CloudStack 4.1.1 with VMware vSphere 5.1 nodes and > >>>NFS backed Primary Storage data stores. We are currently having issues > >>>creating VMs from a template when we have to copy the template from > >>>secondary storage. If the template already exists on primary storage > >>>then the VM gets created just fine. I have already checked the mount > >>>points and vCenter has read/write access to the NFS share for secondary > >>>storage, and the secondary storage VM has the share mounted and can > >>>read/write to it as well. > >>> > >>> This is the exception from the management server logs: > >>> > >>> 2013-12-03 09:13:10,468 DEBUG [agent.manager.AgentManagerImpl] > >>>(Job-Executor-9:job-14655) Details from executing class > >>>com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Unable to > >>>execute PrimaryStorageDownloadCommand due to exception > >>> 2013-12-03 09:13:10,468 DEBUG [cloud.template.TemplateManagerImpl] > >>>(Job-Executor-9:job-14655) Template 244 download to pool 222 failed due > >>>to Unable to execute PrimaryStorageDownloadCommand due to exception > >>> 2013-12-03 09:13:10,469 DEBUG [cloud.template.TemplateManagerImpl] > >>>(Job-Executor-9:job-14655) Template 244 is not found on and can not be > >>>downloaded to pool 222 > >>> 2013-12-03 09:13:10,469 DEBUG [cloud.storage.StorageManagerImpl] > >>>(Job-Executor-9:job-14655) Cannot use this pool > >>>Pool[222|NetworkFilesystem] because we can't propagate template > >>>Tmpl[244-OVA-244-2-0e18671b-1f2a-3b10-8b1a-7608bda5695c > >>> 2013-12-03 09:13:10,505 DEBUG [agent.manager.AgentAttache] > >>>(AgentManager-Handler-15:null) Seq 59-806028519: No more commands found > >>> 2013-12-03 09:13:10,580 INFO [cloud.vm.VirtualMachineManagerImpl] > >>>(Job-Executor-9:job-14655) Unable to contact resource. > >>> com.cloud.exception.StorageUnavailableException: Resource > >>>[StoragePool:222] is unreachable: Unable to create > >>>Vol[11319|vm=11283|ROOT] > >>> at > >>>com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:348 > >>>8) > >>> at > >>>com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManage > >>>rImpl.java:748) > >>> at > >>>com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.j > >>>ava:471) > >>> at > >>>org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deploy > >>>VirtualMachine(VMEntityManagerImpl.java:212) > >>> at > >>>org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.d > >>>eploy(VirtualMachineEntityImpl.java:209) > >>> at > >>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.jav > >>>a:3871) > >>> at > >>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.jav > >>>a:3464) > >>> at > >>>com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.jav > >>>a:3450) > >>> at > >>>com.cloud.utils.component.ComponentInstantiationPostProcessor$Intercepto > >>>rDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > >>> at > >>>org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCm > >>>d.java:379) > >>> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162) > >>> at > >>>com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) > >>> 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.jav > >>>a:1146) > >>> at > >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja > >>>va:615) > >>> at java.lang.Thread.run(Thread.java:679) > >>> 2013-12-03 09:13:10,660 DEBUG [cloud.vm.VirtualMachineManagerImpl] > >>>(Job-Executor-9:job-14655) Cleaning up resources for the vm > >>>VM[User|OrangeTest] in Starting state > >>> > >>> And this is the same error, however this is from the systemvm.log on > >>>the Secondary Storage VM: > >>> > >>> 2013-12-03 15:26:43,125 DEBUG [cloud.agent.Agent] > >>>(agentRequest-Handler-5:) Processing command: > >>>com.cloud.agent.api.storage.PrimaryStorageDownloadCommand > >>> 2013-12-03 15:26:43,126 DEBUG > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Executing resource > >>>PrimaryStorageDownloadCommand: > >>>{"localPath":"/mnt/e2955a69-77f1-3888-a810-d2d54bd6bb0f","poolUuid":"e29 > >>>55a69-77f1-3888-a810-d2d54bd6bb0f","poolId":218,"primaryPool":{"id":218, > >>>"uuid":"e2955a69-77f1-3888-a810-d2d54bd6bb0f","host":"10.1.100.19","path > >>>":"/vol/vol_aCloud_1_01_7k","port":2049,"type":"NetworkFilesystem"},"sec > >>>ondaryStorageUrl":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k > ","primarySt > >>>orageUrl":"nfs://10.1.100.19/vol/vol_aCloud_1_01_7k > ","url":"nfs://10.1.1 > >>>00.20/vol/vol_aCloud_2_01_15k/template/tmpl/2/244//b2504ba2-5b61-3cdb-88 > >>>7e-f52eedf6d1bf.ova","format":"OVA","accountId":2,"name":"244-2-0e18671b > >>>-1f2a-3b10-8b1a-7608bda5695c","wait":10800} > >>> 2013-12-03 15:26:43,424 WARN > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Context validation failed due to Exception: > >>>java.lang.NullPointerException > >>> Message: null > >>> > >>> 2013-12-03 15:26:43,720 WARN [vmware.util.VmwareContext] > >>>(agentRequest-Handler-5:) Unexpected exception: > >>> com.vmware.apputils.ArgumentHandlingException: Exception running : > >>>10.0.50.70-10395 > >>> at > >>>com.vmware.apputils.version.ExtendedAppUtil.disConnect(ExtendedAppUtil.j > >>>ava:90) > >>> at > >>>com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java: > >>>598) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalida > >>>te(VmwareSecondaryStorageContextFactory.java:72) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalid > >>>ateServiceContext(VmwareSecondaryStorageResourceHandler.java:203) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServ > >>>iceContext(VmwareSecondaryStorageResourceHandler.java:186) > >>> at > >>>com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(Vmw > >>>areStorageManagerImpl.java:120) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute > >>>(VmwareSecondaryStorageResourceHandler.java:105) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute > >>>Request(VmwareSecondaryStorageResourceHandler.java:69) > >>> at > >>>com.cloud.storage.resource.PremiumSecondaryStorageResource.executeReques > >>>t(PremiumSecondaryStorageResource.java:54) > >>> at com.cloud.agent.Agent.processRequest(Agent.java:525) > >>> at > >>>com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852) > >>> at com.cloud.utils.nio.Task.run(Task.java:83) > >>> at > >>>java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecuto > >>>r.java:886) > >>> at > >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja > >>>va:908) > >>> at java.lang.Thread.run(Thread.java:662) > >>> 2013-12-03 15:26:46,074 DEBUG > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Context validation succeeded. Validated via > >>>host: 10.0.97.107, guid: HostSystem:host-3906@10.0.50.70 > >>> 2013-12-03 15:26:47,514 INFO > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Setup firewall rule for host: 10.0.97.101 > >>> 2013-12-03 15:26:48,408 INFO > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Setup firewall rule for host: 10.0.97.103 > >>> 2013-12-03 15:26:49,265 INFO > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Setup firewall rule for host: 10.0.97.105 > >>> 2013-12-03 15:26:50,138 INFO > >>>[storage.resource.VmwareSecondaryStorageResourceHandler] > >>>(agentRequest-Handler-5:) Setup firewall rule for host: 10.0.97.107 > >>> 2013-12-03 15:26:50,900 INFO > >>>[vmware.manager.VmwareStorageManagerImpl] (agentRequest-Handler-5:) > >>>Template b2504ba2-5b61-3cdb-887e-f52eedf6d1bf is not setup yet, setup > >>>template from secondary storage with uuid name: > >>>776550120fa43526a7b35637812b5db6 > >>> 2013-12-03 15:26:51,630 INFO > >>>[vmware.manager.VmwareStorageManagerImpl] (agentRequest-Handler-5:) > >>>Executing copyTemplateFromSecondaryToPrimary. secondaryStorage: > >>>nfs://10.1.100.20/vol/vol_aCloud_2_01_15k, > >>>templatePathAtSecondaryStorage: template/tmpl/2/244/, templateName: > >>>b2504ba2-5b61-3cdb-887e-f52eedf6d1bf > >>> 2013-12-03 15:26:51,631 DEBUG > >>>[storage.resource.NfsSecondaryStorageResource] > >>>(agentRequest-Handler-5:) Executing: mount > >>> 2013-12-03 15:26:51,634 DEBUG > >>>[storage.resource.NfsSecondaryStorageResource] > >>>(agentRequest-Handler-5:) Execution is successful. > >>> 2013-12-03 15:26:51,634 INFO > >>>[vmware.manager.VmwareStorageManagerImpl] (agentRequest-Handler-5:) > >>>Secondary storage mount point: > >>>/mnt/SecStorage/9df8a8d2-23c2-38d2-b0c1-eeca6a95ac96 > >>> 2013-12-03 15:26:53,447 ERROR > >>>[vmware.manager.VmwareStorageManagerImpl] (agentRequest-Handler-5:) > >>>Unable to execute PrimaryStorageDownloadCommand due to exception > >>>AxisFault > >>> faultCode: ServerFaultCode > >>> faultSubcode: > >>> faultString: > >>> Attribute xsi:nil not allowed on element spec, which is not nillable. > >>> > >>> while parsing call information for method ImportVApp at line 1, column > >>>227 > >>> > >>> while parsing SOAP body > >>> at line 1, column 213 > >>> > >>> while parsing SOAP envelope > >>> at line 1, column 38 > >>> > >>> while parsing HTTP request for method importVApp on object of type > >>>vim.ResourcePool at line 1, column 0 > >>> faultActor: > >>> faultNode: > >>> faultDetail: > >>> {urn:vim25}InvalidRequestFault:null > >>> > >>> > >>> Attribute xsi:nil not allowed on element spec, which is not nillable. > >>> > >>> while parsing call information for method ImportVApp at line 1, column > >>>227 > >>> > >>> while parsing SOAP body > >>> at line 1, column 213 > >>> > >>> while parsing SOAP envelope > >>> at line 1, column 38 > >>> > >>> while parsing HTTP request for method importVApp on object of type > >>>vim.ResourcePool at line 1, column 0 > >>> at > >>>sun.reflect.GeneratedConstructorAccessor110.newInstance(Unknown Source) > >>> at > >>>sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingCons > >>>tructorAccessorImpl.java:27) > >>> at > >>>java.lang.reflect.Constructor.newInstance(Constructor.java:513) > >>> at java.lang.Class.newInstance0(Class.java:355) > >>> at java.lang.Class.newInstance(Class.java:308) > >>> at > >>>org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.ja > >>>va:104) > >>> at > >>>org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.ja > >>>va:90) > >>> at > >>>com.vmware.vim25.InvalidRequest.getDeserializer(InvalidRequest.java:87) > >>> at sun.reflect.GeneratedMethodAccessor1150.invoke(Unknown Source) > >>> at > >>>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor > >>>Impl.java:25) > >>> at java.lang.reflect.Method.invoke(Method.java:597) > >>> at > >>>org.apache.axis.encoding.ser.BaseDeserializerFactory.getSpecialized(Base > >>>DeserializerFactory.java:154) > >>> at > >>>org.apache.axis.encoding.ser.BaseDeserializerFactory.getDeserializerAs(B > >>>aseDeserializerFactory.java:84) > >>> at > >>>org.apache.axis.encoding.DeserializationContext.getDeserializer(Deserial > >>>izationContext.java:464) > >>> at > >>>org.apache.axis.encoding.DeserializationContext.getDeserializerForType(D > >>>eserializationContext.java:547) > >>> at > >>>org.apache.axis.message.SOAPFaultDetailsBuilder.onStartChild(SOAPFaultDe > >>>tailsBuilder.java:157) > >>> at > >>>org.apache.axis.encoding.DeserializationContext.startElement(Deserializa > >>>tionContext.java:1035) > >>> at > >>>org.apache.xerces.parsers.AbstractSAXParser.startElement(Unknown Source) > >>> at > >>>org.apache.xerces.impl.XMLNSDocumentScannerImpl.scanStartElement(Unknown > >>> Source) > >>> at > >>>org.apache.xerces.impl.XMLDocumentFragmentScannerImpl$FragmentContentDis > >>>patcher.dispatch(Unknown Source) > >>> at > >>>org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unkno > >>>wn Source) > >>> at org.apache.xerces.parsers.XML11Configuration.parse(Unknown > >>>Source) > >>> at org.apache.xerces.parsers.XML11Configuration.parse(Unknown > >>>Source) > >>> at org.apache.xerces.parsers.XMLParser.parse(Unknown Source) > >>> at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown > >>>Source) > >>> at javax.xml.parsers.SAXParser.parse(SAXParser.java:395) > >>> at > >>>org.apache.axis.encoding.DeserializationContext.parse(DeserializationCon > >>>text.java:227) > >>> at org.apache.axis.SOAPPart.getAsSOAPEnvelope(SOAPPart.java:696) > >>> at org.apache.axis.Message.getSOAPEnvelope(Message.java:435) > >>> at > >>>org.apache.axis.handlers.soap.MustUnderstandChecker.invoke(MustUnderstan > >>>dChecker.java:62) > >>> at org.apache.axis.client.AxisClient.invoke(AxisClient.java:206) > >>> at org.apache.axis.client.Call.invokeEngine(Call.java:2784) > >>> at org.apache.axis.client.Call.invoke(Call.java:2767) > >>> at org.apache.axis.client.Call.invoke(Call.java:2443) > >>> at org.apache.axis.client.Call.invoke(Call.java:2366) > >>> at org.apache.axis.client.Call.invoke(Call.java:1812) > >>> at > >>>com.vmware.vim25.VimBindingStub.importVApp(VimBindingStub.java:46658) > >>> at > >>>com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.importVmFromOVF(Hype > >>>rvisorHostHelper.java:863) > >>> at > >>>com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681) > >>> at > >>>com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplat > >>>eFromSecondaryToPrimary(VmwareStorageManagerImpl.java:459) > >>> at > >>>com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(Vmw > >>>areStorageManagerImpl.java:138) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute > >>>(VmwareSecondaryStorageResourceHandler.java:105) > >>> at > >>>com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute > >>>Request(VmwareSecondaryStorageResourceHandler.java:69) > >>> at > >>>com.cloud.storage.resource.PremiumSecondaryStorageResource.executeReques > >>>t(PremiumSecondaryStorageResource.java:54) > >>> at com.cloud.agent.Agent.processRequest(Agent.java:525) > >>> at > >>>com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852) > >>> at com.cloud.utils.nio.Task.run(Task.java:83) > >>> at > >>>java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecuto > >>>r.java:886) > >>> at > >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja > >>>va:908) > >>> at java.lang.Thread.run(Thread.java:662) > >>> 2013-12-03 15:26:53,448 DEBUG [cloud.agent.Agent] > >>>(agentRequest-Handler-5:) Seq 30-428286227: { Ans: , MgmtId: > >>>90520730734904, via: 30, Ver: v1, Flags: 110, > >>>[{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":fals > >>>e,"details":"Unable to execute PrimaryStorageDownloadCommand due to > >>>exception","wait":0}}] } > >> > >
