OSDir


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: KVM Problem by deploying VPC


Ben,


Can you put the KVM agent in debug mode and post the logs?


sed -i 's/INFO/DEBUG/g' /etc/cloudstack/agent/log4j-cloud.xml


Then restart the agent.


- Si


________________________________
From: Benjamin Naber <benjamin.naber@xxxxxxxxxxxxxx>
Sent: Friday, May 18, 2018 2:20 AM
To: Cloudstack Mailinglist
Subject: KVM Problem by deploying VPC

Hi Together,

im currently testing the Configuration of KVM Hosts in our Test environment.
When i try to deploy a VPC the Hypervisor shows me the following error:

Hypervisor Log:

May 18 09:12:08 kvm-test01-sb dbus[883]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 18 09:12:08 kvm-test01-sb systemd: Started Network Manager Script Dispatcher Service.
May 18 09:12:08 kvm-test01-sb nm-dispatcher: req:1 'up' [vnet0]: new request (4 scripts)
May 18 09:12:08 kvm-test01-sb nm-dispatcher: req:1 'up' [vnet0]: start running ordered scripts...
May 18 09:12:08 kvm-test01-sb libvirtd: 2018-05-18 07:12:08.667+0000: 6251: warning : qemuDomainObjTaint:5378 : Domain id=2 name='r-31-VM' uuid=ff22b439-e0d0-44d1-a3cc-8dd23afb82eb is tainted: high-privileges
May 18 09:12:08 kvm-test01-sb dbus[883]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service'
May 18 09:12:08 kvm-test01-sb systemd: Starting Virtual Machine and Container Registration Service...
May 18 09:12:08 kvm-test01-sb dbus[883]: [system] Successfully activated service 'org.freedesktop.machine1'
May 18 09:12:08 kvm-test01-sb systemd: Started Virtual Machine and Container Registration Service.
May 18 09:12:08 kvm-test01-sb systemd-machined: New machine qemu-2-r-31-VM.
May 18 09:12:08 kvm-test01-sb systemd: Started Virtual Machine qemu-2-r-31-VM.
May 18 09:12:08 kvm-test01-sb systemd: Starting Virtual Machine qemu-2-r-31-VM.
May 18 09:12:08 kvm-test01-sb systemd: Unit iscsi.service cannot be reloaded because it is inactive.
May 18 09:12:08 kvm-test01-sb kvm: 1 guest now active
May 18 09:12:12 kvm-test01-sb kernel: kvm [48292]: vcpu0 disabled perfctr wrmsr: 0xc1 data 0xabcd
May 18 09:12:44 kvm-test01-sb kernel: kvm [48292]: vcpu0 disabled perfctr wrmsr: 0xc1 data 0xabcd
May 18 09:12:46 kvm-test01-sb sh: INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:) (logid:b911ffae) Trying to fetch storage pool 2258aa76-7813-354d-b274-961fb337e716 from libvirt
May 18 09:12:46 kvm-test01-sb sh: INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:) (logid:b911ffae) Asking libvirt to refresh storage pool 2258aa76-7813-354d-b274-961fb337e716
May 18 09:13:05 kvm-test01-sb NetworkManager[925]: <info>  [1526627585.6454] manager: (enp8s0f0.233): new VLAN device (/org/freedesktop/NetworkManager/Devices/15)
May 18 09:13:05 kvm-test01-sb NetworkManager[925]: <info>  [1526627585.6470] device (enp8s0f0.233): carrier: link connected
May 18 09:13:05 kvm-test01-sb kernel: brenp8s0f0-233: port 1(enp8s0f0.233) entered blocking state
May 18 09:13:05 kvm-test01-sb kernel: brenp8s0f0-233: port 1(enp8s0f0.233) entered disabled state
May 18 09:13:05 kvm-test01-sb kernel: device enp8s0f0.233 entered promiscuous mode
May 18 09:13:05 kvm-test01-sb kernel: brenp8s0f0-233: port 2(vnet1) entered blocking state
May 18 09:13:05 kvm-test01-sb kernel: brenp8s0f0-233: port 2(vnet1) entered disabled state
May 18 09:13:05 kvm-test01-sb kernel: device vnet1 entered promiscuous mode
May 18 09:13:05 kvm-test01-sb NetworkManager[925]: <info>  [1526627585.6648] manager: (vnet1): new Tun device (/org/freedesktop/NetworkManager/Devices/16)
May 18 09:13:05 kvm-test01-sb NetworkManager[925]: <info>  [1526627585.6662] device (vnet1): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 18 09:13:05 kvm-test01-sb NetworkManager[925]: <info>  [1526627585.6674] device (vnet1): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'external')
May 18 09:13:10 kvm-test01-sb kernel: cloud0: port 1(vnet0) entered disabled state
May 18 09:13:10 kvm-test01-sb kernel: device vnet0 left promiscuous mode
May 18 09:13:10 kvm-test01-sb kernel: cloud0: port 1(vnet0) entered disabled state
May 18 09:13:10 kvm-test01-sb NetworkManager[925]: <info>  [1526627590.5339] device (vnet0): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
May 18 09:13:10 kvm-test01-sb NetworkManager[925]: <info>  [1526627590.5342] device (cloud0): bridge port vnet0 was detached
May 18 09:13:10 kvm-test01-sb NetworkManager[925]: <info>  [1526627590.5342] device (vnet0): released from master device cloud0
May 18 09:13:10 kvm-test01-sb dbus[883]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
May 18 09:13:10 kvm-test01-sb systemd: Starting Network Manager Script Dispatcher Service...
May 18 09:13:10 kvm-test01-sb kernel: device vnet1 left promiscuous mode
May 18 09:13:10 kvm-test01-sb kernel: brenp8s0f0-233: port 2(vnet1) entered disabled state
May 18 09:13:10 kvm-test01-sb dbus[883]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 18 09:13:10 kvm-test01-sb systemd: Started Network Manager Script Dispatcher Service.
May 18 09:13:10 kvm-test01-sb nm-dispatcher: req:1 'down' [vnet0]: new request (4 scripts)
May 18 09:13:10 kvm-test01-sb nm-dispatcher: req:1 'down' [vnet0]: start running ordered scripts...
May 18 09:13:10 kvm-test01-sb NetworkManager[925]: <info>  [1526627590.5772] device (vnet1): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
May 18 09:13:10 kvm-test01-sb NetworkManager[925]: <info>  [1526627590.5772] device (vnet1): released from master device brenp8s0f0-233
May 18 09:13:10 kvm-test01-sb libvirtd: 2018-05-18 07:13:10.596+0000: 1519: error : qemuMonitorIO:704 : internal error: End of file from qemu monitor
May 18 09:13:10 kvm-test01-sb kvm: 0 guests now active
May 18 09:13:10 kvm-test01-sb systemd-machined: Machine qemu-2-r-31-VM terminated.
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching uuid 'ff22b439-e0d0-44d1-a3cc-8dd23afb82eb' (r-31-VM)
May 18 09:13:11 kvm-test01-sb kernel: device enp8s0f0.233 left promiscuous mode
May 18 09:13:11 kvm-test01-sb kernel: brenp8s0f0-233: port 1(enp8s0f0.233) entered disabled state
May 18 09:13:11 kvm-test01-sb NetworkManager[925]: <info>  [1526627591.2137] device (enp8s0f0.233): released from master device brenp8s0f0-233
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: INFO  [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:) (logid:94c38c31) No existing libvirtd connection found. Opening a new one
May 18 09:13:11 kvm-test01-sb sh: libvirt: LXC Driver error : Domain not found: No domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: WARN  [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:) (logid:94c38c31) Can not find a connection for Instance r-31-VM. Assuming the default connection.
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'
May 18 09:13:11 kvm-test01-sb sh: libvirt: QEMU Driver error : Domain not found: no domain with matching name 'r-31-VM'

