Cloudstack agent on KVM not connected after upgrade to 4.21.

[nemethga]

problem

We have an ACS environment that we have been successfully upgrading since version 4.18. We last upgraded from version 4.20 to 4.21. ACS in HA was upgraded fine. However, when upgrading the KVM cloudstack agents, there were problems connecting the agents to ACS. They were connecting and disconnecting all the time. Finally, we did a rollback but we still have problems connecting the agents even though we downgraded the agents to 4.20.1. The VMs are running, but the KVMs cannot connect.

versions

ACS 4.20 on OL9, KVM OL8,

The steps to reproduce the bug

1. Upgrade ACS from 4.20 to 4.21
2. Upgrade CS agent from 4.20 to 4.20.2

What to do about it?

We try dowgrade the agent to version 4.20 but we are not sucessfull. There were 2 different errors on the CS agent. I am attaching the log file.

Error message on agent.log

2025-10-27 12:49:26,477 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) iscsi session clean up is disabled
2025-10-27 12:49:26,481 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) The [vm.memballoon.stats.period] property is set to '0', this prevents memory statistics from being displayed corre
ctly. Adjust (increase) the value of this parameter to correct this.
2025-10-27 12:49:31,387 INFO [cloud.agent.Agent] (main:[]) (logid:) Agent [id = 5, uuid = b1991b02-ccc4-4980-a416-0bc962d8d845, name = kvm01.xxx.sk, type = LibvirtComputingResource, zone = 1, pod = 1, workers = 5, port = 8250] with host = 172.xx.xx.xx local id = 1
2025-10-27 12:49:31,392 INFO [utils.nio.NioClient] (main:[]) (logid:) Connecting to 172.16.x.x:8250
2025-10-27 12:49:31,398 INFO [utils.nio.NioClient] (main:[]) (logid:) Connected to 172.16.x.x:8250
2025-10-27 12:49:31,401 INFO [utils.nio.Link] (main:[]) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2025-10-27 12:49:31,825 INFO [utils.nio.NioClient] (main:[]) (logid:) SSL: Handshake done
2025-10-27 12:49:31,897 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from command "lscpu".
2025-10-27 12:49:31,929 ERROR [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Unable to retrieve the CPU speed from lscpu. java.lang.NullPointerException: Cannot invoke "String.trim()" because "in" is null
at java.base/jdk.internal.math.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:1838)
at java.base/jdk.internal.math.FloatingDecimal.parseFloat(FloatingDecimal.java:122)
at java.base/java.lang.Float.parseFloat(Float.java:476)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getCpuSpeedFromCommandLscpu(KVMHostInfo.java:148)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getCpuSpeed(KVMHostInfo.java:119)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getHostInfoFromLibvirt(KVMHostInfo.java:214)
at org.apache.cloudstack.utils.linux.KVMHostInfo.(KVMHostInfo.java:68)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.initialize(LibvirtComputingResource.java:4123)
at com.cloud.agent.Agent.sendStartup(Agent.java:556)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1314)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)

2025-10-27 12:49:06,970 ERROR [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Failed to parse GPU discovery result: com.google.gson.stream.MalformedJsonException: Expected value at line 1 column 1 path $ com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Expected value at line 1 column 1 path $
at com.google.gson.internal.Streams.parse(Streams.java:61)
at com.google.gson.JsonParser.parseReader(JsonParser.java:102)
at com.google.gson.JsonParser.parseReader(JsonParser.java:70)
at com.google.gson.JsonParser.parseString(JsonParser.java:51)
at com.google.gson.JsonParser.parse(JsonParser.java:115)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.parseGpuDevicesFromResult(LibvirtComputingResource.java:2016)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.getGpuDevices(LibvirtComputingResource.java:2009)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.initialize(LibvirtComputingResource.java:4164)
at com.cloud.agent.Agent.sendStartup(Agent.java:556)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1314)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: com.google.gson.stream.MalformedJsonException: Expected value at line 1 column 1 path $
at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1659)
at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:599)
at com.google.gson.stream.JsonReader.peek(JsonReader.java:433)
at com.google.gson.internal.Streams.parse(Streams.java:47)
... 15 more

