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}}] }
