Chandan Purushothama created CLOUDSTACK-1774:
------------------------------------------------
Summary: Used Master Branch System VM Template: Volume of System
VM Failed to Create on the ESXi host due to Runtime Error
Key: CLOUDSTACK-1774
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-1774
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Management Server
Affects Versions: 4.2.0
Reporter: Chandan Purushothama
Priority: Blocker
Fix For: 4.2.0
Observed the bug on an Advanced Zone setup where I used the new master branch
System VM Template for VMWare. I am not sure whether the bug is in the
CloudStack management server code or the System VM Template itself. I will
re-check the build using the old System VM Template and add more information to
the bug report.
===========
Observations:
===========
2013-03-21 19:44:24,629 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-62062601: Sending { Cmd , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolUuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolId":200,"primaryPool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary","primaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/primary","url":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}}]
}
2013-03-21 19:44:24,630 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-62062601: Executing: { Cmd , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolUuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolId":200,"primaryPool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary","primaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/primary","url":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}}]
}
2013-03-21 19:44:24,631 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-1:null) Seq 1-62062601: Executing request
2013-03-21 19:44:24,632 INFO [vmware.resource.VmwareResource]
(DirectAgent-1:10.223.59.66) Executing resource PrimaryStorageDownloadCommand:
{"localPath":"/mnt/d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolUuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","poolId":200,"primaryPool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary","primaryStorageUrl":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/primary","url":"nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}
2013-03-21 19:44:24,642 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-5:null) Seq 1-62062600: Response Received:
2013-03-21 19:44:24,643 DEBUG [agent.transport.Request] (DirectAgent-5:null)
Seq 1-62062600: Processing: { Ans: , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 10, [{"CheckHealthAnswer":{"result":true,"details":"resource is
alive","wait":0}}] }
2013-03-21 19:44:24,643 DEBUG [agent.transport.Request] (AgentTaskPool-1:null)
Seq 1-62062600: Received: { Ans: , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 10, { CheckHealthAnswer } }
2013-03-21 19:44:24,643 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-1:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-03-21 19:44:24,643 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-1:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-03-21 19:44:24,643 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-1:null) The state determined is Up
2013-03-21 19:44:24,643 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-1:null) Agent is determined to be up and running
2013-03-21 19:44:24,643 DEBUG [cloud.host.Status] (AgentTaskPool-1:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.223.59.66]
2013-03-21 19:44:24,656 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-1:10.223.59.66) Template routing-8 is not setup yet, setup
template from secondary storage with uuid name: b3ec0e8a2229370f80cc00b0ad6c4c72
2013-03-21 19:44:24,659 DEBUG [cloud.host.Status] (AgentTaskPool-1:null) Agent
status update: [id = 1; name = 10.223.59.66; old status = Up; event = Ping; new
status = Up; old update count = 2; new update count = 3]
2013-03-21 19:44:24,668 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-1:10.223.59.66) Executing copyTemplateFromSecondaryToPrimary.
secondaryStorage:
nfs://10.223.110.232/export/home/chandan/asfmas-59-67/secondary,
templatePathAtSecondaryStorage: template/tmpl/1/8/, templateName: routing-8
2013-03-21 19:44:24,668 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-1:10.223.59.66) Secondary storage mount point:
/var/cloudstack/mnt/NEWSYSTEMPLVMW/206915885093604.e5d2f74
2013-03-21 19:44:24,674 ERROR [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-1:10.223.59.66) Unable to execute PrimaryStorageDownloadCommand
due to exception
java.io.FileNotFoundException:
/var/cloudstack/mnt/NEWSYSTEMPLVMW/206915885093604.e5d2f74/template/tmpl/1/8/systemvmtemplate-2013-03-20-master-vmware.ovf
(Permission denied)
at java.io.FileInputStream.open(Native Method)
at java.io.FileInputStream.<init>(FileInputStream.java:137)
at java.io.FileInputStream.<init>(FileInputStream.java:96)
at
com.cloud.hypervisor.vmware.mo.HttpNfcLeaseMO.readOvfContent(HttpNfcLeaseMO.java:125)
at
com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.importVmFromOVF(HypervisorHostHelper.java:981)
at
com.cloud.hypervisor.vmware.mo.HostMO.importVmFromOVF(HostMO.java:681)
at
com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.copyTemplateFromSecondaryToPrimary(VmwareStorageManagerImpl.java:478)
at
com.cloud.hypervisor.vmware.manager.VmwareStorageManagerImpl.execute(VmwareStorageManagerImpl.java:153)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:3660)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:414)
at
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-03-21 19:44:24,676 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-1:null) Seq 1-62062601: Response Received:
2013-03-21 19:44:24,676 DEBUG [agent.transport.Request] (DirectAgent-1:null)
Seq 1-62062601: Processing: { Ans: , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 110,
[{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Unable
to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
2013-03-21 19:44:24,676 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-62062601: Received: { Ans: , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 110, { PrimaryStorageDownloadAnswer } }
2013-03-21 19:44:24,676 DEBUG [agent.manager.AgentAttache] (DirectAgent-1:null)
Seq 1-62062601: No more commands found
2013-03-21 19:44:24,677 DEBUG [agent.manager.AgentManagerImpl]
(consoleproxy-1:null) Details from executing class
com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: Unable to execute
PrimaryStorageDownloadCommand due to exception
2013-03-21 19:44:24,677 DEBUG [cloud.template.TemplateManagerImpl]
(consoleproxy-1:null) Template 8 download to pool 200 failed due to Unable to
execute PrimaryStorageDownloadCommand due to exception
2013-03-21 19:44:24,678 DEBUG [cloud.template.TemplateManagerImpl]
(consoleproxy-1:null) Template 8 is not found on and can not be downloaded to
pool 200
2013-03-21 19:44:24,744 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-62062602: Sending { Cmd , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 100111,
[{"storage.CreateCommand":{"volId":2,"pool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":0,"tags":[],"type":"ROOT","name":"ROOT-2","useLocalStorage":false,"recreatable":true,"diskOfferingId":10,"volumeId":2},"wait":0}}]
}
2013-03-21 19:44:24,745 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-62062602: Executing: { Cmd , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 100111,
[{"storage.CreateCommand":{"volId":2,"pool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":0,"tags":[],"type":"ROOT","name":"ROOT-2","useLocalStorage":false,"recreatable":true,"diskOfferingId":10,"volumeId":2},"wait":0}}]
}
2013-03-21 19:44:24,745 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-62062602: Executing request
2013-03-21 19:44:24,747 INFO [vmware.resource.VmwareResource]
(DirectAgent-6:10.223.59.66) Executing resource CreateCommand:
{"volId":2,"pool":{"id":200,"uuid":"d7574a80-9bb1-3c9c-be00-f12d6fd010f6","host":"10.223.110.232","path":"/export/home/chandan/asfmas-59-67/primary","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":0,"tags":[],"type":"ROOT","name":"ROOT-2","useLocalStorage":false,"recreatable":true,"diskOfferingId":10,"volumeId":2},"wait":0}
2013-03-21 19:44:27,227 DEBUG [vmware.mo.HostMO] (DirectAgent-6:10.223.59.66)
find VM 56b1ebcb2b854ec5b786d6be4afcaaa4 on host
2013-03-21 19:44:27,227 DEBUG [vmware.mo.HostMO] (DirectAgent-6:10.223.59.66)
load VM cache on host
2013-03-21 19:44:27,238 INFO [vmware.resource.VmwareResource]
(DirectAgent-6:10.223.59.66) Delete file if exists in datastore to clear the
way for creating the volume. file: [d7574a809bb13c9cbe00f12d6fd010f6]
ROOT-2-2.vmdk
2013-03-21 19:44:27,243 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) Search file ROOT-2-2.vmdk on
[d7574a809bb13c9cbe00f12d6fd010f6]
2013-03-21 19:44:27,258 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) File [d7574a809bb13c9cbe00f12d6fd010f6]
ROOT-2-2.vmdk does not exist on datastore
2013-03-21 19:44:27,261 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) Search file ROOT-2-2-flat.vmdk on
[d7574a809bb13c9cbe00f12d6fd010f6]
2013-03-21 19:44:27,277 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) File [d7574a809bb13c9cbe00f12d6fd010f6]
ROOT-2-2-flat.vmdk does not exist on datastore
2013-03-21 19:44:27,280 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) Search file ROOT-2-2-delta.vmdk on
[d7574a809bb13c9cbe00f12d6fd010f6]
2013-03-21 19:44:27,298 INFO [vmware.mo.DatastoreMO]
(DirectAgent-6:10.223.59.66) File [d7574a809bb13c9cbe00f12d6fd010f6]
ROOT-2-2-delta.vmdk does not exist on datastore
2013-03-21 19:44:27,843 INFO [vmware.resource.VmwareResource]
(DirectAgent-6:10.223.59.66) Destroy dummy VM after volume creation
2013-03-21 19:44:28,898 ERROR [vmware.resource.VmwareResource]
(DirectAgent-6:10.223.59.66) CreateCommand failed due to Exception:
java.lang.RuntimeException
Message: Invalid configuration for device '0'.
java.lang.RuntimeException: Invalid configuration for device '0'.
at
com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:291)
at
com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createDisk(VirtualMachineMO.java:944)
at
com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createDisk(VirtualMachineMO.java:867)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:3955)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:348)
at
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-03-21 19:44:28,900 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-62062602: Response Received:
2013-03-21 19:44:28,901 DEBUG [agent.transport.Request] (DirectAgent-6:null)
Seq 1-62062602: Processing: { Ans: , MgmtId: 206915885093604, via: 1, Ver: v1,
Flags: 110,
[{"storage.CreateAnswer":{"requestTemplateReload":false,"result":false,"details":"Exception:
java.lang.Exception\nMessage: java.lang.RuntimeException: Invalid
configuration for device '0'.\nStack: java.lang.Exception:
java.lang.RuntimeException: Invalid configuration for device '0'.\n\tat
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:4034)\n\tat
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:348)\n\tat
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)\n\tat
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tat
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tat
java.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tat
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)\n\tat
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)\n\tat
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat
java.lang.Thread.run(Thread.java:679)\nCaused by: java.lang.RuntimeException:
Invalid configuration for device '0'.\n\tat
com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:291)\n\tat
com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createDisk(VirtualMachineMO.java:944)\n\tat
com.cloud.hypervisor.vmware.mo.VirtualMachineMO.createDisk(VirtualMachineMO.java:867)\n\tat
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:3955)\n\t...
10 more\n","wait":0}}] }
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
