[
https://issues.apache.org/jira/browse/CLOUDSTACK-1403?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13588714#comment-13588714
]
Sateesh Chodapuneedi commented on CLOUDSTACK-1403:
--------------------------------------------------
Analysis & Root cause:-
Due to connection issues the first attempt to download template from secondary
storage failed while importing OVA template.
This left a stale template object in the datacenter. Next attempt to download
the template has returned success as only existance of template with the
specific uuid is checked. No more attempts made to setup the template again.
The answer shows template size as 0. Atleast at this point the corruption in
template should have been detected.
The answer from logs is -
[{"storage.PrimaryStorageDownloadAnswer":{"installPath":"e372770297f73702b26a7898d041f3f8","templateSize":0,"result":true,"wait":0}}]
}
Any subsequent VM deployment would look to create a volume from this template
which fails as expected. After a successful import of OVA on primary storage, a
snapshot is taken to create a base snapshot from which volumes are created. But
due to IOException encountered while uploading the file to URL this snapshot
attempt was not made.
Fix:-
Handle IOException while uploading template to primary storage URL and cleanup
stale template. Working on unit testing now.
Changed priority from blocker to critical because of following reason.
We have work around for this issue. Delete the stale template that was created
in datacenter due to failed PrimaryStorageDownloadCommand. Subsequently a
template would be setup again freshly.
Extracts from log file:-
2013-02-19 16:04:47,525 INFO [vmware.resource.VmwareResource]
(DirectAgent-2:10.147.29.64) Executing resource PrimaryStorageDownloadCommand:
{"localPath":"/mnt/957db757-2da7-3172-b081-2d794fd7f772","poolUuid":"957db757-2da7-3172-b081-2d794fd7f772","poolId":200,"primaryPool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/secondary.vmware","primaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/primary1","url":"nfs://10.147.28.7/export/home/bharat/secondary.vmware/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}
2013-02-19 16:04:50,254 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-2:10.147.29.64) Template routing-8 is not setup yet, setup
template from secondary storage with uuid name: e372770297f73702b26a7898d041f3f8
2013-02-19 16:04:51,447 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-2:10.147.29.64) Executing copyTemplateFromSecondaryToPrimary.
secondaryStorage: nfs://10.147.28.7/export/home/bharat/secondary.vmware,
templatePathAtSecondaryStorage: template/tmpl/1/8/, templateName: routing-8
2013-02-19 16:04:51,448 DEBUG [vmware.manager.VmwareManagerImpl]
(DirectAgent-2:10.147.29.64) Executing: sudo mount -t nfs -o resvport
10.147.28.7:/export/home/bharat/secondary.vmware /mnt/VM/1.744d80f9
2013-02-19 16:06:15,448 DEBUG [vmware.manager.VmwareManagerImpl]
(DirectAgent-2:10.147.29.64) Executing: sudo chmod 777 /mnt/VM/1.744d80f9
2013-02-19 16:06:15,507 DEBUG [vmware.manager.VmwareManagerImpl]
(DirectAgent-2:10.147.29.64) Execution is successful.
2013-02-19 16:06:15,507 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-2:10.147.29.64) Secondary storage mount point: /mnt/VM/1.744d80f9
2013-02-19 16:06:28,461 INFO [vmware.mo.HypervisorHostHelper]
(DirectAgent-2:10.147.29.64) Resolving host name in url through vCenter, url:
https://10.147.29.64/nfc/52f60ee1-f3f1-1a77-bfb6-10dff5ad4bef/disk-0.vmdk
2013-02-19 16:06:28,461 INFO [vmware.mo.HypervisorHostHelper]
(DirectAgent-2:10.147.29.64) host name in url is already in IP address, url:
https://10.147.29.64/nfc/52f60ee1-f3f1-1a77-bfb6-10dff5ad4bef/disk-0.vmdk
2013-02-19 16:06:28,624 INFO [vmware.util.VmwareContext]
(DirectAgent-2:10.147.29.64) Connected, conn:
sun.net.www.protocol.https.DelegateHttpsURLConnection:https://10.147.29.64/nfc/52f60ee1-f3f1-1a77-bfb6-10dff5ad4bef/disk-0.vmdk,
retry: 0
2013-02-19 16:06:39,631 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:06:39,634 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:06:39,637 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:06:39,637 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) checking if agent (1) is alive
2013-02-19 16:06:39,642 DEBUG [agent.transport.Request] (AgentTaskPool-4:null)
Seq 1-443088904: Sending { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:06:39,642 DEBUG [agent.transport.Request] (AgentTaskPool-4:null)
Seq 1-443088904: Executing: { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:06:39,642 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-5:null) Seq 1-443088904: Executing request
2013-02-19 16:06:39,643 INFO [vmware.resource.VmwareResource]
(DirectAgent-5:10.147.29.64) Executing resource CheckHealthCommand: {"wait":50}
2013-02-19 16:06:41,605 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-02-19 16:06:41,607 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-02-19 16:06:41,646 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-02-19 16:06:41,648 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-02-19 16:06:42,303 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-5:null) Seq 1-443088904: Response Received:
2013-02-19 16:06:42,303 DEBUG [agent.transport.Request] (DirectAgent-5:null)
Seq 1-443088904: Processing: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10,
[{"CheckHealthAnswer":{"result":true,"details":"resource is alive","wait":0}}] }
2013-02-19 16:06:42,303 DEBUG [agent.transport.Request] (AgentTaskPool-4:null)
Seq 1-443088904: Received: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10, {
CheckHealthAnswer } }
2013-02-19 16:06:42,303 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-02-19 16:06:42,303 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-02-19 16:06:42,304 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) The state determined is Up
2013-02-19 16:06:42,304 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-4:null) Agent is determined to be up and running
2013-02-19 16:06:42,304 DEBUG [cloud.host.Status] (AgentTaskPool-4:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.147.29.64]
2013-02-19 16:06:42,310 DEBUG [cloud.host.Status] (AgentTaskPool-4:null) Agent
status update: [id = 1; name = 10.147.29.64; old status = Up; event = Ping; new
status = Up; old update count = 39; new update count = 40]
2013-02-19 16:06:43,201 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-7:null) Detecting a new state but couldn't find a old state so
adding it to the changes: e372770297f73702b26a7898d041f3f8
2013-02-19 16:06:43,797 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-7:null) Ping from 1.
2013-02-19 16:07:39,635 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:07:39,637 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:07:39,662 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-5:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:07:40,371 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-5:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-02-19 16:07:40,371 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-5:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-02-19 16:07:40,372 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-5:null) The state determined is Up
2013-02-19 16:07:40,372 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-5:null) Agent is determined to be up and running
2013-02-19 16:07:40,372 DEBUG [cloud.host.Status] (AgentTaskPool-5:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.147.29.64]
2013-02-19 16:07:40,378 DEBUG [cloud.host.Status] (AgentTaskPool-5:null) Agent
status update: [id = 1; name = 10.147.29.64; old status = Up; event = Ping; new
status = Up; old update count = 40; new update count = 41]
2013-02-19 16:08:39,637 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:08:39,638 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:08:39,662 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:08:39,663 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) checking if agent (1) is alive
2013-02-19 16:08:39,668 DEBUG [agent.transport.Request] (AgentTaskPool-6:null)
Seq 1-443088906: Sending { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:08:39,668 DEBUG [agent.transport.Request] (AgentTaskPool-6:null)
Seq 1-443088906: Executing: { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:08:39,668 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-443088906: Executing request
2013-02-19 16:08:39,669 INFO [vmware.resource.VmwareResource]
(DirectAgent-6:10.147.29.64) Executing resource CheckHealthCommand: {"wait":50}
2013-02-19 16:08:40,207 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-443088906: Response Received:
2013-02-19 16:08:40,207 DEBUG [agent.transport.Request] (DirectAgent-6:null)
Seq 1-443088906: Processing: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10,
[{"CheckHealthAnswer":{"result":true,"details":"resource is alive","wait":0}}] }
2013-02-19 16:08:40,207 DEBUG [agent.transport.Request] (AgentTaskPool-6:null)
Seq 1-443088906: Received: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10, {
CheckHealthAnswer } }
2013-02-19 16:08:40,207 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-02-19 16:08:40,207 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-02-19 16:08:40,207 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) The state determined is Up
2013-02-19 16:08:40,207 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-6:null) Agent is determined to be up and running
2013-02-19 16:08:40,208 DEBUG [cloud.host.Status] (AgentTaskPool-6:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.147.29.64]
2013-02-19 16:08:40,213 DEBUG [cloud.host.Status] (AgentTaskPool-6:null) Agent
status update: [id = 1; name = 10.147.29.64; old status = Up; event = Ping; new
status = Up; old update count = 41; new update count = 42]
2013-02-19 16:09:39,639 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:09:39,641 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:09:39,666 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:09:39,668 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) checking if agent (1) is alive
2013-02-19 16:09:39,672 DEBUG [agent.transport.Request] (AgentTaskPool-7:null)
Seq 1-443088907: Sending { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:09:39,672 DEBUG [agent.transport.Request] (AgentTaskPool-7:null)
Seq 1-443088907: Executing: { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:09:39,672 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-443088907: Executing request
2013-02-19 16:09:39,673 INFO [vmware.resource.VmwareResource]
(DirectAgent-6:10.147.29.64) Executing resource CheckHealthCommand: {"wait":50}
2013-02-19 16:09:40,194 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-443088907: Response Received:
2013-02-19 16:09:40,195 DEBUG [agent.transport.Request] (DirectAgent-6:null)
Seq 1-443088907: Processing: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10,
[{"CheckHealthAnswer":{"result":true,"details":"resource is alive","wait":0}}] }
2013-02-19 16:09:40,195 DEBUG [agent.transport.Request] (AgentTaskPool-7:null)
Seq 1-443088907: Received: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 10, {
CheckHealthAnswer } }
2013-02-19 16:09:40,196 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-02-19 16:09:40,196 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-02-19 16:09:40,196 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) The state determined is Up
2013-02-19 16:09:40,196 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-7:null) Agent is determined to be up and running
2013-02-19 16:09:40,196 DEBUG [cloud.host.Status] (AgentTaskPool-7:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.147.29.64]
2013-02-19 16:09:40,202 DEBUG [cloud.host.Status] (AgentTaskPool-7:null) Agent
status update: [id = 1; name = 10.147.29.64; old status = Up; event = Ping; new
status = Up; old update count = 42; new update count = 43]
2013-02-19 16:10:21,262 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
(SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-02-19
10:40:21 GMT
2013-02-19 16:10:21,264 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
(SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-02-19 10:40:21
GMT
2013-02-19 16:10:39,642 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:10:39,644 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:10:39,667 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-8:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:10:39,669 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-8:null) checking if agent (1) is alive
2013-02-19 16:10:39,673 DEBUG [agent.transport.Request] (AgentTaskPool-8:null)
Seq 1-443088908: Sending { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100011,
[{"CheckHealthCommand":{"wait":50}}] }
2013-02-19 16:11:40,339 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-9:null) Details from executing class
com.cloud.agent.api.CheckHealthCommand: resource is alive
2013-02-19 16:11:40,339 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-9:null) agent (1) responded to checkHeathCommand, reporting that
agent is Up
2013-02-19 16:11:40,339 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-9:null) The state determined is Up
2013-02-19 16:11:40,339 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-9:null) Agent is determined to be up and running
2013-02-19 16:11:40,339 DEBUG [cloud.host.Status] (AgentTaskPool-9:null)
Transition:[Resource state = Enabled, Agent event = Ping, Host id = 1, name =
10.147.29.64]
2013-02-19 16:11:40,345 DEBUG [cloud.host.Status] (AgentTaskPool-9:null) Agent
status update: [id = 1; name = 10.147.29.64; old status = Up; event = Ping; new
status = Up; old update count = 44; new update count = 45]
2013-02-19 16:11:43,755 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-1:null) Ping from 1
2013-02-19 16:12:39,648 INFO [agent.manager.AgentMonitor] (Thread-10:null)
Found the following agents behind on ping: [1]
2013-02-19 16:12:39,650 DEBUG [cloud.host.Status] (Thread-10:null) Ping timeout
for host 1, do invstigation
2013-02-19 16:12:39,675 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-10:null) Investigating why host 1 has disconnected with event
PingTimeout
2013-02-19 16:12:39,676 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-10:null) checking if agent (1) is alive
2013-02-19 16:13:10,191 INFO [vmware.mo.HttpNfcLeaseMO]
(DirectAgent-2:10.147.29.64) close ProgressReporter, interrupt reporter runner
to let it quit
2013-02-19 16:13:10,311 INFO [vmware.mo.HttpNfcLeaseMO] (Thread-26:null)
ProgressReporter stopped
2013-02-19 16:13:11,286 ERROR [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-2:10.147.29.64) Unable to execute PrimaryStorageDownloadCommand
due to exception
java.io.IOException: Error writing request body to server
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.checkError(HttpURLConnection.java:2805)
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.write(HttpURLConnection.java:2788)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
at
com.cloud.hypervisor.vmware.util.VmwareContext.uploadVmdkFile(VmwareContext.java:361)
at
com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.importVmFromOVF(HypervisorHostHelper.java:893)
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.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:3571)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:399)
at
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
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:680)
2013-02-19 16:13:11,289 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-2:null) Seq 1-443088903: Response Received:
2013-02-19 16:13:11,289 DEBUG [agent.transport.Request] (DirectAgent-2:null)
Seq 1-443088903: Processing: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 110,
[{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Unable
to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
2013-02-19 16:13:11,289 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-443088903: Received: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 110, {
PrimaryStorageDownloadAnswer } }
2013-02-19 16:13:11,289 DEBUG [agent.manager.AgentAttache] (DirectAgent-2:null)
Seq 1-443088903: No more commands found
2013-02-19 16:13:11,291 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-02-19 16:13:11,291 DEBUG [cloud.template.TemplateManagerImpl]
(consoleproxy-1:null) Template 8 download to pool 200 failed due to Unable to
execute PrimaryStorageDownloadCommand due to exception
2013-02-19 16:13:11,291 DEBUG [cloud.template.TemplateManagerImpl]
(consoleproxy-1:null) Downloading 8 via 1
2013-02-19 16:13:15,181 DEBUG [cloud.cluster.ClusterManagerImpl]
(Cluster-Heartbeat-1:null) Management server heartbeat takes too long to
finish. profiler: Done. Duration: 3590ms, profilerHeartbeatUpdate: Done.
Duration: 3587ms, profilerPeerScan: Done. Duration: 3ms, profilerAgentLB: Done.
Duration: 0ms
2013-02-19 16:13:15,181 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-02-19 16:13:15,184 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers to update status.
2013-02-19 16:13:15,187 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-02-19 16:13:15,187 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-02-19 16:13:15,205 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-443088911: Sending { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/957db757-2da7-3172-b081-2d794fd7f772","poolUuid":"957db757-2da7-3172-b081-2d794fd7f772","poolId":200,"primaryPool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/secondary.vmware","primaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/primary1","url":"nfs://10.147.28.7/export/home/bharat/secondary.vmware/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}}]
}
2013-02-19 16:13:15,206 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-443088911: Executing: { Cmd , MgmtId: 1, via: 1, Ver: v1, Flags: 100111,
[{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/957db757-2da7-3172-b081-2d794fd7f772","poolUuid":"957db757-2da7-3172-b081-2d794fd7f772","poolId":200,"primaryPool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/secondary.vmware","primaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/primary1","url":"nfs://10.147.28.7/export/home/bharat/secondary.vmware/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}}]
}
2013-02-19 16:13:15,206 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-12:null) Seq 1-443088911: Executing request
2013-02-19 16:13:16,263 INFO [vmware.resource.VmwareResource]
(DirectAgent-12:10.147.29.64) Executing resource PrimaryStorageDownloadCommand:
{"localPath":"/mnt/957db757-2da7-3172-b081-2d794fd7f772","poolUuid":"957db757-2da7-3172-b081-2d794fd7f772","poolId":200,"primaryPool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/secondary.vmware","primaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/primary1","url":"nfs://10.147.28.7/export/home/bharat/secondary.vmware/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}
2013-02-19 16:13:18,448 INFO [vmware.manager.VmwareStorageManagerImpl]
(DirectAgent-12:10.147.29.64) Template routing-8 has already been setup, skip
the template setup process in primary storage
2013-02-19 16:13:18,451 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-12:null) Seq 1-443088911: Response Received:
2013-02-19 16:13:18,464 DEBUG [agent.transport.Request] (DirectAgent-12:null)
Seq 1-443088911: Processing: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 110,
[{"storage.PrimaryStorageDownloadAnswer":{"installPath":"e372770297f73702b26a7898d041f3f8","templateSize":0,"result":true,"wait":0}}]
}
2013-02-19 16:13:18,465 DEBUG [agent.manager.AgentAttache]
(DirectAgent-12:null) Seq 1-443088911: No more commands found
2013-02-19 16:13:18,473 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 1-443088911: Received: { Ans: , MgmtId: 1, via: 1, Ver: v1, Flags: 110, {
PrimaryStorageDownloadAnswer } }
2013-02-19 16:13:18,483 DEBUG [cloud.template.TemplateManagerImpl]
(consoleproxy-1:null) Template 8 is downloaded via 1
> Storage and console-proxy related error
> ---------------------------------------
>
> Key: CLOUDSTACK-1403
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-1403
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Affects Versions: 4.1.0
> Reporter: Rohit Yadav
> Assignee: Sateesh Chodapuneedi
> Priority: Critical
> Fix For: 4.1.0
>
>
> While trying to verify/fix CLOUDSTACK-1252 I got this error:
> INFO [hypervisor.vmware.VmwareServerDiscoverer]
> (1650735361@qtp-1028456336-8:) Discover host. dc: 1, pod: 1, cluster: 1, uri
> host: 10.147.60.15
> Started
> INFO [vmware.manager.VmwareManagerImpl] (1650735361@qtp-1028456336-8:)
> Preparing network on host
> com.cloud.hypervisor.vmware.util.VmwareContext@2ca59fc for vSwitch0
> INFO [vmware.mo.HypervisorHostHelper] (1650735361@qtp-1028456336-8:) Network
> cloud.private.untagged.0.1-vSwitch0 is ready on vSwitch vSwitch0
> Started
> INFO [vmware.resource.VmwareResource] (1650735361@qtp-1028456336-8:)
> VmwareResource network configuration info. private vSwitch: vSwitch0, public
> vSwitch: vSwitch0, guest network: vSwitch0
> INFO [vmware.resource.VmwareResource] (1650735361@qtp-1028456336-8:) Startup
> report on host hardware info.
> {"memoryBytes":8465100800,"cpuCount":4,"cpuSpeed":3092}
> INFO [vmware.resource.VmwareResource] (1650735361@qtp-1028456336-8:) Startup
> report on host network info.
> {"hostIp":"10.147.29.64","hostNetmask":"255.255.255.0","hostMacAddress":"00:10:18:89:99:ac"}
> INFO [vmware.resource.VmwareResource] (1650735361@qtp-1028456336-8:) Add
> local storage startup command:
> {"totalSize":0,"poolInfo":{"uuid":"61c3c9fe-d775-4563-a6f7-88ba690a0289","host":"10.147.29.64","localPath":"","hostPath":"datastore-111","poolType":"LVM","capacityBytes":494726545408,"availableBytes":493706280960},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"1","pod":"1","cluster":"1","guid":"61c3c9fe-d775-4563-a6f7-88ba690a0289","name":"61c3c9fe-d775-4563-a6f7-88ba690a0289","wait":0}
> INFO [agent.manager.DirectAgentAttache] (1650735361@qtp-1028456336-8:)
> StartupAnswer received 1 Interval = 60
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) Executing
> resource CheckNetworkCommand
> {"networkInfoList":[{"physicalNetworkId":200}],"wait":0}
> INFO [network.security.SecurityGroupListener] (1650735361@qtp-1028456336-8:)
> Received a host startup notification
> INFO [network.security.SecurityGroupListener] (1650735361@qtp-1028456336-8:)
> Scheduled network rules cleanup, interval=2678
> INFO [network.security.SecurityGroupListener] (1650735361@qtp-1028456336-8:)
> Received a host startup notification
> WARN [cloud.vm.VirtualMachineManagerImpl] (1650735361@qtp-1028456336-8:)
> Stopping a VM that we have no record of <fullHostSync>: v-2-VM
> WARN [cloud.vm.VirtualMachineManagerImpl] (1650735361@qtp-1028456336-8:)
> Stopping a VM that we have no record of <fullHostSync>: s-13-VM
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) Executing
> resource StopCommand: {"isProxy":false,"vmName":"v-2-VM","wait":0}
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) VM v-2-VM
> is already in stopped state
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) Executing
> resource StopCommand: {"isProxy":false,"vmName":"s-13-VM","wait":0}
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) VM
> s-13-VM is already in stopped state
> INFO [vmware.resource.VmwareResource] (DirectAgent-2:10.147.29.64) Executing
> resource ReadyCommand: {"dcId":1,"hostId":1,"wait":0}
> INFO [cloud.resource.ResourceManagerImpl] (1650735361@qtp-1028456336-8:)
> External cluster has been successfully discovered by VMware Discover
> INFO [vmware.resource.VmwareResource] (DirectAgent-7:10.147.29.64) Executing
> resource ModifyStoragePoolCommand:
> {"add":true,"pool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"localPath":"/mnt//957db757-2da7-3172-b081-2d794fd7f772","wait":0}
> INFO [cloud.storage.StorageManagerImpl] (1754470817@qtp-1028456336-7:)
> Connection established between Pool[200|NetworkFilesystem] host + 1
> INFO [cloud.resource.ResourceManagerImpl] (1754470817@qtp-1028456336-7:)
> Trying to add a new host at
> nfs://10.147.28.7/export/home/bharat/secondary.vmware in data center 1
> ERROR [cloud.resource.ServerResourceBase] (1754470817@qtp-1028456336-7:) Nics
> are not configured!
> INFO [cloud.resource.ServerResourceBase] (1754470817@qtp-1028456336-7:)
> Designating private to be nic eth0
> INFO [network.security.SecurityGroupListener] (1754470817@qtp-1028456336-7:)
> Received a host startup notification
> WARN [agent.manager.AgentManagerImpl] (1754470817@qtp-1028456336-7:)
> Resource [Host:2] is unreachable: Host 2: Host with specified id is not in
> the right state: Connecting
> INFO [agent.manager.AgentManagerImpl] (1754470817@qtp-1028456336-7:) Host 2
> is disconnecting with event AgentDisconnected
> INFO [cloud.resource.ResourceManagerImpl] (1754470817@qtp-1028456336-7:)
> server resources successfully discovered by SecondaryStorage
> INFO [cloud.utils.AnnotationHelper] (1754470817@qtp-1028456336-7:)
> class java.lang.Stringdoes not have a Table annotation
> INFO [cloud.configuration.ConfigurationManagerImpl]
> (1754470817@qtp-1028456336-7:) No storage traffic type was specified by
> admin, create default storage traffic on physical network 200 with same
> configure of management traffic type
> INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:)
> No running secondary storage vms found in datacenter id=1, starting one
> INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:) No
> stopped secondary storage vm is available, need to allocate a new secondary
> storage vm
> INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:) No
> stopped console proxy is available, need to allocate a new console proxy
> WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:) Network
> Ntwk[204|Guest|6] is not associated with any VPC
> WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:) Network
> Ntwk[202|Control|3] is not associated with any VPC
> WARN [network.element.VpcVirtualRouterElement] (consoleproxy-1:) Network
> Ntwk[201|Management|2] is not associated with any VPC
> INFO [vmware.resource.VmwareResource] (DirectAgent-6:10.147.29.64) Executing
> resource PrimaryStorageDownloadCommand:
> {"localPath":"/mnt/957db757-2da7-3172-b081-2d794fd7f772","poolUuid":"957db757-2da7-3172-b081-2d794fd7f772","poolId":200,"primaryPool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"secondaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/secondary.vmware","primaryStorageUrl":"nfs://10.147.28.7/export/home/bharat/primary1","url":"nfs://10.147.28.7/export/home/bharat/secondary.vmware/template/tmpl/1/8/","format":"OVA","accountId":1,"name":"routing-8","wait":10800}
> WARN [network.element.VpcVirtualRouterElement] (secstorage-1:) Network
> Ntwk[204|Guest|6] is not associated with any VPC
> WARN [network.element.VpcVirtualRouterElement] (secstorage-1:) Network
> Ntwk[202|Control|3] is not associated with any VPC
> WARN [network.element.VpcVirtualRouterElement] (secstorage-1:) Network
> Ntwk[201|Management|2] is not associated with any VPC
> WARN [network.element.VpcVirtualRouterElement] (secstorage-1:) Network
> Ntwk[203|Storage|4] is not associated with any VPC
> INFO [agent.manager.AgentMonitor] (Thread-11:) Found the following agents
> behind on ping: [1]
> INFO [agent.manager.AgentManagerImpl] (AgentTaskPool-1:) Investigating why
> host 1 has disconnected with event PingTimeout
> INFO [vmware.resource.VmwareResource] (DirectAgent-4:10.147.29.64) Executing
> resource CheckHealthCommand: {"wait":50}
> INFO [agent.manager.AgentManagerImpl] (AgentTaskPool-1:) The state
> determined is Up
> INFO [agent.manager.AgentManagerImpl] (AgentTaskPool-1:) Agent is determined
> to be up and running
> INFO [vmware.manager.VmwareStorageManagerImpl] (DirectAgent-6:10.147.29.64)
> Template routing-8 has already been setup, skip the template setup process in
> primary storage
> INFO [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) Executing
> resource CreateCommand:
> {"volId":1,"pool":{"id":200,"uuid":"957db757-2da7-3172-b081-2d794fd7f772","host":"10.147.28.7","path":"/export/home/bharat/primary1","port":2049,"type":"NetworkFilesystem"},"diskCharacteristics":{"size":0,"tags":[],"type":"ROOT","name":"ROOT-1","useLocalStorage":false,"recreatable":true,"diskOfferingId":10,"volumeId":1,"hyperType":"VMware"},"templateUrl":"e372770297f73702b26a7898d041f3f8","wait":0}
> ERROR [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64) Unable to
> find template base snapshot, invalid template
> ERROR [vmware.resource.VmwareResource] (DirectAgent-1:10.147.29.64)
> CreateCommand failed due to Exception: java.lang.Exception
> Message: Unable to find template base snapshot, invalid template
> java.lang.Exception: Unable to find template base snapshot, invalid template
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:3835)
> at
> com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:335)
> 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:1146)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:679)
> INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:) Unable to
> contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:200]
> is unreachable: Unable to create Vol[1|vm=1|ROOT]
> at
> com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3472)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
> at
> com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:37)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
> at
> org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
> at sun.proxy.$Proxy142.prepare(Unknown Source)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:738)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:461)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:454)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
> at
> com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:37)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
> at
> org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
> at sun.proxy.$Proxy230.start(Unknown Source)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:630)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1960)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:174)
> at
> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
> at
> com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at
> com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> 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)
> INFO [vmware.resource.VmwareResource] (DirectAgent-5:10.147.29.64) Executing
> resource StopCommand: {"isProxy":false,"vmName":"v-1-VM","wait":0}
> INFO [vmware.resource.VmwareResource] (DirectAgent-5:10.147.29.64) VM v-1-VM
> is no longer in vSphere
> WARN [cloud.vm.SystemVmLoadScanner] (consoleproxy-1:) Unexpected exception
> null
> java.lang.NullPointerException
> at
> com.cloud.agent.manager.allocator.impl.RecreateHostAllocator.allocateTo(RecreateHostAllocator.java:95)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
> at
> com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:37)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
> at
> org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
> at sun.proxy.$Proxy258.allocateTo(Unknown Source)
> at
> com.cloud.deploy.FirstFitPlanner.findSuitableHosts(FirstFitPlanner.java:713)
> at
> com.cloud.deploy.FirstFitPlanner.checkClustersforDestination(FirstFitPlanner.java:520)
> at
> com.cloud.deploy.FirstFitPlanner.scanClustersForDestinationInZoneOrPod(FirstFitPlanner.java:388)
> at com.cloud.deploy.FirstFitPlanner.plan(FirstFitPlanner.java:278)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
> at
> com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:37)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
> at
> org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
> at sun.proxy.$Proxy269.plan(Unknown Source)
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:699)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:461)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:454)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
> at
> com.cloud.utils.db.TransactionContextBuilder.AroundAnyMethod(TransactionContextBuilder.java:37)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:616)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
> at
> org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
> at
> org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
> at sun.proxy.$Proxy230.start(Unknown Source)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:630)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1960)
> at
> com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:174)
> at
> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
> at
> com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at
> com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> 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)
--
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
