Cloudstack agent doesn't want to start in loop

[bragonznx]

ISSUE TYPE

• Bug Report

COMPONENT NAME

cloudstack-agent

CLOUDSTACK VERSION

4.15

CONFIGURATION

OS / ENVIRONMENT

Ubuntu 20.04 LTS
QEMU emulator version 4.2.1 (Debian 1:4.2-3ubuntu6.16)
libvirt : 6.0.0

SUMMARY

The cloudstack-agent doesn't want to start and crashloop saying :

2021-05-29 07:07:03,384 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Found existing defined storage pool a2e605c9-b2ac-4dd9-9442-a666debbfc35, using it.
2021-05-29 07:07:03,384 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool a2e605c9-b2ac-4dd9-9442-a666debbfc35 from libvirt
2021-05-29 07:07:03,423 INFO [cloud.serializer.GsonHelper] (Agent-Handler-1:null) (logid:) Default Builder inited.
2021-05-29 07:07:03,450 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0
2021-05-29 07:07:03,451 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0
2021-05-29 07:07:03,452 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
2021-05-29 07:07:03,457 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0
2021-05-29 07:07:15,040 INFO [cloud.agent.AgentShell] (main:null) (logid:) Agent started
2021-05-29 07:07:15,044 INFO [cloud.agent.AgentShell] (main:null) (logid:) Implementation Version is 4.15.0.0
2021-05-29 07:07:15,045 INFO [cloud.agent.AgentShell] (main:null) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties
2021-05-29 07:07:15,055 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to using properties file for storage
2021-05-29 07:07:15,055 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to the constant time backoff algorithm
2021-05-29 07:07:15,057 INFO [cloud.utils.LogUtils] (main:null) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml
2021-05-29 07:07:15,066 INFO [cloud.agent.AgentShell] (main:null) (logid:) Using default Java settings for IPv6 preference for agent connection
2021-05-29 07:07:15,131 INFO [cloud.agent.Agent] (main:null) (logid:) id is 0
2021-05-29 07:07:15,139 ERROR [kvm.resource.LibvirtComputingResource] (main:null) (logid:) uefi properties file not found due to: Unable to find file uefi.properties.
2021-05-29 07:07:15,172 INFO [kvm.resource.LibvirtConnection] (main:null) (logid:) No existing libvirtd connection found. Opening a new one
2021-05-29 07:07:15,313 INFO [kvm.resource.LibvirtComputingResource] (main:null) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver.
2021-05-29 07:07:15,424 INFO [kvm.resource.LibvirtComputingResource] (main:null) (logid:) iscsi session clean up is disabled
2021-05-29 07:07:15,434 INFO [cloud.agent.Agent] (main:null) (logid:) Agent [id = 0 : type = LibvirtComputingResource : zone = 85b30a41-6416-4ad2-8ceb-2c6a52bf9de5 : pod = 632d2e63-e32e-4777-a8b1-9979c7cc1d71 : workers = 5 : host = 192.168.70.114 : port = 8250
2021-05-29 07:07:15,441 INFO [utils.nio.NioClient] (main:null) (logid:) Connecting to 192.168.70.114:8250
2021-05-29 07:07:15,444 INFO [utils.nio.Link] (main:null) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2021-05-29 07:07:15,459 WARN [utils.nio.Link] (main:null) (logid:) Failed to load keystore, using trust all manager
2021-05-29 07:07:15,592 INFO [utils.nio.NioClient] (main:null) (logid:) SSL: Handshake done
2021-05-29 07:07:15,593 INFO [utils.nio.NioClient] (main:null) (logid:) Connected to 192.168.70.114:8250
2021-05-29 07:07:15,601 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:null) (logid:) Could not read cpuinfo_max_freq, falling back on libvirt
2021-05-29 07:07:15,632 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Attempting to create storage pool a2e605c9-b2ac-4dd9-9442-a666debbfc35 (Filesystem) in libvirt
2021-05-29 07:07:15,635 ERROR [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Connection with libvirtd is broken: invalid connection pointer in virConnectGetVersion
2021-05-29 07:07:15,637 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Found existing defined storage pool a2e605c9-b2ac-4dd9-9442-a666debbfc35, using it.
2021-05-29 07:07:15,637 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool a2e605c9-b2ac-4dd9-9442-a666debbfc35 from libvirt
2021-05-29 07:07:15,676 INFO [cloud.serializer.GsonHelper] (Agent-Handler-1:null) (logid:) Default Builder inited.
2021-05-29 07:07:15,703 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0
2021-05-29 07:07:15,703 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0
2021-05-29 07:07:15,706 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
2021-05-29 07:07:15,710 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0

STEPS TO REPRODUCE

virsh qemu and KVM are fully functionnal we were able to start a VM and destroy it using virsh ! 

EXPECTED RESULTS

We want to be able to add the KVM hosts inside cloudstack and we don't manage to get the agent working

ACTUAL RESULTS

we crash loop with this error : 
ERROR [kvm.resource.LibvirtConnection] (Agent-Handler-1:null) (logid:) Connection with libvirtd is broken: invalid connection pointer in virConnectGetVersion

[bragonznx]

We have 128Go of memory on the host so no minimum requierment issue.
The hypervisor is fully fonctionnal, I tested it with virsh and I was able to start a VM ! and to destroy it afterward
but the agent still doesn't want to start

[weizhouapache]

@bragonznx have you added the host on cloudstack ui ?

We have 128Go of memory on the host so no minimum requierment issue.
The hypervisor is fully fonctionnal, I tested it with virsh and I was able to start a VM ! and to destroy it afterward
but the agent still doesn't want to start

[bragonznx]

Hi @weizhouapache
Thanks for helping me with that.
On the manager side I get an error 530 when I want to add this host

Inside the manager log I get in loop something like that :

2021-05-29 08:01:34,205 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-3817:ctx-50ed930d) (logid:f2ed1564) Seq 0-0: Processing the first command { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":"2","cpus":"32","speed":"3499","memory":"269075460096","dom0MinMemory":"1073741824","poolSync":"false","supportsClonedVolumes":"false","caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"5.4.0-73-generic","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"20.04","secured":"false","Host.OS":"Ubuntu"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"85b30a41-6416-4ad2-8ceb-2c6a52bf9de5","pod":"632d2e63-e32e-4777-a8b1-9979c7cc1d71","cluster":"c6234b13-41f3-4cf0-ad38-5e2ea8c6e7c6","guid":"97851bbc-2e94-4ec0-972f-2ba927ad560f-LibvirtComputingResource","name":"hyper15","id":"0","version":"4.15.0.0","iqn":"iqn.1993-08.org.debian:01:4efdaa48c143","publicIpAddress":"192.168.70.206","publicNetmask":"255.255.255.0","publicMacAddress":"f4:03:43:a3:a2:d0","privateIpAddress":"192.168.70.206","privateMacAddress":"f4:03:43:a3:a2:d0","privateNetmask":"255.255.255.0","storageIpAddress":"192.168.70.206","storageNetmask":"255.255.255.0","storageMacAddress":"f4:03:43:a3:a2:d0","resourceName":"LibvirtComputingResource","gatewayIpAddress":"192.168.70.1","msHostList":"192.168.70.114","wait":"0"}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":"(0 bytes) 0","poolInfo":{"uuid":"a2e605c9-b2ac-4dd9-9442-a666debbfc35","host":"192.168.70.206","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":"(39.12 GB) 42007232512","availableBytes":"(37.00 GB) 39725334528"},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"85b30a41-6416-4ad2-8ceb-2c6a52bf9de5","pod":"632d2e63-e32e-4777-a8b1-9979c7cc1d71","guid":"97851bbc-2e94-4ec0-972f-2ba927ad560f-LibvirtComputingResource","name":"hyper15","id":"0","version":"4.15.0.0","resourceName":"LibvirtComputingResource","msHostList":"192.168.70.114","wait":"0"}}] }
2021-05-29 08:01:34,208 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3817:ctx-50ed930d) (logid:f2ed1564) Cannot parse 85b30a41-6416-4ad2-8ceb-2c6a52bf9de5 into Long.
2021-05-29 08:01:34,208 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3817:ctx-50ed930d) (logid:f2ed1564) Failed to handle host connection:
java.lang.IllegalArgumentException: Host 192.168.70.206 sent incorrect data center: 85b30a41-6416-4ad2-8ceb-2c6a52bf9de5
at com.cloud.resource.ResourceManagerImpl.createHostVO(ResourceManagerImpl.java:1865)
at com.cloud.resource.ResourceManagerImpl.createHostVOForConnectedAgent(ResourceManagerImpl.java:2278)
at jdk.internal.reflect.GeneratedMethodAccessor90.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy188.createHostVOForConnectedAgent(Unknown Source)
at com.cloud.agent.manager.AgentManagerImpl.handleConnectedAgent(AgentManagerImpl.java:1097)
at com.cloud.agent.manager.AgentManagerImpl$HandleAgentConnectTask.runInContext(AgentManagerImpl.java:1194)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2021-05-29 08:01:34,211 WARN [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3817:ctx-50ed930d) (logid:f2ed1564) Unable to create attache for agent: Seq 0-0: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":"2","cpus":"32","speed":"3499","memory":"269075460096","dom0MinMemory":"1073741824","poolSync":"false","supportsClonedVolumes":"false","caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"5.4.0-73-generic","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"20.04","secured":"false","Host.OS":"Ubuntu"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"85b30a41-6416-4ad2-8ceb-2c6a52bf9de5","pod":"632d2e63-e32e-4777-a8b1-9979c7cc1d71","cluster":"c6234b13-41f3-4cf0-ad38-5e2ea8c6e7c6","guid":"97851bbc-2e94-4ec0-972f-2ba927ad560f-LibvirtComputingResource","name":"hyper15","id":"0","version":"4.15.0.0","iqn":"iqn.1993-08.org.debian:01:4efdaa48c143","publicIpAddress":"192.168.70.206","publicNetmask":"255.255.255.0","publicMacAddress":"f4:03:43:a3:a2:d0","privateIpAddress":"192.168.70.206","privateMacAddress":"f4:03:43:a3:a2:d0","privateNetmask":"255.255.255.0","storageIpAddress":"192.168.70.206","storageNetmask":"255.255.255.0","storageMacAddress":"f4:03:43:a3:a2:d0","resourceName":"LibvirtComputingResource","gatewayIpAddress":"192.168.70.1","msHostList":"192.168.70.114","wait":"0"}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":"(0 bytes) 0","poolInfo":{"uuid":"a2e605c9-b2ac-4dd9-9442-a666debbfc35","host":"192.168.70.206","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":"(39.12 GB) 42007232512","availableBytes":"(37.00 GB) 39725334528"},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"85b30a41-6416-4ad2-8ceb-2c6a52bf9de5","pod":"632d2e63-e32e-4777-a8b1-9979c7cc1d71","guid":"97851bbc-2e94-4ec0-972f-2ba927ad560f-LibvirtComputingResource","name":"hyper15","id":"0","version":"4.15.0.0","resourceName":"LibvirtComputingResource","msHostList":"192.168.70.114","wait":"0"}}] }
2021-05-29 08:01:34,254 WARN [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) (logid:) Throwing away a request because it came through as the first command on a connect: Seq 0--1: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 111, [{"com.cloud.agent.api.ShutdownCommand":{"reason":"sig.kill","removeHost":"false","wait":"0"}}] }
2021-05-29 08:01:34,293 WARN [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) Throwing away a request because it came through as the first command on a connect: Seq 0-1: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"0","wait":"0"}}] }
2021-05-29 08:01:35,113 INFO [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) Connection from /192.168.70.120 closed but no cleanup was done.
2021-05-29 08:01:35,267 INFO [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) Connection from /192.168.70.206 closed but no cleanup was do