[boring-cyborg]

Thanks for opening your first issue here! Be sure to follow the issue template!

[weizhouapache]

@nemethga
can you enable debugging and restart agent ?

    sed -i "s/INFO/DEBUG/g" /etc/cloudstack/agent/log4j-cloud.xml && \
    systemctl restart cloudstack-agent

[nemethga]

Here it is

2025-10-28 11:40:19,765 DEBUG [cloud.agent.Agent] (Agent-Handler-1:[]) (logid:) Creating startup task for link: /172.xx.xx.xxx:8250
2025-10-28 11:40:19,765 DEBUG [cloud.agent.Agent] (Agent-Handler-1:[]) (logid:) Startup task created
2025-10-28 11:40:19,770 DEBUG [agent.properties.AgentPropertiesFileHandler] (Agent-Handler-1:[]) (logid:) Property [libvirt.events.enabled] has empty or null value. Using default value [false].
2025-10-28 11:40:19,770 DEBUG [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Libvirt event listening is disabled, not registering status updater
2025-10-28 11:40:19,787 DEBUG [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Received response: Seq 2-0: { Ans: , MgmtId: 345050284381, via: -1, Ver: v1, Flags: 100000, [{"com.cloud.agent.api.StartupA
nswer":{"hostId":"0","pingInterval":"60","result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:19,788 DEBUG [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Startup task cancelled
2025-10-28 11:40:19,788 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Process agent startup answer, agent [id: 0, uuid: null, name: null] connected to the server
2025-10-28 11:40:19,788 DEBUG [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Set agent id 0
2025-10-28 11:40:19,811 ERROR [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Error parsing task java.lang.NullPointerException
at java.base/java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011)
at java.base/java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
at java.base/java.util.Properties.put(Properties.java:1301)
at java.base/java.util.Properties.setProperty(Properties.java:229)
at com.cloud.agent.dao.impl.PropertiesStorage.persist(PropertiesStorage.java:55)
at com.cloud.agent.AgentShell.setPersistentProperty(AgentShell.java:215)
at com.cloud.agent.Agent.setUuid(Agent.java:422)
at com.cloud.agent.Agent.processStartupAnswer(Agent.java:687)
at com.cloud.agent.Agent.processResponse(Agent.java:931)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1219)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)

2025-10-28 11:40:19,978 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Request:Seq 2-4165829655317708801: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.
api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":"200","privateNetworkName":"cloudbr45","publicNetworkName":"cloudbr","guestNetworkName":"cloudbr","storageNetworkName":"cloudbr144"}],"wai
t":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:19,978 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Processing command: com.cloud.agent.api.CheckNetworkCommand
2025-10-28 11:40:20,088 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,111 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564220] for command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,111 DEBUG [kvm.resource.LibvirtComputingResource] (AgentRequest-Handler-2:[]) (logid:) Checking if network cloudbr exists as openvswitch bridge
2025-10-28 11:40:20,112 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,132 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564221] for command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,132 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr45 ].
2025-10-28 11:40:20,152 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564222] for command [/bin/sh -c ovs-vsctl br-exists cloudbr45 ].
2025-10-28 11:40:20,153 DEBUG [kvm.resource.LibvirtComputingResource] (AgentRequest-Handler-2:[]) (logid:) Checking if network cloudbr45 exists as openvswitch bridge
2025-10-28 11:40:20,153 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr45 ].
2025-10-28 11:40:20,173 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564223] for command [/bin/sh -c ovs-vsctl br-exists cloudbr45 ].
2025-10-28 11:40:20,174 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,197 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564224] for command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,198 DEBUG [kvm.resource.LibvirtComputingResource] (AgentRequest-Handler-2:[]) (logid:) Checking if network cloudbr exists as openvswitch bridge
2025-10-28 11:40:20,198 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Executing command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,220 DEBUG [utils.script.Script] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564228] for command [/bin/sh -c ovs-vsctl br-exists cloudbr ].
2025-10-28 11:40:20,223 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Seq 2-4165829655317708801: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.CheckN
etworkAnswer":{"_reconnect":"false","result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:20,294 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Request:Seq 2-4165829655317708802: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100011, [{"com.cloud.agent.
api.ModifyStoragePoolCommand":{"add":"true","pool":{"id":"29","uuid":"72ca4543-7de5-4bea-9979-25dd9220822b","host":"localhost","path":"/opt/mnt/primary","port":"0","type":"SharedMountPoint"},"localPath":"
/mnt//3481f990-1f2b-3923-bb6f-67dbfbdc3832","wait":"300","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:20,294 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Processing command: com.cloud.agent.api.ModifyStoragePoolCommand
2025-10-28 11:40:20,294 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:) Attempting to create storage pool 72ca4543-7de5-4bea-9979-25dd9220822b (SharedMountPoint) in libvirt
2025-10-28 11:40:20,294 DEBUG [kvm.resource.LibvirtConnection] (AgentRequest-Handler-3:[]) (logid:) Looking for libvirtd connection at: qemu:///system
2025-10-28 11:40:20,309 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:) Found existing defined storage pool 72ca4543-7de5-4bea-9979-25dd9220822b, using it.
2025-10-28 11:40:20,309 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:) Trying to fetch storage pool 72ca4543-7de5-4bea-9979-25dd9220822b from libvirt
2025-10-28 11:40:20,310 DEBUG [kvm.resource.LibvirtConnection] (AgentRequest-Handler-3:[]) (logid:) Looking for libvirtd connection at: qemu:///system
2025-10-28 11:40:20,334 DEBUG [utils.script.Script] (Script-7:[]) (logid:) Piped commands executed successfully
2025-10-28 11:40:21,346 DEBUG [utils.script.Script] (Script-9:[]) (logid:) Piped commands executed successfully
2025-10-28 11:40:21,347 DEBUG [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:) Updated used IOPS: 173 for pool: 72ca4543-7de5-4bea-9979-25dd9220822b
2025-10-28 11:40:21,349 DEBUG [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:) Successfully refreshed pool 72ca4543-7de5-4bea-9979-25dd9220822b Capacity: (4.0000 TB) 4398046511104
Used: (1.4489 TB) 1593063636992 Available: (2.5511 TB) 2804982874112
2025-10-28 11:40:21,355 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Seq 2-4165829655317708802: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ModifyS
toragePoolAnswer":{"poolInfo":{"host":"localhost","localPath":"/mnt//3481f990-1f2b-3923-bb6f-67dbfbdc3832","hostPath":"/opt/mnt/primary","poolType":"SharedMountPoint","capacityBytes":"(4.0000 TB) 43980465
11104","availableBytes":"(2.5511 TB) 2804982874112"},"templateInfo":{},"datastoreClusterChildren":[],"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,432 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Request:Seq 2-4165829655317708803: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100011, [{"com.cloud.agent.
api.CleanupNetworkRulesCmd":{"interval":"2092","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,433 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Processing command: com.cloud.agent.api.CleanupNetworkRulesCmd
2025-10-28 11:40:21,433 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Adding a watch list
2025-10-28 11:40:21,435 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Seq 2-4165829655317708803: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer"
:{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,584 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-5:[]) (logid:) Request:Seq 2-4165829655317708804: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100011, [{"com.cloud.agent.
api.ModifySshKeysCommand":{"wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,584 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-5:[]) (logid:) Processing command: com.cloud.agent.api.ModifySshKeysCommand
2025-10-28 11:40:21,586 DEBUG [resource.wrapper.LibvirtModifySshKeysCommandWrapper] (AgentRequest-Handler-5:[]) (logid:) Executing command [chmod 600 /root/.ssh/id_rsa.cloud ].
2025-10-28 11:40:21,588 DEBUG [resource.wrapper.LibvirtModifySshKeysCommandWrapper] (AgentRequest-Handler-5:[]) (logid:) Successfully executed process [2564262] for command [chmod 600 /root/.ssh/id_rsa.cl
oud ].
2025-10-28 11:40:21,590 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-5:[]) (logid:) Seq 2-4165829655317708804: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer"
:{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,607 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-1:[]) (logid:) Request:Seq 2-4165829655317708805: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.
api.SetHostParamsCommand":{"params":{"tungsten.plugin.enable":"false","migratewait":"36000","router.aggregation.command.each.timeout":"600"},"wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,607 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-1:[]) (logid:) Processing command: com.cloud.agent.api.SetHostParamsCommand
2025-10-28 11:40:21,608 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Request:Seq 2-4165829655317708806: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100011, [{"com.cloud.agent.
api.ModifySshKeysCommand":{"wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,608 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Processing command: com.cloud.agent.api.ModifySshKeysCommand
2025-10-28 11:40:21,608 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (AgentRequest-Handler-1:[]) (logid:) The router.aggregation.command.each.timeout in seconds is set to 600
2025-10-28 11:40:21,608 DEBUG [resource.wrapper.LibvirtModifySshKeysCommandWrapper] (AgentRequest-Handler-2:[]) (logid:) Executing command [chmod 600 /root/.ssh/id_rsa.cloud ].
2025-10-28 11:40:21,608 DEBUG [agent.properties.AgentPropertiesFileHandler] (AgentRequest-Handler-1:[]) (logid:) Property [router.aggregation.command.each.timeout] has empty or null value. Using default v
alue [null].
2025-10-28 11:40:21,611 DEBUG [resource.wrapper.LibvirtModifySshKeysCommandWrapper] (AgentRequest-Handler-2:[]) (logid:) Successfully executed process [2564263] for command [chmod 600 /root/.ssh/id_rsa.cl
2025-10-28 11:40:21,613 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Seq 2-4165829655317708806: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer"
:{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,630 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-1:[]) (logid:) Seq 2-4165829655317708805: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer
":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,724 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Request:Seq 2-4165829655317708807: { Cmd , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 100111, [{"com.cloud.agent.
api.ReadyCommand":{"dcId":"1","hostId":"2","enableHumanReadableSizes":"true","wait":"60","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,724 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Processing command: com.cloud.agent.api.ReadyCommand
2025-10-28 11:40:21,724 INFO [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Processing agent ready command, agent id = 2, uuid = null, name = null
2025-10-28 11:40:21,725 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Set agent id 2
2025-10-28 11:40:21,725 WARN [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Caught: java.lang.NullPointerException
at java.base/java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011)
at java.base/java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
at java.base/java.util.Properties.put(Properties.java:1301)
at java.base/java.util.Properties.setProperty(Properties.java:229)
at com.cloud.agent.dao.impl.PropertiesStorage.persist(PropertiesStorage.java:55)
at com.cloud.agent.AgentShell.setPersistentProperty(AgentShell.java:215)
at com.cloud.agent.Agent.setUuid(Agent.java:422)
at com.cloud.agent.Agent.processReadyCommand(Agent.java:956)
at com.cloud.agent.Agent.processRequest(Agent.java:774)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1193)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)

2025-10-28 11:40:21,730 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-3:[]) (logid:) Seq 2-4165829655317708807: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer
":{"result":"false","details":"java.lang.NullPointerException
at java.base/java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011)
at java.base/java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
at java.base/java.util.Properties.put(Properties.java:1301)
at java.base/java.util.Properties.setProperty(Properties.java:229)
at com.cloud.agent.dao.impl.PropertiesStorage.persist(PropertiesStorage.java:55)
at com.cloud.agent.AgentShell.setPersistentProperty(AgentShell.java:215)
at com.cloud.agent.Agent.setUuid(Agent.java:422)
at com.cloud.agent.Agent.processReadyCommand(Agent.java:956)
at com.cloud.agent.Agent.processRequest(Agent.java:774)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1193)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-28 11:40:21,804 DEBUG [utils.nio.NioClient] (Agent-NioConnectionHandler-1:[]) (logid:) Location 1: Socket Socket[addr=/172.xx.xx.xxx,port=8250,localport=51902] closed on read. Probably -1 returned
: Connection closed with -1 on reading size.
2025-10-28 11:40:21,805 DEBUG [utils.nio.NioClient] (Agent-NioConnectionHandler-1:[]) (logid:) Closing socket Socket[addr=/172.xx.xx.xxx,port=8250,localport=51902]
2025-10-28 11:40:21,806 DEBUG [cloud.agent.Agent] (Agent-Handler-5:[]) (logid:) Executing disconnect task - /172.xx.xx.xxx:8250
2025-10-28 11:40:21,807 DEBUG [cloud.agent.Agent] (Agent-Handler-5:[]) (logid:) Clearing watch list: 1
2025-10-28 11:40:21,807 INFO [cloud.agent.Agent] (Agent-Handler-5:[]) (logid:) Lost connection to host: 172.xx.xx.xxx. Attempting reconnection while we still have 0 commands in progress.
2025-10-28 11:40:21,807 INFO [utils.nio.NioClient] (Agent-Handler-5:[]) (logid:) NioClient connection closed
2025-10-28 11:40:26,808 DEBUG [agent.properties.AgentPropertiesFileHandler] (Agent-Handler-5:[]) (logid:) Property [ssl.handshake.timeout] has empty or null value. Using default value [null].
2025-10-28 11:40:26,808 INFO [cloud.agent.Agent] (Agent-Handler-5:[]) (logid:) Reconnecting to host: 172.xx.xx.xxx
2025-10-28 11:40:26,808 INFO [utils.nio.NioClient] (Agent-Handler-5:[]) (logid:) Connecting to 172.xx.xx.xxx:8250
2025-10-28 11:40:26,809 INFO [utils.nio.NioClient] (Agent-Handler-5:[]) (logid:) Connected to 172.xx.xx.xxx:8250
2025-10-28 11:40:26,809 INFO [utils.nio.Link] (Agent-Handler-5:[]) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2025-10-28 11:40:26,992 INFO [utils.nio.NioClient] (Agent-Handler-5:[]) (logid:) SSL: Handshake done
2025-10-28 11:40:26,994 DEBUG [kvm.resource.LibvirtConnection] (Agent-Handler-1:[]) (logid:) Looking for libvirtd connection at: qemu:///system
2025-10-28 11:40:27,064 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from command "lscpu".
2025-10-28 11:40:27,064 DEBUG [utils.script.Script] (Agent-Handler-1:[]) (logid:) Executing command [/bin/bash -c lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:digit:]].[[:digit:]]+GHz' | sed 's
/GHz//g' ].
2025-10-28 11:40:27,096 DEBUG [utils.script.Script] (Agent-Handler-1:[]) (logid:) Successfully executed process [2564403] for command [/bin/bash -c lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:
digit:]].[[:digit:]]+GHz' | sed 's/GHz//g' ].
2025-10-28 11:40:27,097 ERROR [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Unable to retrieve the CPU speed from lscpu. java.lang.NullPointerException: Cannot invoke "String.trim()" because "in
" is null
at java.base/jdk.internal.math.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:1838)
at java.base/jdk.internal.math.FloatingDecimal.parseFloat(FloatingDecimal.java:122)
at java.base/java.lang.Float.parseFloat(Float.java:476)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getCpuSpeedFromCommandLscpu(KVMHostInfo.java:141)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getCpuSpeed(KVMHostInfo.java:115)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getHostInfoFromLibvirt(KVMHostInfo.java:207)
at org.apache.cloudstack.utils.linux.KVMHostInfo.(KVMHostInfo.java:68)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.initialize(LibvirtComputingResource.java:3766)
at com.cloud.agent.Agent.sendStartup(Agent.java:541)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1212)
at com.cloud.utils.nio.Task.call(Task.java:83)
at com.cloud.utils.nio.Task.call(Task.java:29)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)

