-----Original Message-----
From: Sebastian Trampler [mailto:[email protected]]
Sent: Friday, November 29, 2013 1:18 PM
To: [email protected]
Subject: SSVM won't start
Hello,
we have problems starting the ssvm.
First of all some facts about our actual test system.
Cloudstack is installed on Ubuntu 12.04. Primary and secondary storage are
nfs shares hosted on Cloudstack server.
Host is a XenServer 6.2.
While starting the ssvm we get the following error messages:
2013-11-29 08:38:10,103 DEBUG [storage.volume.VolumeServiceImpl]
(consoleproxy-1:null) Acquire lock on VMTemplateStoragePool 2280 with
timeout 3600 seconds
2013-11-29 08:38:10,107 INFO [storage.volume.VolumeServiceImpl]
(consoleproxy-1:null) lock is acquired for VMTemplateStoragePool 2280
2013-11-29 08:38:10,109 DEBUG [cloud.storage.VolumeManagerImpl]
(secstorage-1:null) Checking if we need to prepare 1 volumes for
VM[SecondaryStorageVm|s-1159-VM]
2013-11-29 08:38:10,135 DEBUG
[storage.motion.AncientDataMotionStrategy]
(consoleproxy-1:null) copyAsync inspecting src type TEMPLATE copyAsync
inspecting dest type TEMPLATE
2013-11-29 08:38:10,137 DEBUG [storage.image.TemplateDataFactoryImpl]
(secstorage-1:null) template 1 is already in store:2, type:Image
2013-11-29 08:38:10,171 DEBUG [storage.image.TemplateDataFactoryImpl]
(secstorage-1:null) template 1 is already in store:2, type:Primary
2013-11-29 08:38:10,174 DEBUG [storage.volume.VolumeServiceImpl]
(secstorage-1:null) Found template routing-1 in storage pool 2 with
VMTemplateStoragePool id: 2280
2013-11-29 08:38:10,185 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371787: Sending { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.
apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1
/1/","origUrl":"http://download.cloud.com/templates/4.2/systemvmtempla
te-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-4d43-11e3-8eab-
c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032
a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM
Template
(XenServer)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nf
s://172.16.51.47:/export/secondary2","_role":"Image"}},"name":"routing-
1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storag
e.to.TemplateObjectTO":{"origUrl":"http://download.cloud.com/templates/
4.2/systemvmtemplate-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-
4d43-11e3-8eab-
c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032
a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM
Template
(XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.Primary
DataStoreTO":{"uuid":"fefdf148-d326-3fa0-9aca-
3f8956fbd8f7","id":2,"poolType":"NetworkFilesystem","host":"172.16.51.47",
"path":"/export/primary2","port":2049}},"name":"routing-
1","hypervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}
}]
}
2013-11-29 08:38:10,187 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371787: Executing: { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.
apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1
/1/","origUrl":"http://download.cloud.com/templates/4.2/systemvmtempla
te-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-4d43-11e3-8eab-
c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032
a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM
Template
(XenServer)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nf
s://172.16.51.47:/export/secondary2","_role":"Image"}},"name":"routing-
1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storag
e.to.TemplateObjectTO":{"origUrl":"http://download.cloud.com/templates/
4.2/systemvmtemplate-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-
4d43-11e3-8eab-
c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032
a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM
Template
(XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.Primary
DataStoreTO":{"uuid":"fefdf148-d326-3fa0-9aca-
3f8956fbd8f7","id":2,"poolType":"NetworkFilesystem","host":"172.16.51.47",
"path":"/export/primary2","port":2049}},"name":"routing-
1","hypervisorType":"XenServer"}},"executeInSequence":true,"wait":10800}
}]
}
2013-11-29 08:38:10,188 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-1:null) Seq 1-1431371787: Executing request
2013-11-29 08:38:10,190 DEBUG [storage.volume.VolumeServiceImpl]
(secstorage-1:null) Acquire lock on VMTemplateStoragePool 2280 with
timeout 3600 seconds
2013-11-29 08:38:12,360 WARN [xen.resource.XenServerStorageProcessor]
(DirectAgent-1:null) destoryVDIbyNameLabel failed due to there are 0 VDIs
with name cloud-0212d4f0-d5ca-4dc5-9071-25179ec8f8f8
2013-11-29 08:38:12,362 WARN [xen.resource.XenServerStorageProcessor]
(DirectAgent-1:null) can not create vdi in sr bd7cb192-5956-307f-c993-
f4ce268c39da
2013-11-29 08:38:12,365 WARN [xen.resource.XenServerStorageProcessor]
(DirectAgent-1:null) Catch Exception
com.cloud.utils.exception.CloudRuntimeException for template + due to
com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr
bd7cb192-5956-307f-c993-f4ce268c39da
com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr
bd7cb192-5956-307f-c993-f4ce268c39da
at
com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.copy_vhd_f
rom_secondarystorage(XenServerStorageProcessor.java:792)
at
com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.copyTempla
teToPrimaryStorage(XenServerStorageProcessor.java:863)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execu
te(StorageSubsystemCommandHandlerBase.java:70)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handl
eStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(Citr
ixResourceBase.java:621)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(
XenServer56Resource.java:73)
at
com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest
(XenServer610Resource.java:104)
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.ac
cess$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
n(ScheduledThreadPoolExecutor.java:266)
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:701)
2013-11-29 08:38:12,367 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-1:null) Seq 1-1431371787: Response Received:
2013-11-29 08:38:12,368 DEBUG [agent.transport.Request]
(DirectAgent-1:null) Seq 1-1431371787: Processing: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":fals
e,"details":"Catch
Exception com.cloud.utils.exception.CloudRuntimeException for template
+ due to com.cloud.utils.exception.CloudRuntimeException: can not
create vdi in sr bd7cb192-5956-307f-c993-f4ce268c39da","wait":0}}] }
2013-11-29 08:38:12,369 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371787: Received: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2013-11-29 08:38:12,370 DEBUG [agent.manager.AgentAttache]
(DirectAgent-1:null) Seq 1-1431371787: No more commands found
2013-11-29 08:38:12,404 INFO [storage.volume.VolumeServiceImpl]
(consoleproxy-1:null) releasing lock for VMTemplateStoragePool 2280
2013-11-29 08:38:12,405 WARN [utils.db.Merovingian2]
(consoleproxy-1:null) Was unable to find lock for the key
template_spool_ref2280 and thread id 1998200215
2013-11-29 08:38:12,406 DEBUG [cloud.storage.VolumeManagerImpl]
(consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:Catch Exception
com.cloud.utils.exception.CloudRuntimeException for template + due to
com.cloud.utils.exception.CloudRuntimeException: can not create vdi in sr
bd7cb192-5956-307f-c993-f4ce268c39da
2013-11-29 08:38:12,406 INFO [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource
[StoragePool:2] is unreachable: Unable to create Vol[2|vm=2|ROOT]:Catch
Exception com.cloud.utils.exception.CloudRuntimeException for template
+ due to com.cloud.utils.exception.CloudRuntimeException: can not
create vdi in sr bd7cb192-5956-307f-c993-f4ce268c39da
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerI
mpl.java:2544)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:
2592)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
nagerImpl.java:889)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:578)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:571)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProx
yManagerImpl.java:556)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsolePr
oxyManagerImpl.java:928)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsolePr
oxyManagerImpl.java:1672)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsolePr
oxyManagerImpl.java:157)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java
:111)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.ja
va:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.j
ava: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:35
1)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
cess$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
n(ScheduledThreadPoolExecutor.java:267)
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:701)
2013-11-29 08:38:12,420 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-
2-VM] in Starting state
2013-11-29 08:38:12,426 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371788: Sending { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequenc
e":true,"vmName":"v-2-VM","wait":0}}]
}
2013-11-29 08:38:12,426 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371788: Executing: { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequenc
e":true,"vmName":"v-2-VM","wait":0}}]
}
2013-11-29 08:38:12,427 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-1431371788: Executing request
2013-11-29 08:38:12,523 INFO [xen.resource.CitrixResourceBase]
(DirectAgent-6:null) VM does not exist on
XenServer8f6e5992-458e-4fe6-9559-439b81ca65b9
2013-11-29 08:38:12,524 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-6:null) Seq 1-1431371788: Response Received:
2013-11-29 08:38:12,525 DEBUG [agent.transport.Request]
(DirectAgent-6:null) Seq 1-1431371788: Processing: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"V
M
does not exist","wait":0}}] }
2013-11-29 08:38:12,525 DEBUG [agent.manager.AgentAttache]
(DirectAgent-6:null) Seq 1-1431371788: No more commands found
2013-11-29 08:38:12,526 DEBUG [agent.transport.Request]
(consoleproxy-1:null) Seq 1-1431371788: Received: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-11-29 08:38:12,546 DEBUG [cloud.network.NetworkModelImpl]
(consoleproxy-1:null) Service SecurityGroup is not supported in the network
id=204
2013-11-29 08:38:12,567 DEBUG [cloud.network.NetworkManagerImpl]
(consoleproxy-1:null) Asking VirtualRouter to release Nic[5-2-9cd70f9a-9622-
49be-94c2-051974dd5b48-172.16.51.221]
2013-11-29 08:38:12,576 DEBUG [network.guru.ControlNetworkGuru]
(consoleproxy-1:null) Released nic: NicProfile[6-2-null-null-null
2013-11-29 08:38:12,603 DEBUG [dc.dao.DataCenterIpAddressDaoImpl]
(consoleproxy-1:null) Releasing ip address for reservationId=9cd70f9a-9622-
49be-94c2-051974dd5b48, instance=7
2013-11-29 08:38:12,605 DEBUG [network.guru.PodBasedNetworkGuru]
(consoleproxy-1:null) Released nic: NicProfile[7-2-null-null-null
2013-11-29 08:38:12,618 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Successfully released network resources for the vm
VM[ConsoleProxy|v-2-VM]
2013-11-29 08:38:12,619 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Successfully cleanued up resources for the vm
VM[ConsoleProxy|v-2-VM] in Starting state
2013-11-29 08:38:12,625 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null)
Deploy avoids pods: null, clusters: null, hosts: [1]
2013-11-29 08:38:12,628 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_9e815cea@58b375
61
2013-11-29 08:38:12,628 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null)
Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null,
requested cpu: 500, requested ram: 1073741824
2013-11-29 08:38:12,628 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is
ROOT volume READY (pool already allocated)?: No
2013-11-29 08:38:12,628 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Searching resources only under specified Pod: 1
2013-11-29 08:38:12,629 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this
Pod: 1
2013-11-29 08:38:12,652 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null)
Checking resources in Cluster: 1 under Pod: 1
2013-11-29 08:38:12,652 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1
pod:1 cluster:1
2013-11-29 08:38:12,662 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-1-Routing]]
2013-11-29 08:38:12,668 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Found 1 hosts for allocation after
prioritization: [Host[-1-Routing]]
2013-11-29 08:38:12,668 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz,
Ram=1024
2013-11-29 08:38:12,668 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Host name: iisys-xen-02,
hostId: 1 is in avoid set, skipping this and trying other available hosts
2013-11-29 08:38:12,668 DEBUG [allocator.impl.FirstFitAllocator]
(consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 0 suitable
hosts
2013-11-29 08:38:12,669 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No
suitable hosts found
2013-11-29 08:38:12,669 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) No
suitable hosts found under this Cluster: 1
2013-11-29 08:38:12,674 DEBUG
[cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null)
Could not find suitable Deployment Destination for this VM under any
clusters, returning.
2013-11-29 08:38:12,674 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Searching resources only under specified Pod: 1
2013-11-29 08:38:12,674 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this
Pod: 1
2013-11-29 08:38:12,678 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) Removing from the clusterId list these clusters from
avoid set: [1]
2013-11-29 08:38:12,678 DEBUG [cloud.deploy.FirstFitPlanner]
(consoleproxy-1:null) No clusters found after removing disabled clusters and
clusters in avoid list, returning.
2013-11-29 08:38:12,702 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 1
2013-11-29 08:38:12,723 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Hosts's actual total CPU: 48000 and CPU after applying
overprovisioning: 48000
2013-11-29 08:38:12,723 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Hosts's actual total RAM: 198565129728 and RAM after
applying overprovisioning: 198565134336
2013-11-29 08:38:12,724 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release cpu from host: 1, old used: 1000,reserved:
0, actual total: 48000, total with overprovisioning: 48000; new used:
500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-11-29 08:38:12,724 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release mem from host: 1, old used:
1342177280,reserved: 0, total: 198565134336; new used:
268435456,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-11-29 08:38:12,739 WARN
[cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null)
Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create
a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
nagerImpl.java:842)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:578)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:571)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProx
yManagerImpl.java:556)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsolePr
oxyManagerImpl.java:928)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsolePr
oxyManagerImpl.java:1672)
at
com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsolePr
oxyManagerImpl.java:157)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java
:111)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.ja
va:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.j
ava: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:35
1)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
cess$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
n(ScheduledThreadPoolExecutor.java:267)
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:701)
2013-11-29 08:38:15,198 INFO [storage.volume.VolumeServiceImpl]
(secstorage-1:null) Unable to acquire lock on VMTemplateStoragePool 2280
2013-11-29 08:38:15,202 ERROR [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-1159-
VM] java.lang.NullPointerException
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImage
Async(VolumeServiceImpl.java:422)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFro
mTemplateAsync(VolumeServiceImpl.java:569)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerI
mpl.java:2536)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:
2592)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
nagerImpl.java:889)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:578)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:571)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorag
eVm(SecondaryStorageManagerImpl.java:267)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(
SecondaryStorageManagerImpl.java:696)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(S
econdaryStorageManagerImpl.java:1300)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Pre
miumSecondaryStorageManagerImpl.java:123)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Pre
miumSecondaryStorageManagerImpl.java:50)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java
:104)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.ja
va:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.j
ava: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:35
1)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
cess$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
n(ScheduledThreadPoolExecutor.java:267)
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:701)
2013-11-29 08:38:15,217 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Cleaning up resources for the vm
VM[SecondaryStorageVm|s-1159-VM] in Starting state
2013-11-29 08:38:15,223 DEBUG [agent.transport.Request]
(secstorage-1:null) Seq 1-1431371789: Sending { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequenc
e":true,"vmName":"s-1159-VM","wait":0}}]
}
2013-11-29 08:38:15,223 DEBUG [agent.transport.Request]
(secstorage-1:null) Seq 1-1431371789: Executing: { Cmd , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequenc
e":true,"vmName":"s-1159-VM","wait":0}}]
}
2013-11-29 08:38:15,224 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-7:null) Seq 1-1431371789: Executing request
2013-11-29 08:38:15,306 INFO [xen.resource.CitrixResourceBase]
(DirectAgent-7:null) VM does not exist on
XenServer8f6e5992-458e-4fe6-9559-439b81ca65b9
2013-11-29 08:38:15,307 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-7:null) Seq 1-1431371789: Response Received:
2013-11-29 08:38:15,308 DEBUG [agent.transport.Request]
(DirectAgent-7:null) Seq 1-1431371789: Processing: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"V
M
does not exist","wait":0}}] }
2013-11-29 08:38:15,308 DEBUG [agent.manager.AgentAttache]
(DirectAgent-7:null) Seq 1-1431371789: No more commands found
2013-11-29 08:38:15,308 DEBUG [agent.transport.Request]
(secstorage-1:null) Seq 1-1431371789: Received: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-11-29 08:38:15,329 DEBUG [cloud.network.NetworkModelImpl]
(secstorage-1:null) Service SecurityGroup is not supported in the network
id=204
2013-11-29 08:38:15,352 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Asking VirtualRouter to release Nic[4632-1159-00610b50-
8d60-47fa-a951-a5f94ab71d1d-172.16.51.220]
2013-11-29 08:38:15,360 DEBUG [network.guru.ControlNetworkGuru]
(secstorage-1:null) Released nic: NicProfile[4633-1159-null-null-null
2013-11-29 08:38:15,388 DEBUG [dc.dao.DataCenterIpAddressDaoImpl]
(secstorage-1:null) Releasing ip address for reservationId=00610b50-8d60-
47fa-a951-a5f94ab71d1d, instance=4634
2013-11-29 08:38:15,390 DEBUG [network.guru.PodBasedNetworkGuru]
(secstorage-1:null) Released nic: NicProfile[4634-1159-null-null-null
2013-11-29 08:38:15,419 DEBUG [network.guru.StorageNetworkGuru]
(secstorage-1:null) Release an storage ip 172.16.51.243
2013-11-29 08:38:15,432 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Successfully released network resources for the vm
VM[SecondaryStorageVm|s-1159-VM]
2013-11-29 08:38:15,432 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Successfully cleanued up resources for the vm
VM[SecondaryStorageVm|s-1159-VM] in Starting state
2013-11-29 08:38:15,461 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 1
2013-11-29 08:38:15,483 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) Hosts's actual total CPU: 48000 and CPU after applying
overprovisioning: 48000
2013-11-29 08:38:15,484 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) Hosts's actual total RAM: 198565129728 and RAM after
applying overprovisioning: 198565134336
2013-11-29 08:38:15,484 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual
total: 48000, total with overprovisioning: 48000; new used:
0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-11-29 08:38:15,484 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) release mem from host: 1, old used:
268435456,reserved: 0, total: 198565134336; new used: 0,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-11-29 08:38:15,500 WARN
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null)
Exception while trying to start secondary storage vm
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to null
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
nagerImpl.java:988)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:578)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerIm
pl.java:571)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorag
eVm(SecondaryStorageManagerImpl.java:267)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(
SecondaryStorageManagerImpl.java:696)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(S
econdaryStorageManagerImpl.java:1300)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Pre
miumSecondaryStorageManagerImpl.java:123)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(Pre
miumSecondaryStorageManagerImpl.java:50)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java
:104)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.ja
va:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.j
ava: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:35
1)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
cess$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
n(ScheduledThreadPoolExecutor.java:267)
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:701)
Caused by: java.lang.NullPointerException
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImage
Async(VolumeServiceImpl.java:422)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFro
mTemplateAsync(VolumeServiceImpl.java:569)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerI
mpl.java:2536)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:
2592)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineMa
nagerImpl.java:889)
... 20 more
2013-11-29 08:38:15,504 INFO
[storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null)
Unable to start secondary storage vm for standby capacity, secStorageVm vm
Id : 1159, will recycle it and start a new one
2013-11-29 08:38:15,504 INFO
[cloud.secstorage.PremiumSecondaryStorageManagerImpl]
(secstorage-1:null) Primary secondary storage is not even started, wait until
next turn
2013-11-29 08:38:17,380 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-14:null) Ping from 1
2013-11-29 08:38:18,451 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-15:null) Seq 1-1431371781: Executing request
2013-11-29 08:38:18,701 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-15:null) Seq 1-1431371781: Response Received:
2013-11-29 08:38:18,703 DEBUG [agent.transport.Request]
(DirectAgent-15:null) Seq 1-1431371781: Processing: { Ans: , MgmtId:
217970788423578, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},
"_isExecuted":false,"result":true,"wait":0}}]
}
Many thanks in advance for your help!
Best regards