CS Management Exception:

2018-05-18 09:13:11,284 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Failed to start instance VM[DomainRouter|r-31-VM]
com.cloud.utils.exception.ExecutionException: Unable to start  VM:ff22b439-e0d0-44d1-a3cc-8dd23afb82eb due to error in finalizeStart, not retrying
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1099)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4691)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
        at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4852)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:558)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:506)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2018-05-18 09:13:11,289 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Cleaning up resources for the vm VM[DomainRouter|r-31-VM] in Starting state
2018-05-18 09:13:11,291 DEBUG [c.c.a.t.Request] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Seq 10-6761873365520090721: Sending  { Cmd , MgmtId: 109952567336, via: 10(kvm-test01-sb), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"r-31-VM","executeInSequence":false,"wait":0}}] }
2018-05-18 09:13:11,627 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null) (logid:) Seq 10-6761873365520090721: Processing:  { Ans: , MgmtId: 109952567336, via: 10, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2018-05-18 09:13:11,627 DEBUG [c.c.a.t.Request] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Seq 10-6761873365520090721: Received:  { Ans: , MgmtId: 109952567336, via: 10(kvm-test01-sb), Ver: v1, Flags: 10, { StopAnswer } }
2018-05-18 09:13:11,639 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Released nic: NicProfile[65-31-null-null-null
2018-05-18 09:13:11,646 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Successfully released network resources for the vm VM[DomainRouter|r-31-VM]
2018-05-18 09:13:11,646 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-30:ctx-67604a44 job-169/job-170 ctx-ec9dfbf1) (logid:94c38c31) Successfully cleanued up resources for the vm VM[DomainRouter|r-31-VM] in Starting state

Deployment of Isolatet Networks and redundant VPCs, works wothout any problems.

CS Version: 4.10
KVM Host: CentOS 7.4 minimal (libvirt-3.9.0-14.el7_5.2.x86_64, qemu-kvm-1.5.3-156.el7.x86_64, kernel-3.10.0-693.el7.x86_64)

Someone got an i idea ?

Kind regards

Ben