Host stuck state: Alert, When add Secondary storage

[leduyquy]

problem

I have plan deploy 1 zone use local disk and GPU, Because i don't need HA, i don't deploy any shared storage to primary storage. I using only local disk for primary storage.

When i setup Secondary storage use NFS for store template and ISO, KVM host in Zone state stuck on alert, To make sure the NFS configuration works fine, I mounted it manually on the kvm host and managerment and it worked fine

when i created the zone i saw it still created 2 system vm for the zone and it worked fine, things only got worse when i started creating VMs and digging deeper into them

versions

Managerment Version: 4.20.0
Agent Version: 4.20.0
KVM host OS: 22.04

The steps to reproduce the bug

1. Create Zone and set use local storage for user instance and system VM
2. Add Secondary Storage
3. Restart cloudstack-agent or reboot KVM host
   ...

What to do about it?

Add Secondary storage and anything working fine

[DaanHoogland]

@leduyquy,

Can you edit the description to make more clear what the issue is?
Is it that the VMs you speak about are not deploying or starting?
Or are they but not functional?
Can you log in to the systemVMs?
Can you register templates?

[leduyquy]

HI @DaanHoogland

when i add secondary storage using NFS to zone, the KVM host gets stuck in alert state
like it:

now i can't deploy VM, register template or do anything else. The problem was only resolved when I removed the secondary storage from the zone.

I have another zone, it uses ceph for primary storage and doesn't have the above problem.

[DaanHoogland]

So when you add a secondary storage to an already enabled zone, @leduyquy ?
Can the host reach the NFS?
Can you share the agent log for the host?

[leduyquy]

Can the host reach the NFS?
=> Host can connect to nfs server, i tried mounting nfs folder manually on hosts to make sure it works properly

Can you share the agent log for the host?
=> Below is the agent log on host.

2025-04-11 10:42:56,783 INFO [cloud.agent.Agent] (Agent-Handler-1:[]) (logid:) Reconnecting to host:
2025-04-11 10:42:56,783 INFO [utils.nio.NioClient] (Agent-Handler-1:[]) (logid:) Connecting to :8250
2025-04-11 10:42:56,784 INFO [utils.nio.Link] (Agent-Handler-1:[]) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2025-04-11 10:42:56,825 INFO [utils.nio.NioClient] (Agent-Handler-1:[]) (logid:) SSL: Handshake done
2025-04-11 10:42:56,825 INFO [utils.nio.NioClient] (Agent-Handler-1:[]) (logid:) Connected to :8250
2025-04-11 10:42:56,877 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from command "lscpu".
2025-04-11 10:42:56,914 ERROR [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Unable to retrieve the CPU speed from lscpu. java.lang.NullPointerException

2025-04-11 10:42:56,914 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from file [/sys/devices/system/cpu/cpu0/cpufreq/base_frequency].
2025-04-11 10:42:56,915 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Retrieved value [2000000] from file [/sys/devices/system/cpu/cpu0/cpufreq/base_frequency]. This corresponds to a CPU speed of [2000] MHz.
2025-04-11 10:42:56,915 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching host CPU arch
2025-04-11 10:42:56,926 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Host uses control group [cgroup2fs].
2025-04-11 10:42:56,926 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Calculating the max shares of the host.
2025-04-11 10:42:56,926 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) The max shares of the host is [64000].
2025-04-11 10:42:57,009 WARN [utils.script.Script] (Agent-Handler-1:[]) (logid:) Execution of process [1715251] for command [/bin/bash -c virt-v2v --version ] failed.
2025-04-11 10:42:57,009 WARN [utils.script.Script] (Agent-Handler-1:[]) (logid:) Process [1715251] for command [/bin/bash -c virt-v2v --version ] encountered the error: [127].
2025-04-11 10:42:57,030 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Attempting to create storage pool 4952e569-130a-4dd8-817c-78f945323cfa (Filesystem) in libvirt
2025-04-11 10:42:57,052 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Found existing defined storage pool 4952e569-130a-4dd8-817c-78f945323cfa, using it.
2025-04-11 10:42:57,052 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Trying to fetch storage pool 4952e569-130a-4dd8-817c-78f945323cfa from libvirt
2025-04-11 10:42:57,078 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Process agent startup answer, agent id = 0
2025-04-11 10:42:57,079 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Startup Response Received: agent id = 0
2025-04-11 10:42:57,577 WARN [cloud.agent.Agent] (Agent-Handler-5:[]) (logid:8c3b34cc) Unable to send response: null

here is the log from the management server i found. hope it helps