[weizhouapache]

@bragonznx
please check /etc/cloudstack/agent/agent.properties on hosts
the value of zone,cluster,pod should be id not uuid

an example below

cluster=1
pod=1
zone=1
`

[bragonznx]

Ok thanks
I found the issue, it was double and no documented at all.

1. Yes you need to use the ID and not the UUID, but the WEBUI is only showing the UUID (which makes no sens to me)
   My advice is to update the doc to speak about that.

2. the sshd config of the KVM hypervisor need to accepted weak encryption because the manager is using old encryptions method inside the java auth :
   add to your KVM host /etc/ssh/sshd_config :
   KexAlgorithms +diffie-hellman-group1-sha1
   Ciphers +aes128-cbc
   restart ssh

And you should be able to connect via the manager to the KVM host !

[weizhouapache]

@bragonznx
agent.properties is changed when you adds the host. you do not need to create or change it manually.

yes, some operations (add host, cancel host maintenance, etc) are done via ssh with user/password login, from management server to hosts.

[yadvr]

@bragonznx the issue of ssh library has been fixed in 4.15.1 with #4099
You won't need the sshd workaround starting 4.15.1. Closing on your remark that you've fixed it with the workaround.

[tampler]

@rhtyd The issue was NOT fixed in 4.15.1

I followed your blog here to setup CloudStack on Ubuntu 20.04.2
Still getting the ERROR [kvm.resource.LibvirtConnection] (Agent-Handler-1:) (logid:) Connection with libvirtd is broken: invalid connection pointer in virConnectGetVersion

My agent.properties:

cluster=default
pod=default
resource=com.cloud.hypervisor.kvm.resource.LibvirtComputingResource
private.network.device=cloudbr0
domr.scripts.dir=scripts/network/domr/kvm
guest.network.device=cloudbr0
hypervisor.type=kvm
port=8250
zone=default
public.network.device=cloudbr0
local.storage.uuid=1caef572-3417-4a15-b871-0ed392d4269a
host=localhost
guid=4adb36ce-833b-4250-b049-b3c7d08c6f82
LibvirtComputingResource.id=0
workers=5
iscsi.session.cleanup.enabled=false

Setup:

Ubuntu 20.04.2 Server
KVM
CloudStack 4.15.1.0~focal
Compiled against library: libvirt 6.0.0
Using library: libvirt 6.0.0
Using API: QEMU 6.0.0
Running hypervisor: QEMU 4.2.1

PS:
I'm using a non-root user to launch the server. Maybe I've missed some setup in the /etc/sudoers file ?

PPS:
I set ca.plugin.root.auth.strictness to "false" in the web GUI, rebooted the server, but still getting the same

PPPS:
I also updated my sshd_config with the following:

#PubkeyAcceptedKeyTypes=+ssh-dss
#HostKeyAlgorithms=+ssh-dss
#KexAlgorithms=+diffie-hellman-group1-sha1
KexAlgorithms +diffie-hellman-group1-sha1
Ciphers +aes128-cbc

Nothing worked

Any ideas ?

[tampler]

Hey @bragonznx

Have you managed to install Cloudstack on Ubuntu 20.04 ? Which install manual have you followed to get that done?

Thanks

[bragonznx]

Hello Tampler
The manual isn't complete to my view
To be able to install the agent, their is a couple of tricks and tips to do ....

0. Make sure the management network CIDR is configured properly on the cloudstack manager:

Head to configuration → global settings and search for management.network.cidr

management.network.cidr The cidr of management server network Advanced X.X.X.X

Edit the X.X.X.X value here

1. Make sure your primary and secondary storage is available; this can cause the agent to loop while waiting for storage and can block discovery

2. Clean up the host from the Cloudstack dashboard:

• Head to infrastructure → hosts - Edit host → enable maintenance (warning this causes migration) - Edit host → delete host

3. Head on the host you wish to re-attach

systemctl stop cloudstack-agent
cd /etc/cloudstack/agent
mkdir old
mv cloud.* old/
cp agent.properties old/
echo > agent.properties
systemctl start cloudstack-agent
4. Add the host using the Web UI or the Cloudmonkey CLI

add host username=[USER] password=[PASSWORD] hosttags=[TAGS] url=http://[IP] hypervis
or=kvm zoneid=[ZONE_ID] clusterid=[CLUSTER_ID] podid=[POD_ID]

[tampler]

Hello @bragonznx

Tried to reset agent.properties and used the CloudMonkey CLI . Still no luck. Any more thoughts?

(localcloud) 🐱 > add host username=<login> password=<pass> hosttags=tag0 url=http://192.168.1.55 hypervisor=kvm zoneid=1c828cb5-d3d7-4b22-ab50-b6827d7a22a5 clusterid=5f6faf25-65e7-4746-a183-957f4cd146ec podid=b9f813fd-cb3f-4dfa-987a-66b1295c3cfa
🙈 Error: (HTTP 530, error code 9999) Unable to add the host

[tampler]

@bragonznx
please check /etc/cloudstack/agent/agent.properties on hosts
the value of zone,cluster,pod should be id not uuid

an example below

cluster=1
pod=1
zone=1
`

Okay, I fixed an issue. Set cluster, pod, zone id to 1 and restarted libvirtd and cloudstack-agent under the root.
Works for me now! Thanks everybody for your help and advice