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 <[email protected]> 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