2025-04-11 09:46:30,192 DEBUG [o.a.c.c.p.RootCACustomTrustManager] (pool-13580-thread-1:[]) (logid:) Client/agent connection from ip= accepted without certificate validation.
2025-04-11 09:46:30,465 DEBUG [c.c.a.t.Request] (AgentManager-Handler-7:[ctx-003f58d4]) (logid:) Seq 0-34315: Scheduling the first command { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":"1","cpus":"32","speed":"2000","cpuArch":"x86_64","memory":"268672163840","dom0MinMemory":"1073741824","poolSync":"false","supportsClonedVolumes":"false","caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"5.15.0-135-generic","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"22.04","host.volume.encryption":"true","host.instance.conversion":"false","secured":"true","Host.OS":"Ubuntu"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"9","pod":"9","cluster":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","iqn":"iqn.2004-10.com.ubuntu:01:52c55542e014","privateIpAddress":"","privateMacAddress":"1a:b7:0d:b8:19:7f","privateNetmask":"255.255.255.0","storageIpAddress":"","storageNetmask":"255.255.255.0","storageMacAddress":"1a:b7:0d:b8:19:7f","resourceName":"LibvirtComputingResource","gatewayIpAddress":"","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":"(0 bytes) 0","poolInfo":{"uuid":"4952e569-130a-4dd8-817c-78f945323cfa","host":"","localPath":"/data","hostPath":"/data","poolType":"Filesystem","capacityBytes":"(3.4908 TB) 3838228365312","availableBytes":"(3.4629 TB) 3807542657024"},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"9","pod":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","resourceName":"LibvirtComputingResource","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}}] }
2025-04-11 09:46:30,468 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-13571:[ctx-a28ca8e4]) (logid:4b22fb41) Seq 0-34315: Processing the first command { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":"1","cpus":"32","speed":"2000","cpuArch":"x86_64","memory":"268672163840","dom0MinMemory":"1073741824","poolSync":"false","supportsClonedVolumes":"false","caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"5.15.0-135-generic","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"22.04","host.volume.encryption":"true","host.instance.conversion":"false","secured":"true","Host.OS":"Ubuntu"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"9","pod":"9","cluster":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","iqn":"iqn.2004-10.com.ubuntu:01:52c55542e014","privateIpAddress":"","privateMacAddress":"1a:b7:0d:b8:19:7f","privateNetmask":"255.255.255.0","storageIpAddress":"","storageNetmask":"255.255.255.0","storageMacAddress":"1a:b7:0d:b8:19:7f","resourceName":"LibvirtComputingResource","gatewayIpAddress":"","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":"(0 bytes) 0","poolInfo":{"uuid":"4952e569-130a-4dd8-817c-78f945323cfa","host":"","localPath":"/data","hostPath":"/data","poolType":"Filesystem","capacityBytes":"(3.4908 TB) 3838228365312","availableBytes":"(3.4629 TB) 3807542657024"},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"9","pod":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","resourceName":"LibvirtComputingResource","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}}] }
2025-04-11 09:46:30,706 WARN [c.c.a.m.A.HandleAgentConnectTask] (AgentConnectTaskPool-13571:[ctx-a28ca8e4]) (logid:4b22fb41) Unable to create attache for agent: Seq 0-34315: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":"1","cpus":"32","speed":"2000","cpuArch":"x86_64","memory":"268672163840","dom0MinMemory":"1073741824","poolSync":"false","supportsClonedVolumes":"false","caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"5.15.0-135-generic","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"22.04","host.volume.encryption":"true","host.instance.conversion":"false","secured":"true","Host.OS":"Ubuntu"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"9","pod":"9","cluster":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","iqn":"iqn.2004-10.com.ubuntu:01:52c55542e014","privateIpAddress":"","privateMacAddress":"1a:b7:0d:b8:19:7f","privateNetmask":"255.255.255.0","storageIpAddress":"","storageNetmask":"255.255.255.0","storageMacAddress":"1a:b7:0d:b8:19:7f","resourceName":"LibvirtComputingResource","gatewayIpAddress":"","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":"(0 bytes) 0","poolInfo":{"uuid":"4952e569-130a-4dd8-817c-78f945323cfa","host":"","localPath":"/data","hostPath":"/data","poolType":"Filesystem","capacityBytes":"(3.4908 TB) 3838228365312","availableBytes":"(3.4629 TB) 3807542657024"},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"9","pod":"9","guid":"92426e62-ab7a-3ef4-9d7b-0c0d02d93121-LibvirtComputingResource","name":"cs-gpu-01","id":"0","version":"4.20.0.0","resourceName":"LibvirtComputingResource","msHostList":"@static","wait":"0","bypassHostMaintenance":"false"}}] }