2025-10-28 11:40:27,097 DEBUG [utils.script.Script] (Agent-Handler-1:[]) (logid:) Executing command [/bin/bash -c lscpu | grep -i 'CPU max MHz' | head -n 1 | sed 's/^.: //' | xargs ].
2025-10-28 11:40:27,129 DEBUG [utils.script.Script] (Agent-Handler-1:[]) (logid:) Successfully executed process [2564410] for command [/bin/bash -c lscpu | grep -i 'CPU max MHz' | head -n 1 | sed 's/^.:
//' | xargs ].
2025-10-28 11:40:27,130 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Command [lscpu | grep -i 'CPU max MHz' | head -n 1 | sed 's/^.*: //' | xargs] resulted in the value [3729] for CPU spe
ed.
2025-10-28 11:40:27,130 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching host CPU arch

[weizhouapache]

@nemethga
was the host added to cloudstack before, then removed and re-added ?

[nemethga]

@nemethga was the host added to cloudstack before, then removed and re-added ?

no, because we tested the update procedure in a test environment and everything went without problems. During the upgrade in production, we have a problem with connecting to the guests on which the VM is still running. Another error appears in the log, the uefi.properties error.

2025-10-28 14:30:02,807 ERROR [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) uefi properties file not found due to: Unable to find file uefi.properties.
2025-10-28 14:30:02,809 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [domr.scripts.dir] was altered. Now using the value [scripts/network/domr/kvm].
2025-10-28 14:30:02,809 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [hypervisor.scripts.dir] has empty or null value. Using default value [scripts/vm/hypervisor].
2025-10-28 14:30:02,809 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [kvm.scripts.dir] has empty or null value. Using default value [scripts/vm/hypervisor/kvm].
2025-10-28 14:30:02,810 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [network.scripts.dir] has empty or null value. Using default value [scripts/vm/network/vnet].
2025-10-28 14:30:02,810 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [storage.scripts.dir] has empty or null value. Using default value [scripts/storage/qcow2].
2025-10-28 14:30:02,810 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [network.bridge.type] was altered. Now using the value [openvswitch].
2025-10-28 14:30:02,811 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [openvswitch.dpdk.enabled] has empty or null value. Using default value [false].
2025-10-28 14:30:02,812 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [direct.download.temporary.download.location] has empty or null value. Using default value [/var/lib/libvirt/images].
2025-10-28 14:30:02,813 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [host.cache.location] has empty or null value. Using default value [/var/cache/cloud].
2025-10-28 14:30:02,823 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (main:[]) (logid:) The router.aggregation.command.each.timeout in seconds is set to 600
2025-10-28 14:30:02,823 DEBUG [agent.properties.AgentPropertiesFileHandler] (main:[]) (logid:) Property [zone] was altered. Now using the value [1].

[weizhouapache]

@nemethga
can you check the host table ?

select * from host where id=2\G

[nemethga]

+----+-------------------+--------------------------------------+--------+---------+--------------------+-----------------+---------------------+--------------------+-----------------+---------------------+----------------------+-----------------------+-------------------+------------+-------------------+----------------+--------------------+------------+----------------+--------+-------------+------+-------+-------------------------------------+---------+-----------------+--------------------+---------------+----------+----------+--------+------------+--------------+---------------------------------------------------------------+-----------+-------+-------------+------------+----------------+--------------+---------------------+---------+--------------+----------------+-------+-------------+--------------+--------+
| id | name | uuid | status | type | private_ip_address | private_netmask | private_mac_address | storage_ip_address | storage_netmask | storage_mac_address | storage_ip_address_2 | storage_mac_address_2 | storage_netmask_2 | cluster_id | public_ip_address | public_netmask | public_mac_address | proxy_port | data_center_id | pod_id | cpu_sockets | cpus | speed | url | fs_type | hypervisor_type | hypervisor_version | ram | resource | version | parent | total_size | capabilities | guid | available | setup | dom0_memory | last_ping | mgmt_server_id | disconnected | created | removed | update_count | resource_state | owner | lastUpdated | engine_state | arch |
+----+-------------------+--------------------------------------+--------+---------+--------------------+-----------------+---------------------+--------------------+-----------------+---------------------+----------------------+-----------------------+-------------------+------------+-------------------+----------------+--------------------+------------+----------------+--------+-------------+------+-------+-------------------------------------+---------+-----------------+--------------------+---------------+----------+----------+--------+------------+--------------+---------------------------------------------------------------+-----------+-------+-------------+------------+----------------+--------------+---------------------+---------+--------------+----------------+-------+-------------+--------------+--------+
| 2 | kvmxx.xx.sk | 9b8d38a2-f304-4716-acca-dc49667c1757 | Alert | Routing | 172.xx.xx.xx | 255.255.255.0 | ca:49:56:df:f3:40 | 172.xx.xx.xx | 255.255.255.0 | ca:49:56:df:f3:40 | NULL | NULL | NULL | 1 | NULL | NULL | NULL | NULL | 1 | 1 | 2 | 64 | 3729 | iqn.1988-12.com.oracle:8320fcb38042 | NULL | KVM | NULL | 1080372228096 | NULL | 4.20.2.0 | NULL | NULL | hvm,snapshot | 3eb07f08-dcb4-3604-99d0-7c4190cda1a1-LibvirtComputingResource | 1 | 0 | 0 | 1720359402 | NULL | NULL | 2024-04-21 21:38:17 | NULL | 372 | Enabled | NULL | NULL | Disabled | x86_64 |
+----+-------------------+--------------------------------------+--------+---------+--------------------+-----------------+---------------------+--------------------+-----------------+---------------------+----------------------+-----------------------+-------------------+------------+-------------------+----------------+--------------------+------------+----------------+--------+-------------+------+-------+-------------------------------------+---------+-----------------+--------------------+---------------+----------+----------+--------+------------+--------------+---------------------------------------------------------------+-----------+-------+-------------+------------+----------------+--------------+---------------------+---------+--------------+----------------+-------+-------------+--------------+--------+

[weizhouapache]

I noticed that the ReadyCommand does not have hostUuid and hostName, below is log on my testing env

{"com.cloud.agent.api.ReadyCommand":{"dcId":"1","hostId":"1","hostUuid":"402c8127-2eb9-491d-9cbd-aae52cfa9f4c","hostName":"ref-trl-xxxx-kvm1","enableHumanReadableSizes":"true","wait":"60","bypassHostMaintenance":"false"}}

@nemethga
can you check management-server.log if there are any error logs around ReadyCommand ?

[weizhouapache]

@nemethga

The steps to reproduce the bug
Upgrade ACS from 4.20 to 4.21
Upgrade CS agent from 4.20 to 4.20.2

can you upgrade ACS mgmt and agent to same version ?

[nemethga]

@nemethga

The steps to reproduce the bug
Upgrade ACS from 4.20 to 4.21
Upgrade CS agent from 4.20 to 4.20.2

can you upgrade ACS mgmt and agent to same version ?

I'll try again.
Errors from the cloud agent logs and management server logs are the deferred logs from the upgrade to 4.21. Since the upgrade failed due to errors, we reverted ACS back to version 4.20. We downgraded the agent to 4.20.x on KVM

In the test environment, I found that I can eliminate the above errors as follows:

1. Problem with lscpu - I solved it by adding host.cpu.manual.speed.mhz= XXXXX to agent.properties on kvm. I got the value via the command "cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq"

2. GPU error problem - I solved it by adding "enable.gpu.discovery=false" to agent.properties

3. UEFI error problem - I solved it by creating a file /etc/cloudstack/agent/uefi.properties with the content "uefi.enable=false"

When I added uefi.properties, the agent connected to ACS. This week we are going to do another iteration of the upgrade to 4.21. I consider these problems as bugs, because since version 4.18 all my upgrades have been fine. Until now.

[nemethga]

. can you check management-server.log if there are any error logs around ReadyCommand ?

Maybe this?

2025-10-27 15:50:12,786 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-359:[ctx-c528d5a8]) (logid:41d31dfa) Seq 2-1489284101776080903: Sending { Cmd , MgmtId: 345050284381, via: 2(kvmxx.xxx.sk), Ver:
v1, Flags: 100111, [{"com.cloud.agent.api.ReadyCommand":{"dcId":"1","hostId":"2","hostUuid":"9b8d38a2-f304-4716-acca-dc49667c1757","hostName":"kvmxx.xxx.sk","enableHumanReadableSizes":"true","wait":
"60","bypassHostMaintenance":"false"}}] }
2025-10-27 15:50:13,678 INFO [c.c.c.ClusterManagerImpl] (Cluster-Heartbeat-1:[ctx-801bd743]) (logid:dd9e64e8) No inactive management server node found
2025-10-27 15:50:13,678 DEBUG [c.c.c.ClusterManagerImpl] (Cluster-Heartbeat-1:[ctx-801bd743]) (logid:dd9e64e8) Peer scan is finished. profiler: Done. Duration: 3ms , profilerQueryActiveList: Done. Duratio
n: 1ms, , profilerSyncClusterInfo: Done. Duration: 0ms, profilerInvalidatedNodeList: Done. Duration: 0ms, profilerRemovedList: Done. Duration: 0ms,, profilerNewList: Done. Duration: 0ms, profilerInactiveL
ist: Done. Duration: 1ms
2025-10-27 15:50:13,717 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:[]) (logid:) Seq 2-1489284101776080903: Processing: { Ans: , MgmtId: 345050284381, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent
.api.ReadyAnswer":{"detailsMap":{"host.virtv2v.version":"1.42.0rhel=8"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-10-27 15:50:13,717 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-12:[]) (logid:) Seq 2-1489284101776080903: No more commands found
2025-10-27 15:50:13,718 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-359:[ctx-c528d5a8]) (logid:41d31dfa) Seq 2-1489284101776080903: Received: { Ans: , MgmtId: 345050284381, via: 2(kvmxx.xxx.sk), V
er: v1, Flags: 110, { ReadyAnswer } }
2025-10-27 15:50:13,718 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentConnectTaskPool-359:[ctx-c528d5a8]) (logid:41d31dfa) Got HOST_UEFI_ENABLE [null] for host [Host {"id":2,"name":"kvmxx.xxx.sk","
type":"Routing","uuid":"9b8d38a2-f304-4716-acca-dc49667c1757"}]:
2025-10-27 15:50:13,721 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentConnectTaskPool-359:[ctx-c528d5a8]) (logid:41d31dfa) Failed to handle host connection: java.lang.NullPointerException
at com.cloud.agent.manager.AgentManagerImpl.notifyMonitorsOfConnection(AgentManagerImpl.java:812)
at com.cloud.agent.manager.AgentManagerImpl.connectHostAgent(AgentManagerImpl.java:1403)
at com.cloud.agent.manager.AgentManagerImpl.sendReadyAndGetAttache(AgentManagerImpl.java:1365)
at com.cloud.agent.manager.AgentManagerImpl.handleConnectedAgent(AgentManagerImpl.java:1419)
at com.cloud.agent.manager.AgentManagerImpl$HandleAgentConnectTask.runInContext(AgentManagerImpl.java:1515)
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 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)