You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cloudstack.apache.org by Busy Dev <bu...@gmail.com> on 2012/10/08 03:28:44 UTC

Unable to start VM (using 4.0 task branch)

>From vmops.log, it looks like the "router" VM is not able to start?

*Here's the snippet from vmops.log.*

2012-10-07 20:57:20,643 INFO  [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-11:job-11) Unable to contact resource.
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due t*o Unable to start
VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying*
 at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
 at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2352)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1597)
 at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1697)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
 at
com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:205)
at
com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2056)
 at
com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2172)
at
com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2113)
 at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
 at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1842)
 at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at com.cloud.api.commands.StartVMCmd.execute(StartVMCmd.java:123)
 at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
 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.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: com.cloud.utils.exception.ExecutionException: Unable to start
VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:814)
 ... 27 more
2012-10-07 20:57:20,753 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-11:job-11) Cleaning up resources for the vm
VM[User|8b340b2c-732d-45dc-bc7d-805ce2c0718e] in Starti

*Here's libvirtd.log from the KVM host:*
2012-10-08 00:54:43.135+0000: 1782: warning : qemuDomainObjTaint:1297 :
Domain id=6 name='r-7-TEST' uuid=7863482b-93e4-3b93-81b1-03b53b98cddd is
tainted: high-privileges
2012-10-08 00:55:40.002+0000: 1777: error : qemuMonitorIO:574 : internal
error End of file from monitor
2012-10-08 00:56:07.364+0000: 1784: error :
virStoragePoolSourceFindDuplicate:1718 : operation failed: Storage source
conflict with pool: '2a3bb121-788a-44b1-9730-7c0f7c2fe193'

*Here's agent.log from the KVM host*
2012-10-06 00:29:12,444 WARN  [cloud.agent.Agent]
(agentRequest-Handler-2:null) Caught:
java.lang.NullPointerException
        at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2656)
        at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1001)
        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)

Re: Unable to start VM (using 4.0 task branch)

Posted by "Kelceydamage@bbits" <ke...@bbits.ca>.
What build was the finalizeStart error resolved in... I have a 323 build exhibiting this same behaviour.

Sent from my iPhone

On Oct 7, 2012, at 8:02 PM, Marcus Sorensen <sh...@gmail.com> wrote:

> What's the 4.0 'task' branch?  I was looking at your libvirtd log and
> it resembles a recently closed bug
> (https://reviews.apache.org/r/7304/), however that was with user vm
> isos and not the system VMs. I wanted to see if it included the commit
> described, but I'm not sure what commit level your 4.0 is at or which
> branch it is for sure.
> 
> Also, the timestamps are different on each log, so I'm not sure
> they're all relevant to the same event.
> 
> If you can replicate that libvirtd.log error whenever you try to start
> the router VM, look at the detailed pool info for the mentioned
> storage pool and just see if it's trying to create a primary storage
> pool, an NFS or other secondary pool, or what.
> 
> I suppose that error could occur if you're redeploying/re-joining a
> host into a cloudstack environment as well (without a fresh
> reinstall), as the storage pools will already exist in libvirt and
> fail to create.
> 
> On Sun, Oct 7, 2012 at 6:28 PM, Busy Dev <bu...@gmail.com> wrote:
>> From vmops.log, it looks like the "router" VM is not able to start?
>> 
>> *Here's the snippet from vmops.log.*
>> 
>> 2012-10-07 20:57:20,643 INFO  [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-11:job-11) Unable to contact resource.
>> com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
>> unreachable: Host 1: Unable to start instance due t*o Unable to start
>> VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying*
>> at
>> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
>> at
>> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
>> at
>> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2352)
>> at
>> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1597)
>> at
>> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1697)
>> at
>> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
>> at
>> com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:205)
>> at
>> com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2056)
>> at
>> com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2172)
>> at
>> com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2113)
>> at
>> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:752)
>> at
>> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
>> at
>> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
>> at
>> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1842)
>> at
>> com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
>> at com.cloud.api.commands.StartVMCmd.execute(StartVMCmd.java:123)
>> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
>> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
>> 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.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: com.cloud.utils.exception.ExecutionException: Unable to start
>> VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying
>> at
>> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:814)
>> ... 27 more
>> 2012-10-07 20:57:20,753 DEBUG [cloud.vm.VirtualMachineManagerImpl]
>> (Job-Executor-11:job-11) Cleaning up resources for the vm
>> VM[User|8b340b2c-732d-45dc-bc7d-805ce2c0718e] in Starti
>> 
>> *Here's libvirtd.log from the KVM host:*
>> 2012-10-08 00:54:43.135+0000: 1782: warning : qemuDomainObjTaint:1297 :
>> Domain id=6 name='r-7-TEST' uuid=7863482b-93e4-3b93-81b1-03b53b98cddd is
>> tainted: high-privileges
>> 2012-10-08 00:55:40.002+0000: 1777: error : qemuMonitorIO:574 : internal
>> error End of file from monitor
>> 2012-10-08 00:56:07.364+0000: 1784: error :
>> virStoragePoolSourceFindDuplicate:1718 : operation failed: Storage source
>> conflict with pool: '2a3bb121-788a-44b1-9730-7c0f7c2fe193'
>> 
>> *Here's agent.log from the KVM host*
>> 2012-10-06 00:29:12,444 WARN  [cloud.agent.Agent]
>> (agentRequest-Handler-2:null) Caught:
>> java.lang.NullPointerException
>>        at
>> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2656)
>>        at
>> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1001)
>>        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)