[DaanHoogland]

@leduyquy , it seems /bin/bash -c virt-v2v --version fails, can you execute that manually on the host?

[leduyquy]

I don't use KVM migration so I didn't install it, Other hosts also do not need to install this package and it still works fine. After I installed it, the log also no longer has the alert, but the host is still stuck in the alert.

Log on agent:

2025-04-11 16:26:49,589 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Reconnecting to host:
2025-04-11 16:26:49,590 INFO [utils.nio.NioClient] (Agent-Handler-2:[]) (logid:) Connecting to :8250
2025-04-11 16:26:49,591 INFO [utils.nio.Link] (Agent-Handler-2:[]) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2025-04-11 16:26:49,677 INFO [utils.nio.NioClient] (Agent-Handler-2:[]) (logid:) SSL: Handshake done
2025-04-11 16:26:49,677 INFO [utils.nio.NioClient] (Agent-Handler-2:[]) (logid:) Connected to :8250
2025-04-11 16:26:49,706 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from command "lscpu".
2025-04-11 16:26:49,740 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:116)
at org.apache.cloudstack.utils.linux.KVMHostInfo.getHostInfoFromLibvirt(KVMHostInfo.java:196)
at org.apache.cloudstack.utils.linux.KVMHostInfo.(KVMHostInfo.java:69)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.initialize(LibvirtComputingResource.java:3672)
at com.cloud.agent.Agent.sendStartup(Agent.java:458)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1128)
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-04-11 16:26:49,741 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from file [/sys/devices/system/cpu/cpu0/cpufreq/base_frequency].
2025-04-11 16:26:49,742 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Retrieved value [2000000] from file [/sys/devices/system/cpu/cpu0/cpufreq/base_frequency]. This corresponds to a CPU speed of [2000] MHz.
2025-04-11 16:26:49,742 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching host CPU arch
2025-04-11 16:26:49,753 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Host uses control group [cgroup2fs].
2025-04-11 16:26:49,753 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Calculating the max shares of the host.
2025-04-11 16:26:49,753 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) The max shares of the host is [64000].
2025-04-11 16:26:49,898 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Attempting to create storage pool 4952e569-130a-4dd8-817c-78f945323cfa (Filesystem) in libvirt
2025-04-11 16:26:49,901 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Found existing defined storage pool 4952e569-130a-4dd8-817c-78f945323cfa, using it.
2025-04-11 16:26:49,902 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Trying to fetch storage pool 4952e569-130a-4dd8-817c-78f945323cfa from libvirt
2025-04-11 16:26:49,947 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Process agent startup answer, agent id = 0
2025-04-11 16:26:49,949 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Startup Response Received: agent id = 0
2025-04-11 16:26:50,236 WARN [cloud.agent.Agent] (Agent-Handler-1:[]) (logid:6ffc30f3) Unable to send response: null

[DaanHoogland]

@leduyquy ,
can you execute

lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:digit:]].[[:digit:]]+GHz' | sed 's/GHz//g'

on the host (and compare it to the output on the other hosts)?

[leduyquy]

I don't think it's related to the problem I'm having.

I see it will get GHz info from CPU Model name, however for gold series CPU it has removed it from CPU name.

In host problem:

In another host:

I think there is a problem with secondary storage, because when I remove it from the zone, the host changes to state: UP

[DaanHoogland]

sounds reasonable, but as a followup, do the rest of the hosts all look the same?

it must be the combination host/secondary storage as far as I understand, if all other hosts function normally.

[DaanHoogland]

btw, can you also check nfs versions used on the server and the clients?

[leduyquy]

All kvm hosts use NFSv4 and i have never had any problems with it before

I tried another test case. I added a primary storage using NFS to the above zone and it worked fine without any problems.

when i add nfs as secondary storage i notice it mounts to manager and kvm host, however it is removed from manager and host after the process of syncing templates to this secondary storage is complete. Then the state of kvm host agent will change to alert

[leduyquy]

Update: I checked further and found that it is only mounted nfs secondary storage at Secondary Storage VMs

[DaanHoogland]

Update: I checked further and found that it is only mounted nfs secondary storage at Secondary Storage VMs

this seems alright.

it should not be the reason the host goes to alert state.

[weizhouapache]

maybe we need to check what triggered the kvm agent investigation
(which caused the host to Alert state as there is no NFS mounted)

@leduyquy
can you share the full management-server log ?