Sebastian, In XenServer host, can you check your vhd-util location. The correct location for vhd-util is "/opt/xensource/bin", if it is not in this folder then you have to copy it from /usr/bin/vhd-util.
--Sanjay > -----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 >
