Hello, After the update to CS 4.2 The system vm's won't boot, they don't go to error or anything, they just stay in starting state... I've update the system vm templates with the following link: http://download.cloud.com/templates/4.2/systemvmtemplate-2013-06-12-master-kvm.qcow2.bz2
Log file (management-server): 2013-10-07 09:18:05,451 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-10-07 09:18:06,079 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-506658917: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:18:06,713 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-164233323: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:18:07,209 DEBUG [agent.transport.Request] (AgentManager-Handler-4:null) Seq 2-164233312: Processing: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: name in virStorageVolLookupByName must not be NULL\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getPhysicalDisk(KVMStoragePoolManager.java:166)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:3668)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3537)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1252)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] } 2013-10-07 09:18:07,209 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-4:null) Seq 2-164233322: Sending now. is current sequence. 2013-10-07 09:18:07,211 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 2-164233312: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 110, { Answer, Answer } } 2013-10-07 09:18:07,214 ERROR [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-32-VM] com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:921) 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:679) 2013-10-07 09:18:07,216 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-32-VM] in Starting state 2013-10-07 09:18:07,218 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 2-164233324: Waiting for Seq 164233322 Scheduling: { Cmd , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-32-VM","wait":0}}] } 2013-10-07 09:18:16,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:16,914 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:17,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:17,021 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:35,841 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running... 2013-10-07 09:18:35,845 INFO [storage.endpoint.DefaultEndPointSelector] (StatsCollector-2:null) No running ssvm is found, so command will be sent to LocalHostEndPoint 2013-10-07 09:18:36,314 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-506658918: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-10-07 09:18:46,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:46,914 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:47,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:47,021 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:52,648 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 1 2013-10-07 09:18:52,676 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 2 2013-10-07 09:19:02,334 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running... 2013-10-07 09:19:06,713 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running... 2013-10-07 09:19:07,378 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-506658919: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:19:08,039 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 2-164233325: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:19:16,912 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:16,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:17,019 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:17,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:22,147 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect 2013-10-07 09:19:22,149 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect 2013-10-07 09:19:22,149 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server 2013-10-07 09:19:36,314 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running... 2013-10-07 09:19:36,319 INFO [storage.endpoint.DefaultEndPointSelector] (StatsCollector-1:null) No running ssvm is found, so command will be sent to LocalHostEndPoint 2013-10-07 09:19:36,792 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-506658920: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } [root@energia ~]# tail -150 /var/log/cloudstack/management/management-server.log 2013-10-07 09:18:01,776 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Trying to deploy VM, vm has dcId: 1 and podId: 1 2013-10-07 09:18:01,776 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null 2013-10-07 09:18:01,779 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Root volume is ready, need to place VM in volume's cluster 2013-10-07 09:18:01,779 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Vol[36|vm=31|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: null , and clusterId: null 2013-10-07 09:18:01,780 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Deploy avoids pods: null, clusters: null, hosts: null 2013-10-07 09:18:01,781 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_78958a70@51f090da 2013-10-07 09:18:01,781 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 1073741824 2013-10-07 09:18:01,781 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Is ROOT volume READY (pool already allocated)?: Yes 2013-10-07 09:18:01,781 DEBUG [cloud.deploy.FirstFitPlanner] (consoleproxy-1:null) Searching all possible resources under this Zone: 1 2013-10-07 09:18:01,783 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 Zone: 1 2013-10-07 09:18:01,792 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking resources in Cluster: 1 under Pod: 1 2013-10-07 09:18:01,792 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 2013-10-07 09:18:01,797 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-2-Routing], Host[-1-Routing]] 2013-10-07 09:18:01,800 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-2-Routing], Host[-1-Routing]] 2013-10-07 09:18:01,800 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=1024 2013-10-07 09:18:01,807 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 63960 and CPU after applying overprovisioning: 63960 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 63460 , Requested CPU: 500 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 33385836544 , Requested RAM: 1073741824 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 500, reserved: 0, actual total: 63960, total with overprovisioning: 63960; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2013-10-07 09:18:01,810 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 268435456, reserved: 0, total: 33654272000; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true 2013-10-07 09:18:01,810 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 2 2013-10-07 09:18:01,816 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Hosts's actual total CPU: 63984 and CPU after applying overprovisioning: 63984 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free CPU: 63984 , Requested CPU: 500 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Free RAM: 135317831680 , Requested RAM: 1073741824 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) Host has enough CPU and RAM available 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 0, reserved: 0, actual total: 63984, total with overprovisioning: 63984; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true 2013-10-07 09:18:01,818 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 0, reserved: 0, total: 135317831680; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true 2013-10-07 09:18:01,818 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Found a suitable host, adding to list: 1 2013-10-07 09:18:01,818 DEBUG [allocator.impl.FirstFitAllocator] (consoleproxy-1:FirstFitRoutingAllocator) Host Allocator returning 2 suitable hosts 2013-10-07 09:18:01,820 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking suitable pools for volume (Id, Type): (36,ROOT) 2013-10-07 09:18:01,820 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Volume has pool already allocated, checking if pool can be reused, poolId: 1 2013-10-07 09:18:01,821 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Pool of the volume does not fit the specified plan, need to reallocate a pool for this volume 2013-10-07 09:18:01,822 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) We need to allocate new storagepool for this volume 2013-10-07 09:18:01,822 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Calling StoragePoolAllocators to find suitable pools 2013-10-07 09:18:01,824 DEBUG [storage.allocator.LocalStoragePoolAllocator] (consoleproxy-1:null) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2013-10-07 09:18:01,824 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) ClusterScopeStoragePoolAllocator looking for storage pool 2013-10-07 09:18:01,824 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) Looking for pools in dc: 1 pod:1 cluster:1 2013-10-07 09:18:01,826 DEBUG [storage.allocator.ClusterScopeStoragePoolAllocator] (consoleproxy-1:null) No storage pools available for shared volume allocation, returning 2013-10-07 09:18:01,826 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator] (consoleproxy-1:null) ZoneWideStoragePoolAllocator to find storage pool 2013-10-07 09:18:01,835 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking pool 1 for storage, totalSize: 177159012352, usedBytes: 19323158528, usedPct: 0.10907239926132867, disable threshold: 0.85 2013-10-07 09:18:01,846 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking pool: 1 for volume allocation [Vol[36|vm=31|ROOT]], maxSize : 177159012352, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85 2013-10-07 09:18:01,846 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2013-10-07 09:18:01,846 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Checking if host: 2 can access any suitable storage pool for volume: ROOT 2013-10-07 09:18:01,847 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Host: 2 can access pool: 1 2013-10-07 09:18:01,848 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Found a potential host id: 2 name: buran.brusselsairport.aero and associated storage pools for this VM 2013-10-07 09:18:01,850 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (consoleproxy-1:null) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(36|ROOT-->Pool(1))] 2013-10-07 09:18:01,850 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Deployment found - P0=VM[ConsoleProxy|v-31-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(36|ROOT-->Pool(1))] 2013-10-07 09:18:01,858 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 2 host id before state transition: null 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 63960 and CPU after applying overprovisioning: 63960 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) We are allocating VM, increasing the used capacity of this host:2 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used CPU: 500 , Free CPU:63460 ,Requested CPU: 500 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Current Used RAM: 268435456 , Free RAM:33385836544 ,Requested RAM: 1073741824 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) CPU STATS after allocation: for host: 2, old used: 500, old reserved: 0, actual total: 63960, total with overprovisioning: 63960; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false 2013-10-07 09:18:01,868 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) RAM STATS after allocation: for host: 2, old used: 268435456, old reserved: 0, total: 33654272000; new used: 1342177280, reserved: 0; requested mem: 1073741824,alloc_from_last:false 2013-10-07 09:18:01,870 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) VM is being created in podId: 1 2013-10-07 09:18:01,875 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=200 is already implemented 2013-10-07 09:18:01,887 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=202 is already implemented 2013-10-07 09:18:01,900 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Network id=201 is already implemented 2013-10-07 09:18:01,912 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Allocated a nic NicProfile[122-31-f5afa53d-e600-4b0d-a556-3908c9b55197-10.110.56.136-null for VM[ConsoleProxy|v-31-VM] 2013-10-07 09:18:01,915 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Checking if we need to prepare 1 volumes for VM[ConsoleProxy|v-31-VM] 2013-10-07 09:18:01,915 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Volume Vol[36|vm=31|ROOT] will be recreated on storage pool Pool[1|CLVM] assigned by deploymentPlanner 2013-10-07 09:18:01,919 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Created new volume Vol[38|vm=31|ROOT] for old volume Vol[36|vm=31|ROOT] 2013-10-07 09:18:01,922 DEBUG [storage.image.TemplateDataFactoryImpl] (consoleproxy-1:null) template 3 is already in store:2, type:Image 2013-10-07 09:18:01,925 DEBUG [storage.image.TemplateDataFactoryImpl] (consoleproxy-1:null) template 3 is already in store:1, type:Primary 2013-10-07 09:18:01,943 DEBUG [storage.image.TemplateDataFactoryImpl] (consoleproxy-1:null) template 3 is already in store:2, type:Image 2013-10-07 09:18:01,949 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-506658916: Sending { Cmd , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/1/3/","origUrl":" http://localhost/cloudimages/systemvmtemplate-2013-06-12-master-kvm.qcow2.bz2","uuid":"11448a17-2f13-11e3-be07-005056b9154e","id":3,"format":"QCOW2","accountId":1,"checksum":"6cea42b2633841648040becb588bd8f0","hvm":false,"displayText":"SystemVM Template (KVM)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs:// 10.206.2.45/energiaprimary","_role":"Image"}},"name":"routing-3","hypervisorType":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0e4306d2-55b8-48cb-a1ef-6eafad737e84","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"d9883bc4-179d-4b97-b78e-b6040ec5d698","id":1,"poolType":"CLVM","host":"localhost","path":"/cloud_vg","port":0}},"name":"ROOT-31","size":0,"volumeId":38,"vmName":"v-31-VM","accountId":1,"format":"QCOW2","id":38,"hypervisorType":"KVM"}},"executeInSequence":true,"wait":10800}}] } 2013-10-07 09:18:02,329 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running... 2013-10-07 09:18:05,023 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 1-506658916: Processing: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"Failed to get volumes from pool: 6ae72d3a-43f7-3874-8311-98344d5e48d3","wait":0}}] } 2013-10-07 09:18:05,023 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-1:null) Seq 1-506658916: No more commands found 2013-10-07 09:18:05,024 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-506658916: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer } } 2013-10-07 09:18:05,035 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Boot Args for VM[ConsoleProxy|v-31-VM]: template=domP type=consoleproxy host=10.110.56.100 port=8250 name=v-31-VM premium=true zone=1 pod=1 guid=Proxy.31 proxy_vm=31 disable_rp_filter=true eth2ip=10.206.10.101 eth2mask=255.255.255.0 gateway=10.206.10.1 eth0ip=169.254.1.166 eth0mask=255.255.0.0 eth1ip=10.110.56.136 eth1mask=255.255.255.0 mgmtcidr=10.110.56.0/24 localgw=10.110.56.1 internaldns1=10.110.3.123 internaldns2=10.110.3.125 dns1=10.110.3.123 dns2=10.110.3.125 2013-10-07 09:18:05,045 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 2-164233322: Waiting for Seq 164233312 Scheduling: { Cmd , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":31,"name":"v-31-VM","type":"ConsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy host=10.110.56.100 port=8250 name=v-31-VM premium=true zone=1 pod=1 guid=Proxy.31 proxy_vm=31 disable_rp_filter=true eth2ip=10.206.10.101 eth2mask=255.255.255.0 gateway=10.206.10.1 eth0ip=169.254.1.166 eth0mask=255.255.0.0 eth1ip=10.110.56.136 eth1mask=255.255.255.0 mgmtcidr= 10.110.56.0/24 localgw=10.110.56.1 internaldns1=10.110.3.123 internaldns2=10.110.3.125 dns1=10.110.3.123 dns2=10.110.3.125","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"eb79c03afe52482b","params":{},"uuid":"7752a679-b674-4fb3-85c2-64e867daf238","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0e4306d2-55b8-48cb-a1ef-6eafad737e84","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"d9883bc4-179d-4b97-b78e-b6040ec5d698","id":1,"poolType":"CLVM","host":"localhost","path":"/cloud_vg","port":0}},"name":"ROOT-31","size":0,"volumeId":38,"vmName":"v-31-VM","accountId":1,"format":"QCOW2","id":38,"hypervisorType":"KVM"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"65a62b71-437a-45cd-9c61-ada67c08e767","ip":"10.206.10.101","netmask":"255.255.255.0","gateway":"10.206.10.1","mac":"06:d6:cc:00:00:35","dns1":"10.110.3.123","dns2":"10.110.3.125","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://110","isolationUri":"vlan://110","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"60431a1f-6108-4c91-b24a-82888d7dc830","ip":"169.254.1.166","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:01:a6","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"9a37fb52-62ba-4e66-8cb8-ac9f089a84ea","ip":"10.110.56.136","netmask":"255.255.255.0","gateway":"10.110.56.1","mac":"06:cc:ee:00:00:24","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"manbr0"}]},"hostIp":"10.110.56.21","executeInSequence":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.1.166","port":3922,"interval":6,"retries":100,"name":"v-31-VM","wait":0}}] } 2013-10-07 09:18:05,451 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-10-07 09:18:06,079 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-506658917: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:18:06,713 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-164233323: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:18:07,209 DEBUG [agent.transport.Request] (AgentManager-Handler-4:null) Seq 2-164233312: Processing: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: name in virStorageVolLookupByName must not be NULL\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getPhysicalDisk(KVMStoragePoolManager.java:166)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.createVbd(LibvirtComputingResource.java:3668)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3537)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1252)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] } 2013-10-07 09:18:07,209 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-4:null) Seq 2-164233322: Sending now. is current sequence. 2013-10-07 09:18:07,211 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 2-164233312: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 110, { Answer, Answer } } 2013-10-07 09:18:07,214 ERROR [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Failed to start instance VM[SecondaryStorageVm|s-32-VM] com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:921) 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:679) 2013-10-07 09:18:07,216 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-32-VM] in Starting state 2013-10-07 09:18:07,218 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 2-164233324: Waiting for Seq 164233322 Scheduling: { Cmd , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"s-32-VM","wait":0}}] } 2013-10-07 09:18:16,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:16,914 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:17,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:17,021 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:35,841 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running... 2013-10-07 09:18:35,845 INFO [storage.endpoint.DefaultEndPointSelector] (StatsCollector-2:null) No running ssvm is found, so command will be sent to LocalHostEndPoint 2013-10-07 09:18:36,314 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-506658918: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-10-07 09:18:46,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:46,914 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:47,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:18:47,021 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:18:52,648 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 1 2013-10-07 09:18:52,676 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 2 2013-10-07 09:19:02,334 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) VmStatsCollector is running... 2013-10-07 09:19:06,713 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running... 2013-10-07 09:19:07,378 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 1-506658919: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:19:08,039 DEBUG [agent.transport.Request] (StatsCollector-2:null) Seq 2-164233325: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:19:16,912 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:16,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:17,019 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:17,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:22,147 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Resetting hosts suitable for reconnect 2013-10-07 09:19:22,149 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed resetting hosts suitable for reconnect 2013-10-07 09:19:22,149 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters already owned by this management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters already owned by this management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Acquiring hosts for clusters not owned by any management server 2013-10-07 09:19:22,150 DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:null) Completed acquiring hosts for clusters not owned by any management server 2013-10-07 09:19:36,314 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) StorageCollector is running... 2013-10-07 09:19:36,319 INFO [storage.endpoint.DefaultEndPointSelector] (StatsCollector-1:null) No running ssvm is found, so command will be sent to LocalHostEndPoint 2013-10-07 09:19:36,792 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-506658920: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-10-07 09:19:46,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:46,914 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:47,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:19:47,021 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:19:52,636 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 2 2013-10-07 09:19:52,647 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1 2013-10-07 09:20:02,340 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running... 2013-10-07 09:20:08,039 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-10-07 09:20:08,692 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 1-506658921: Received: { Ans: , MgmtId: 345052353870, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:20:09,333 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 2-164233326: Received: { Ans: , MgmtId: 345052353870, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-10-07 09:20:16,912 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:20:16,913 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. 2013-10-07 09:20:17,019 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. 2013-10-07 09:20:17,020 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. Hope somebody can help me Kind regards, Koen