Re: Unable to start VM (using 4.0 task branch)

Posted by Marcus Sorensen <sh...@gmail.com>.
What's the 4.0 'task' branch?  I was looking at your libvirtd log and
it resembles a recently closed bug
(https://reviews.apache.org/r/7304/), however that was with user vm
isos and not the system VMs. I wanted to see if it included the commit
described, but I'm not sure what commit level your 4.0 is at or which
branch it is for sure.

Also, the timestamps are different on each log, so I'm not sure
they're all relevant to the same event.

If you can replicate that libvirtd.log error whenever you try to start
the router VM, look at the detailed pool info for the mentioned
storage pool and just see if it's trying to create a primary storage
pool, an NFS or other secondary pool, or what.

I suppose that error could occur if you're redeploying/re-joining a
host into a cloudstack environment as well (without a fresh
reinstall), as the storage pools will already exist in libvirt and
fail to create.

On Sun, Oct 7, 2012 at 6:28 PM, Busy Dev <bu...@gmail.com> wrote:
> From vmops.log, it looks like the "router" VM is not able to start?
>
> *Here's the snippet from vmops.log.*
>
> 2012-10-07 20:57:20,643 INFO  [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-11:job-11) Unable to contact resource.
> com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
> unreachable: Host 1: Unable to start instance due t*o Unable to start
> VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying*
>  at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
>  at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2352)
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1597)
>  at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1697)
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
>  at
> com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:205)
> at
> com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2056)
>  at
> com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2172)
> at
> com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2113)
>  at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:752)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
>  at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
> at
> com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1842)
>  at
> com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
> at com.cloud.api.commands.StartVMCmd.execute(StartVMCmd.java:123)
>  at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
> at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
>  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.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: com.cloud.utils.exception.ExecutionException: Unable to start
> VM[DomainRouter|r-7-TEST] due to error in finalizeStart, not retrying
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:814)
>  ... 27 more
> 2012-10-07 20:57:20,753 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-11:job-11) Cleaning up resources for the vm
> VM[User|8b340b2c-732d-45dc-bc7d-805ce2c0718e] in Starti
>
> *Here's libvirtd.log from the KVM host:*
> 2012-10-08 00:54:43.135+0000: 1782: warning : qemuDomainObjTaint:1297 :
> Domain id=6 name='r-7-TEST' uuid=7863482b-93e4-3b93-81b1-03b53b98cddd is
> tainted: high-privileges
> 2012-10-08 00:55:40.002+0000: 1777: error : qemuMonitorIO:574 : internal
> error End of file from monitor
> 2012-10-08 00:56:07.364+0000: 1784: error :
> virStoragePoolSourceFindDuplicate:1718 : operation failed: Storage source
> conflict with pool: '2a3bb121-788a-44b1-9730-7c0f7c2fe193'
>
> *Here's agent.log from the KVM host*
> 2012-10-06 00:29:12,444 WARN  [cloud.agent.Agent]
> (agentRequest-Handler-2:null) Caught:
> java.lang.NullPointerException
>         at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2656)
>         at
> com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1001)
>         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)