You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by John Skinner <jo...@appcore.com> on 2013/12/03 20:25:15 UTC
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:3488)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.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.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":"e2955a69-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"},"secondaryStorageUrl":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k","primaryStorageUrl":"nfs://10.1.100.19/vol/vol_aCloud_1_01_7k","url":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k/template/tmpl/2/244//b2504ba2-5b61-3cdb-887e-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.java:90)
at com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java:598)
at com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalidate(VmwareSecondaryStorageContextFactory.java:72)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalidateServiceContext(VmwareSecondaryStorageResourceHandler.java:203)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServiceContext(VmwareSecondaryStorageResourceHandler.java:186)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:120)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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(DelegatingConstructorAccessorImpl.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.java:104)
at org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.java:90)
at com.vmware.vim25.InvalidRequest.getDeserializer(InvalidRequest.java:87)
at sun.reflect.GeneratedMethodAccessor1150.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.axis.encoding.ser.BaseDeserializerFactory.getSpecialized(BaseDeserializerFactory.java:154)
at org.apache.axis.encoding.ser.BaseDeserializerFactory.getDeserializerAs(BaseDeserializerFactory.java:84)
at org.apache.axis.encoding.DeserializationContext.getDeserializer(DeserializationContext.java:464)
at org.apache.axis.encoding.DeserializationContext.getDeserializerForType(DeserializationContext.java:547)
at org.apache.axis.message.SOAPFaultDetailsBuilder.onStartChild(SOAPFaultDetailsBuilder.java:157)
at org.apache.axis.encoding.DeserializationContext.startElement(DeserializationContext.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$FragmentContentDispatcher.dispatch(Unknown Source)
at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown 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(DeserializationContext.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(MustUnderstandChecker.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(HypervisorHostHelper.java:863)
at com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplateFromSecondaryToPrimary(VmwareStorageManagerImpl.java:459)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:138)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":false,"details":"Unable to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
Re: Unable to execute PrimaryStorageDownloadCommand
Posted by Sean Hamilton <se...@seanhamilton.co.uk>.
It's been logged: https://issues.apache.org/jira/browse/CLOUDSTACK-5382<%22>
On 4 December 2013 21:48, Nitin Mehta <Ni...@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" <se...@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 <jo...@appcore.com> wrote:
> >>
> >> I did confirm that the template does exist in the directory.
> >>> On Dec 3, 2013, at 11:05 PM, Sanjeev Neelarapu
> >>><sa...@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.skinner@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}}] }
> >>
>
>
Re: Unable to execute PrimaryStorageDownloadCommand
Posted by Nitin Mehta <Ni...@citrix.com>.
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" <se...@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 <jo...@appcore.com> wrote:
>>
>> I did confirm that the template does exist in the directory.
>>> On Dec 3, 2013, at 11:05 PM, Sanjeev Neelarapu
>>><sa...@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.skinner@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}}] }
>>
Re: Unable to execute PrimaryStorageDownloadCommand
Posted by Sean Hamilton <se...@seanhamilton.co.uk>.
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 <jo...@appcore.com> wrote:
>
> I did confirm that the template does exist in the directory.
>> On Dec 3, 2013, at 11:05 PM, Sanjeev Neelarapu <sa...@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.skinner@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:3488)
>> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
>> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
>> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
>> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
>> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
>> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
>> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
>> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
>> at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.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.java:1146)
>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":"e2955a69-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"},"secondaryStorageUrl":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k","primaryStorageUrl":"nfs://10.1.100.19/vol/vol_aCloud_1_01_7k","url":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k/template/tmpl/2/244//b2504ba2-5b61-3cdb-887e-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.java:90)
>> at com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java:598)
>> at com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalidate(VmwareSecondaryStorageContextFactory.java:72)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalidateServiceContext(VmwareSecondaryStorageResourceHandler.java:203)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServiceContext(VmwareSecondaryStorageResourceHandler.java:186)
>> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:120)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
>> at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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(DelegatingConstructorAccessorImpl.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.java:104)
>> at org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.java:90)
>> at com.vmware.vim25.InvalidRequest.getDeserializer(InvalidRequest.java:87)
>> at sun.reflect.GeneratedMethodAccessor1150.invoke(Unknown Source)
>> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>> at java.lang.reflect.Method.invoke(Method.java:597)
>> at org.apache.axis.encoding.ser.BaseDeserializerFactory.getSpecialized(BaseDeserializerFactory.java:154)
>> at org.apache.axis.encoding.ser.BaseDeserializerFactory.getDeserializerAs(BaseDeserializerFactory.java:84)
>> at org.apache.axis.encoding.DeserializationContext.getDeserializer(DeserializationContext.java:464)
>> at org.apache.axis.encoding.DeserializationContext.getDeserializerForType(DeserializationContext.java:547)
>> at org.apache.axis.message.SOAPFaultDetailsBuilder.onStartChild(SOAPFaultDetailsBuilder.java:157)
>> at org.apache.axis.encoding.DeserializationContext.startElement(DeserializationContext.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$FragmentContentDispatcher.dispatch(Unknown Source)
>> at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown 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(DeserializationContext.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(MustUnderstandChecker.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(HypervisorHostHelper.java:863)
>> at com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681)
>> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplateFromSecondaryToPrimary(VmwareStorageManagerImpl.java:459)
>> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:138)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
>> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
>> at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":false,"details":"Unable to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
>
Re: Unable to execute PrimaryStorageDownloadCommand
Posted by John Skinner <jo...@appcore.com>.
I did confirm that the template does exist in the directory.
On Dec 3, 2013, at 11:05 PM, Sanjeev Neelarapu <sa...@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.skinner@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:3488)
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
> at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
> at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
> at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
> at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.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.java:1146)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":"e2955a69-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"},"secondaryStorageUrl":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k","primaryStorageUrl":"nfs://10.1.100.19/vol/vol_aCloud_1_01_7k","url":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k/template/tmpl/2/244//b2504ba2-5b61-3cdb-887e-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.java:90)
> at com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java:598)
> at com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalidate(VmwareSecondaryStorageContextFactory.java:72)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalidateServiceContext(VmwareSecondaryStorageResourceHandler.java:203)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServiceContext(VmwareSecondaryStorageResourceHandler.java:186)
> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:120)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
> at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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(DelegatingConstructorAccessorImpl.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.java:104)
> at org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.java:90)
> at com.vmware.vim25.InvalidRequest.getDeserializer(InvalidRequest.java:87)
> at sun.reflect.GeneratedMethodAccessor1150.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.axis.encoding.ser.BaseDeserializerFactory.getSpecialized(BaseDeserializerFactory.java:154)
> at org.apache.axis.encoding.ser.BaseDeserializerFactory.getDeserializerAs(BaseDeserializerFactory.java:84)
> at org.apache.axis.encoding.DeserializationContext.getDeserializer(DeserializationContext.java:464)
> at org.apache.axis.encoding.DeserializationContext.getDeserializerForType(DeserializationContext.java:547)
> at org.apache.axis.message.SOAPFaultDetailsBuilder.onStartChild(SOAPFaultDetailsBuilder.java:157)
> at org.apache.axis.encoding.DeserializationContext.startElement(DeserializationContext.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$FragmentContentDispatcher.dispatch(Unknown Source)
> at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown 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(DeserializationContext.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(MustUnderstandChecker.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(HypervisorHostHelper.java:863)
> at com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681)
> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplateFromSecondaryToPrimary(VmwareStorageManagerImpl.java:459)
> at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:138)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
> at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
> at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":false,"details":"Unable to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
RE: Unable to execute PrimaryStorageDownloadCommand
Posted by Sanjeev Neelarapu <sa...@citrix.com>.
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.skinner@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:3488)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:748)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:471)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:212)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3871)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3464)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3450)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.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.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":"e2955a69-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"},"secondaryStorageUrl":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k","primaryStorageUrl":"nfs://10.1.100.19/vol/vol_aCloud_1_01_7k","url":"nfs://10.1.100.20/vol/vol_aCloud_2_01_15k/template/tmpl/2/244//b2504ba2-5b61-3cdb-887e-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.java:90)
at com.cloud.hypervisor.vmware.util.VmwareContext.close(VmwareContext.java:598)
at com.cloud.storage.resource.VmwareSecondaryStorageContextFactory.invalidate(VmwareSecondaryStorageContextFactory.java:72)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.invalidateServiceContext(VmwareSecondaryStorageResourceHandler.java:203)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.getServiceContext(VmwareSecondaryStorageResourceHandler.java:186)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:120)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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(DelegatingConstructorAccessorImpl.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.java:104)
at org.apache.axis.encoding.ser.BeanDeserializer.<init>(BeanDeserializer.java:90)
at com.vmware.vim25.InvalidRequest.getDeserializer(InvalidRequest.java:87)
at sun.reflect.GeneratedMethodAccessor1150.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.axis.encoding.ser.BaseDeserializerFactory.getSpecialized(BaseDeserializerFactory.java:154)
at org.apache.axis.encoding.ser.BaseDeserializerFactory.getDeserializerAs(BaseDeserializerFactory.java:84)
at org.apache.axis.encoding.DeserializationContext.getDeserializer(DeserializationContext.java:464)
at org.apache.axis.encoding.DeserializationContext.getDeserializerForType(DeserializationContext.java:547)
at org.apache.axis.message.SOAPFaultDetailsBuilder.onStartChild(SOAPFaultDetailsBuilder.java:157)
at org.apache.axis.encoding.DeserializationContext.startElement(DeserializationContext.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$FragmentContentDispatcher.dispatch(Unknown Source)
at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown 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(DeserializationContext.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(MustUnderstandChecker.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(HypervisorHostHelper.java:863)
at com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplateFromSecondaryToPrimary(VmwareStorageManagerImpl.java:459)
at com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:138)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.execute(VmwareSecondaryStorageResourceHandler.java:105)
at com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:69)
at com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(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(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: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":false,"details":"Unable to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }