Hi,
I have been trying to figure this one out for awhile now. I successfully
imported an OVA template created on VMWare (Win 2008 Server) into
Cloudstack and when I try to instantiate an instance using the template I
see the error "Unable to execute PrimaryStorageDownloadCommand due to
exception" in the log file. I am using NFS and the management server hosts
both secondary and primary storage locations. I have imported other
Windows templates and they run without difficulty, so I am stumped as to
what the problem could be.
I did notice some bugs back in release 2.2 regarding this error, but I
thought they were correct for the 3.0.2 release. Has anyone come across
this error?
I am using CloudStack 3.0.2 running on Ubuntu 10.04 and the host is VMWare
VCenter 5.0.
The log snippet is below.
Thanks.
--Jim L.
2012-12-04 12:52:47,915 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-366:10.40.10.100) Run vm_data command on domain router
10.40.10.68, data: routerIP
10.40.10.68
vmIP
10.100.104.84
userdata,user-data
none
metadata,service-offering
XLarge Instance
metadata,availability-zone
Zone-0
metadata,local-ipv4
10.100.104.84
metadata,local-hostname
CinegyTemplate
metadata,public-ipv4
10.40.10.20
metadata,public-hostname
10.40.10.20
metadata,instance-id
i-2-39-VM
metadata,vm-id
39
metadata,public-keys
none
metadata,cloud-identifier
CloudStack-{bedafd09-6066-4039-9a82-1c60d6366e31}
2012-12-04 12:52:48,348 DEBUG
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1
is ready to launch secondary storage VM
2012-12-04 12:52:48,441 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-12-04 12:52:48,708 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers.
2012-12-04 12:52:50,990 INFO [vmware.resource.VmwareResource]
(DirectAgent-366:10.40.10.100) vm_data command on domain router 10.40.10.68
completed
2012-12-04 12:52:50,994 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-366:null) Seq 1-998130062: Response Received:
2012-12-04 12:52:50,994 DEBUG [agent.transport.Request]
(DirectAgent-366:null) Seq 1-998130062: Processing: { Ans: , MgmtId:
345051131092, via: 1, Ver: v1, Flags: 110,
[{"Answer":{"result":true,"wait":0}},{"Answer":{"result":true,"wait":0}}] }
2012-12-04 12:52:50,994 DEBUG [agent.transport.Request]
(Job-Executor-32:job-111) Seq 1-998130062: Received: { Ans: , MgmtId:
345051131092, via: 1, Ver: v1, Flags: 110, { Answer, Answer } }
2012-12-04 12:52:50,994 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Cleanup succeeded. Details null
2012-12-04 12:52:50,994 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Cleanup succeeded. Details null
2012-12-04 12:52:50,994 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-32:job-111) Asking Ovs to prepare for
Nic[61-39-d576126a-f7aa-4f7d-ae8e-ba8e8748ace4-10.100.104.84]
2012-12-04 12:52:50,994 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-32:job-111) Asking ExternalDhcpServer to prepare for
Nic[61-39-d576126a-f7aa-4f7d-ae8e-ba8e8748ace4-10.100.104.84]
2012-12-04 12:52:50,997 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-32:job-111) Asking BareMetal to prepare for
Nic[61-39-d576126a-f7aa-4f7d-ae8e-ba8e8748ace4-10.100.104.84]
2012-12-04 12:52:50,998 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-32:job-111) Asking SecurityGroupProvider to prepare for
Nic[61-39-d576126a-f7aa-4f7d-ae8e-ba8e8748ace4-10.100.104.84]
2012-12-04 12:52:50,999 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-366:null) Cleanup succeeded. Details null
2012-12-04 12:52:50,999 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-366:null) Cleanup succeeded. Details null
2012-12-04 12:52:50,999 DEBUG [agent.manager.AgentAttache]
(DirectAgent-366:null) Seq 1-998130062: No more commands found
2012-12-04 12:52:51,001 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-32:job-111) Service SecurityGroup is not supported in the
network id=209
2012-12-04 12:52:51,002 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-32:job-111) Checking if we need to prepare 1 volumes for
VM[User|i-2-39-VM]
2012-12-04 12:52:51,007 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-32:job-111) Creating volume: Vol[40|vm=39|ROOT]
2012-12-04 12:52:51,007 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-32:job-111) Trying to create in Pool[200|NetworkFilesystem]
2012-12-04 12:52:51,017 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-32:job-111) Downloading 208 via 1
2012-12-04 12:52:51,030 DEBUG [agent.transport.Request]
(Job-Executor-32:job-111) Seq 5-675881158: Sending { Cmd , MgmtId:
345051131092, via: 5, Ver: v1, Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/6ca370f8-ea32-35b0-9848-9074f6a0be3c","poolUuid":"6ca370f8-ea32-35b0-9848-9074f6a0be3c","poolId":200,"secondaryStorageUrl":"nfs://
10.40.10.10/export/secondary","primaryStorageUrl":"nfs://
10.40.10.10/export/primary","url":"nfs://
10.40.10.10/export/secondary/template/tmpl//2/208//7099b88d-1640-3bd1-bdff-fb7f16d68213.ova","format":"OVA","accountId":2,"name":"208-2-b06bf5c5-47bc-3eb5-b482-f212ff587dd1","wait":10800}}]
}
2012-12-04 12:52:51,455 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2012-12-04 12:52:51,510 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-6:null) Cleanup succeeded. Details null
2012-12-04 12:52:51,510 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 5-675881159: Received: { Ans: , MgmtId:
345051131092, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-12-04 12:52:51,510 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2012-12-04 12:52:51,514 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-41:null) Seq 1-998130063: Executing request
2012-12-04 12:52:52,403 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-41:10.40.10.100) Datastore summary info, storageId:
6ca370f8-ea32-35b0-9848-9074f6a0be3c, localPath: /export/primary, poolType:
NetworkFilesystem, capacity: 463898075136, free: 389019492352, used:
74878582784
2012-12-04 12:52:52,404 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-41:null) Seq 1-998130063: Response Received:
2012-12-04 12:52:52,404 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 1-998130063: Received: { Ans: , MgmtId:
345051131092, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2012-12-04 12:52:52,404 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2012-12-04 12:52:52,404 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(DirectAgent-41:null) Cleanup succeeded. Details null
2012-12-04 12:53:01,230 DEBUG [agent.transport.Request]
(AgentManager-Handler-7:null) Seq 5-675881158: Processing: { Ans: ,
MgmtId: 345051131092, via: 5, Ver: v1, Flags: 110,
[{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Unable
to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
2012-12-04 12:53:01,230 DEBUG [agent.transport.Request]
(Job-Executor-32:job-111) Seq 5-675881158: Received: { Ans: , MgmtId:
345051131092, via: 5, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer }
}
2012-12-04 12:53:01,236 WARN [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Cleanup failed due to Unable to execute
PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:01,236 DEBUG [agent.manager.AgentManagerImpl]
(Job-Executor-32:job-111) Details from executing class
com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Unable to
execute PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:01,236 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-32:job-111) Template 208 download to pool 200 failed due to
Unable to execute PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:01,236 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-32:job-111) Downloading 208 via 1
2012-12-04 12:53:01,236 WARN [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-7:null) Cleanup failed due to Unable to execute
PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:01,237 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-7:null) Seq 5-675881158: No more commands found
2012-12-04 12:53:01,251 DEBUG [agent.transport.Request]
(Job-Executor-32:job-111) Seq 5-675881160: Sending { Cmd , MgmtId:
345051131092, via: 5, Ver: v1, Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/6ca370f8-ea32-35b0-9848-9074f6a0be3c","poolUuid":"6ca370f8-ea32-35b0-9848-9074f6a0be3c","poolId":200,"secondaryStorageUrl":"nfs://
10.40.10.10/export/secondary","primaryStorageUrl":"nfs://
10.40.10.10/export/primary","url":"nfs://
10.40.10.10/export/secondary/template/tmpl//2/208//7099b88d-1640-3bd1-bdff-fb7f16d68213.ova","format":"OVA","accountId":2,"name":"208-2-b06bf5c5-47bc-3eb5-b482-f212ff587dd1","wait":10800}}]
}
2012-12-04 12:53:08,663 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2012-12-04 12:53:11,207 DEBUG [agent.transport.Request]
(AgentManager-Handler-8:null) Seq 5-675881160: Processing: { Ans: ,
MgmtId: 345051131092, via: 5, Ver: v1, Flags: 110,
[{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Unable
to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
2012-12-04 12:53:11,207 DEBUG [agent.transport.Request]
(Job-Executor-32:job-111) Seq 5-675881160: Received: { Ans: , MgmtId:
345051131092, via: 5, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer }
}
2012-12-04 12:53:11,210 WARN [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Cleanup failed due to Unable to execute
PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:11,211 DEBUG [agent.manager.AgentManagerImpl]
(Job-Executor-32:job-111) Details from executing class
com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Unable to
execute PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:11,211 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-32:job-111) Template 208 download to pool 200 failed due to
Unable to execute PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:11,211 WARN [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-8:null) Cleanup failed due to Unable to execute
PrimaryStorageDownloadCommand due to exception
2012-12-04 12:53:11,211 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-8:null) Seq 5-675881160: No more commands found
2012-12-04 12:53:11,211 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-32:job-111) Template 208 is not found on and can not be
downloaded to pool 200
2012-12-04 12:53:11,212 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-32:job-111) Cannot use this pool Pool[200|NetworkFilesystem]
because we can't propagate template
Tmpl[208-OVA-208-2-b06bf5c5-47bc-3eb5-b482-f212ff587dd1
2012-12-04 12:53:11,214 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:200]
is unreachable: Unable to create Vol[40|vm=39|ROOT]
at
com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:2990)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:743)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:461)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2580)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2517)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:32)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:317)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:132)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:427)
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:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-12-04 12:53:11,227 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-32:job-111) Cleaning up resources for the vm
VM[User|i-2-39-VM] in Starting state
