Hi Mahfuj, >From the logs it looks like issue while mounting the primary storage mount >point on the host. Is the storage pool is reachable to the host?. Can you manually mount it and verify whether the primary storage mount point can be mounted on the host or not and its reachable.
Thanks Rajesh Battala -----Original Message----- From: Mahfuj Jia [mailto:[email protected]] Sent: Wednesday, January 16, 2013 4:13 PM To: [email protected] Subject: Re: Host installed ok. Only problem appears to be with the System VMs coming up Hi I am waiting for your reply This is our Management server log 2013-01-15 05:39:55,615 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[1181-296-null-null-null 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking JuniperSRX to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Netscaler to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking F5BigIP to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalDhcpServer to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking BareMetal to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking CiscoNexus1000vVSM to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,619 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[1181-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,627 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (secstorage-1:null) Releasing ip address for reservationId=a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf, instance=1182 2013-01-15 05:39:55,643 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-01-15 05:39:55,650 DEBUG [network.guru.PodBasedNetworkGuru] (secstorage-1:null) Released nic: NicProfile[1182-296-null-null-null 2013-01-15 05:39:55,655 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking JuniperSRX to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Netscaler to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking F5BigIP to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VirtualRouter to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking Ovs to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking ExternalDhcpServer to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking BareMetal to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking SecurityGroupProvider to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking CiscoNexus1000vVSM to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking VpcVirtualRouter to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.network.NetworkManagerImpl] (secstorage-1:null) Asking NiciraNvp to release Nic[1182-296-a47e227a-1c5c-4a5e-8e26-3dd9a81e81cf-null] 2013-01-15 05:39:55,656 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully released network resources for the vm VM[SecondaryStorageVm|s-296-VM] 2013-01-15 05:39:55,656 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-296-VM] in Starting state 2013-01-15 05:39:55,671 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-01-15 05:39:55,674 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) Hosts's actual total CPU: 8000 and CPU after applying overprovisioning: 8000 2013-01-15 05:39:55,674 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 8000, total with overprovisioning: 8000; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse 2013-01-15 05:39:55,674 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 1, old used: 1342177280,reserved: 0, total: 16726679552; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse 2013-01-15 05:39:55,678 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 com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:257) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:684) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1310) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:119) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:106) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83) at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73) 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:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) Caused by: java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:663) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3442) at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3351) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:754) ... 20 more 2013-01-15 05:39:55,679 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 296, will recycle it and start a new one 2013-01-15 05:39:55,679 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn 2013-01-15 05:40:00,255 DEBUG [cloud.template.TemplateManagerImpl] (consoleproxy-1:null) Downloading 3 via 1 2013-01-15 05:40:00,260 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-2027227198: Sending { Cmd , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/var/lib/libvirt/images/","poolUuid":"9652649a-6c25-403a-88b8-7e609f706e27","poolId":201,"secondaryStorageUrl":"nfs://192.168.71.50/export/secondary","primaryStorageUrl":"nfs://192.168.71.41/var/lib/libvirt/images/","url":"nfs://192.168.71.50/export/secondary/template/tmpl/1/3/","format":"QCOW2","accountId":1,"name":"routing-3","wait":10800}}] } 2013-01-15 05:40:00,340 DEBUG [agent.transport.Request] (AgentManager-Handler-14:null) Seq 1-2027227198: Processing: { Ans: , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:462)\n\tat com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getStoragePoolByURI(LibvirtStorageAdaptor.java:745)\n\tat com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:52)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2017)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1009)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}}] } 2013-01-15 05:40:00,340 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-14:null) Seq 1-2027227198: No more commands found 2013-01-15 05:40:00,340 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-2027227198: Received: { Ans: , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 110, { Answer } } 2013-01-15 05:40:00,340 DEBUG [agent.manager.AgentManagerImpl] (consoleproxy-1:null) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: java.lang.NullPointerException at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:462) at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getStoragePoolByURI(LibvirtStorageAdaptor.java:745) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:52) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2017) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1009) at com.cloud.agent.Agent.processRequest(Agent.java:518) at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831) at com.cloud.utils.nio.Task.run(Task.java:83) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-01-15 05:40:00,342 ERROR [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Failed to start instance VM[ConsoleProxy|v-83-VM] java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:663) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3442) at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3351) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:754) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83) at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73) 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:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-01-15 05:40:00,349 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Cleaning up resources for the vm VM[ConsoleProxy|v-83-VM] in Starting state 2013-01-15 05:40:00,351 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-2027227199: Sending { Cmd , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"v-83-VM","wait":0}}] } 2013-01-15 05:40:00,601 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 1-2027227199: Processing: { Ans: , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] } 2013-01-15 05:40:00,602 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 1-2027227199: No more commands found 2013-01-15 05:40:00,602 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-2027227199: Received: { Ans: , MgmtId: 52242164673, via: 1, Ver: v1, Flags: 110, { StopAnswer } } 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,638 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[328-83-37122d6d-0259-4b1a-8638-6b6148037bd9-192.168.71.71] 2013-01-15 05:40:00,650 DEBUG [network.guru.ControlNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[329-83-null-null-null 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,655 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[329-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,662 DEBUG [dc.dao.DataCenterIpAddressDaoImpl] (consoleproxy-1:null) Releasing ip address for reservationId=37122d6d-0259-4b1a-8638-6b6148037bd9, instance=330 2013-01-15 05:40:00,666 DEBUG [network.guru.PodBasedNetworkGuru] (consoleproxy-1:null) Released nic: NicProfile[330-83-null-null-null 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking JuniperSRX to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Netscaler to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking F5BigIP to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VirtualRouter to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking Ovs to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking ExternalDhcpServer to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking BareMetal to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking SecurityGroupProvider to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking CiscoNexus1000vVSM to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking VpcVirtualRouter to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.network.NetworkManagerImpl] (consoleproxy-1:null) Asking NiciraNvp to release Nic[330-83-37122d6d-0259-4b1a-8638-6b6148037bd9-null] 2013-01-15 05:40:00,670 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully released network resources for the vm VM[ConsoleProxy|v-83-VM] 2013-01-15 05:40:00,670 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully cleanued up resources for the vm VM[ConsoleProxy|v-83-VM] in Starting state 2013-01-15 05:40:00,678 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-01-15 05:40:00,681 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) Hosts's actual total CPU: 8000 and CPU after applying overprovisioning: 8000 2013-01-15 05:40:00,681 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 500,reserved: 0, actual total: 8000, total with overprovisioning: 8000; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse 2013-01-15 05:40:00,681 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1073741824,reserved: 0, total: 16726679552; new used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse 2013-01-15 05:40:00,685 WARN [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start instance due to com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:627) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:1164) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1981) at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:173) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:113) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83) at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73) 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:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) Caused by: java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer at com.cloud.template.TemplateManagerImpl.prepareTemplateForCreate(TemplateManagerImpl.java:663) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.storage.StorageManagerImpl.createVolume(StorageManagerImpl.java:3442) at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3351) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:754) ... 19 more --------------------------------------------- And this is KVM Agent log [root@kvm01 agent]# tail -f agent.log at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getStoragePoolByURI(LibvirtStorageAdaptor.java:745) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:52) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2017) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1009) at com.cloud.agent.Agent.processRequest(Agent.java:518) at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831) at com.cloud.utils.nio.Task.run(Task.java:83) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-01-16 01:51:18,634 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) org.libvirt.LibvirtException: internal error Child process (/bin/mount 192.168.71.50:/export/secondary/template/tmpl/1/3 /mnt/ba4c9106-f7f9-3d6e-a87f-97544149b33b) status unexpected: exit status 32 2013-01-16 01:51:18,640 WARN [cloud.agent.Agent] (agentRequest-Handler-1:null) Caught: java.lang.NullPointerException at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.createStoragePool(LibvirtStorageAdaptor.java:462) at com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.getStoragePoolByURI(LibvirtStorageAdaptor.java:745) at com.cloud.hypervisor.kvm.storage.KVMStoragePoolManager.getStoragePoolByURI(KVMStoragePoolManager.java:52) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2017) at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1009) at com.cloud.agent.Agent.processRequest(Agent.java:518) at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831) at com.cloud.utils.nio.Task.run(Task.java:83) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-01-16 01:51:18,956 ERROR [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) org.libvirt.LibvirtException: internal error Child process (/bin/mount 192.168.71.50:/export/secondary/template/tmpl/1/3 /mnt/ba4c9106-f7f9-3d6e-a87f-97544149b33b) status unexpected: exit status 32 2013-01-16 01:51:18,961 WARN [cloud.agent.Agent] (agentRequest-Handler-4:null) Caught: On 1/16/13, Mahfuj Jia <[email protected]> wrote: > Thanks for your replying > > I have send you Logs.zip file.Please sir give me suggestion. > > On Tue, Jan 15, 2013 at 10:07 PM, Rajesh Battala > <[email protected]>wrote: > >> Hi Mahfuj, >> Can you post the DEBUG log of MS and kvm agent. >> >> Thanks >> Rajesh Battala >> >> -----Original Message----- >> From: Mahfuj Jia [mailto:[email protected]] >> Sent: Tuesday, January 15, 2013 8:52 PM >> To: [email protected] >> Subject: Host installed ok. Only problem appears to be with the >> System VMs coming up >> >> Hi, I am using CloudStack4 official installation guide and >> successfully installed the following things >> >> >> 1. One Management Server. (Linux Centos x86_64) 2. One KVM host server. >> (Linux Centos x86_64) >> >> Cloudstack 4.0 installation process: >> >> At Management Server: >> >> 1. Install cloud-client. (Successfully) 2. Install Mysql Server. >> (Succesfully) 3. Cloud Database Created. (Successfully) 4. NFS Server >> installed. >> (Successfully). >> 5. NFS Share. (Successfully) >> >> >> At Client Machine: >> >> 1. Install cloud-agent. (Successfully) 2. NFS mount. (Successfully) >> >> The main problem is after successfully adding host from CloudStack >> user interface when System VM coming up following exceptions has >> thrown >> >> *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 Unable to get >> answer that is of class com.cloud.agent.api.StartAnswer >> >> 2013-01-15 03:05:55,238 ERROR [cloud.vm.VirtualMachineManagerImpl] >> (secstorage-1:null) Failed to start instance >> VM[SecondaryStorageVm|s-142-VM] >> java.lang.ClassCastException: com.cloud.agent.api.Answer cannot be >> cast to com.cloud.agent.api.storage.PrimaryStorageDownloadAnswer >> >> 2013-01-15 03:05:55,580 INFO >> [cloud.secstorage.PremiumSecondaryStorageManagerImpl] >> (secstorage-1:null)*Primary secondary storage is not even started, >> wait until next turn >> * >> >> >> How I will solve this problem.Please if you have any recommendation >> tell me. >> >
