SSVM won't start

Thu, 28 Nov 2013 23:49:04 -0800 

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/systemvmtemplate-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-4d43-11e3-8eab-c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://172.16.51.47:/export/secondary2","_role":"Image"}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.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":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"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/systemvmtemplate-2013-07-12-master-xen.vhd.bz2","uuid":"82cd934b-4d43-11e3-8eab-c63e476a579a","id":1,"format":"VHD","accountId":1,"checksum":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://172.16.51.47:/export/secondary2","_role":"Image"}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.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":"fb1b6e032a160d86f2c28feb5add6d83","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"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_from_secondarystorage(XenServerStorageProcessor.java:792) at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.copyTemplateToPrimaryStorage(XenServerStorageProcessor.java:863) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:70) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.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.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: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":false,"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(VolumeManagerImpl.java:2544) at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2592) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:928) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1672) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157) 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: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,"executeInSequence":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,"executeInSequence":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":"VM 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@58b37561 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(VirtualMachineManagerImpl.java:842) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:928) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1672) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157) 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: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.createBaseImageAsync(VolumeServiceImpl.java:422) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:569) at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2536) at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2592) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:889) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104) 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: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,"executeInSequence":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,"executeInSequence":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":"VM 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(VirtualMachineManagerImpl.java:988) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:571) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:267) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:696) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1300) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104) 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:701)
Caused by: java.lang.NullPointerException
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:422) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:569) at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2536) at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2592) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.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

Reply via email to