Unable to provision keys

[nlindblo]

I asked previously about "assuming server identity" when physically replacing a server, this broadly worked but I could not provision the host security keys. In the end, I removed the previous server from the database and reinstalled the "new" server again with same IP and name, added it as a management server and host. However, I am still unable to provision the security keys, it appears from the logs (below) that libvirtd fails to restart (I can execute sudo service libvirtd restart successfully). I am also unable to launch any VM's on the new server even when unsecure, not sure if this is related and the secure comms needs to be established first. Some help would be appreciated

agent.log snippet

2025-07-28 08:13:56,748 INFO [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Restarting libvirt after certificate provisioning/renewal
2025-07-28 08:13:56,764 INFO [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Stopping the agent: Reason = sig.kill
2025-07-28 08:13:56,765 WARN [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Execution of process [15555] for command [sudo service libvirtd restart ] failed.
2025-07-28 08:13:56,765 WARN [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Process [15555] for command [sudo service libvirtd restart ] encountered the error: [].
2025-07-28 08:13:56,767 WARN [cloud.agent.Agent] (CertificateRenewalTask-1:[]) (logid:) Failed to execute post certificate renewal command: java.lang.IllegalStateException: Shutdown in progress
at java.base/java.lang.ApplicationShutdownHooks.remove(ApplicationShutdownHooks.java:82)
at java.base/java.lang.Runtime.removeShutdownHook(Runtime.java:245)
at com.cloud.agent.Agent$PostCertificateRenewalTask.runInContext(Agent.java:1268)
at org.apache.cloudstack.managed.context.ManagedContextTimerTask$1.runInContext(ManagedContextTimerTask.java:30)
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.managed.context.ManagedContextTimerTask.run(ManagedContextTimerTask.java:32)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
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-07-28 08:13:58,190 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Agent started
2025-07-28 08:13:58,192 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Implementation Version is 4.20.1.0
2025-07-28 08:13:58,193 INFO [cloud.agent.AgentShell] (main:[]) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties
2025-07-28 08:13:58,213 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to using properties file for storage
2025-07-28 08:13:58,214 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to the constant time backoff algorithm
2025-07-28 08:13:58,229 INFO [cloud.utils.LogUtils] (main:[]) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml
2025-07-28 08:13:58,229 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Using default Java settings for IPv6 preference for agent connection
2025-07-28 08:13:58,270 INFO [cloud.agent.Agent] (main:[]) (logid:) Initialising agent [id: 10, uuid: aeb26945-0f0d-4fdb-8961-3cd755c35501, name: cloudstack2]
2025-07-28 08:13:58,275 ERROR [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) uefi properties file not found due to: Unable to find file uefi.properties.
2025-07-28 08:13:58,293 INFO [kvm.resource.LibvirtConnection] (main:[]) (logid:) No existing libvirtd connection found. Opening a new one
2025-07-28 08:13:58,457 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) IO uring driver for Qemu: enabled
2025-07-28 08:13:58,528 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.LinstorStorageAdaptor
2025-07-28 08:13:58,529 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.StorPoolStorageAdaptor
2025-07-28 08:13:58,530 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.ScaleIOStorageAdaptor
2025-07-28 08:13:58,530 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.IscsiAdmStorageAdaptor
2025-07-28 08:13:58,531 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.ManagedNfsStorageAdaptor
2025-07-28 08:13:58,537 INFO [kvm.storage.FiberChannelAdapter] (main:[]) (logid:) Loaded FiberChannelAdapter for StorageLayer
2025-07-28 08:13:58,538 INFO [kvm.storage.FiberChannelAdapter] (main:[]) (logid:) Loaded FiberChannelAdapter for StorageLayer on host [cloudstack2]
2025-07-28 08:13:58,538 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.FiberChannelAdapter
2025-07-28 08:13:58,538 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver.
2025-07-28 08:13:58,642 INFO [cloud.serializer.GsonHelper] (main:[]) (logid:) Default Builder inited.
2025-07-28 08:13:58,643 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) iscsi session clean up is disabled
2025-07-28 08:13:58,644 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) Skipping the memory balloon stats period setting, since there are no VMs (active Libvirt domains) on this host.
2025-07-28 08:13:58,644 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) The [vm.memballoon.stats.period] property is set to '0', this prevents memory statistics from being displayed correctly. Adjust (increase) the value of this parameter to correct this.
2025-07-28 08:13:58,646 INFO [cloud.agent.Agent] (main:[]) (logid:) Agent [id = 10, uuid = aeb26945-0f0d-4fdb-8961-3cd755c35501, name = cloudstack2, type = LibvirtComputingResource, zone = 1, pod = 1, workers = 5, port = 8250] with host = 192.168.10.221, local id = 1
2025-07-28 08:13:58,647 INFO [utils.nio.NioClient] (main:[]) (logid:) Connecting to 192.168.10.221:8250
2025-07-28 08:13:58,651 INFO [utils.nio.NioClient] (main:[]) (logid:) Connected to 192.168.10.221:8250
2025-07-28 08:13:58,652 INFO [utils.nio.Link] (main:[]) (logid:) Conf file found: /etc/cloudstack/agent/agent.properties
2025-07-28 08:13:58,803 INFO [utils.nio.NioClient] (main:[]) (logid:) SSL: Handshake done
2025-07-28 08:13:58,812 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching CPU speed from command "lscpu".
2025-07-28 08:13:58,820 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:3748)
at com.cloud.agent.Agent.sendStartup(Agent.java:542)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1213)
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-07-28 08:13:58,829 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 [4367] for CPU speed.
2025-07-28 08:13:58,829 INFO [utils.linux.KVMHostInfo] (Agent-Handler-1:[]) (logid:) Fetching host CPU arch
2025-07-28 08:13:58,836 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Host uses control group [cgroup2fs].
2025-07-28 08:13:58,837 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Calculating the max shares of the host.
2025-07-28 08:13:58,837 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) The max shares of the host is [104808].
2025-07-28 08:13:58,868 WARN [utils.script.Script] (Agent-Handler-1:[]) (logid:) Execution of process [15770] for command [/bin/bash -c virt-v2v --version ] failed.
2025-07-28 08:13:58,868 WARN [utils.script.Script] (Agent-Handler-1:[]) (logid:) Process [15770] for command [/bin/bash -c virt-v2v --version ] encountered the error: [127].
2025-07-28 08:13:58,877 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Attempting to create storage pool effe48a3-ce83-47be-999b-607501e7851e (Filesystem) in libvirt
2025-07-28 08:13:58,878 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Found existing defined storage pool effe48a3-ce83-47be-999b-607501e7851e, using it.
2025-07-28 08:13:58,878 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:[]) (logid:) Trying to fetch storage pool effe48a3-ce83-47be-999b-607501e7851e from libvirt
2025-07-28 08:13:59,929 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Process agent startup answer, agent [id: 0, uuid: , name: ] connected to the server
2025-07-28 08:13:59,938 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Startup Response Received: agent [id: 0, uuid: , name: ]
2025-07-28 08:14:00,132 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-4:[]) (logid:) Attempting to create storage pool 9b0a80be-9a4c-3f26-ad9b-7a48a7d37eeb (NetworkFilesystem) in libvirt
2025-07-28 08:14:00,133 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-4:[]) (logid:) Found existing defined storage pool 9b0a80be-9a4c-3f26-ad9b-7a48a7d37eeb, using it.
2025-07-28 08:14:00,137 INFO [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-4:[]) (logid:) Trying to fetch storage pool 9b0a80be-9a4c-3f26-ad9b-7a48a7d37eeb from libvirt
2025-07-28 08:14:00,315 INFO [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Processing agent ready command, agent id = 10, uuid = aeb26945-0f0d-4fdb-8961-3cd755c35501, name = cloudstack2
2025-07-28 08:14:00,317 INFO [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:) Ready command is processed for agent [id: 10, uuid: aeb26945-0f0d-4fdb-8961-3cd755c35501, name: cloudstack2]
2025-07-28 08:14:00,449 INFO [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Processing agent ready command, agent id = 10, uuid = aeb26945-0f0d-4fdb-8961-3cd755c35501, name = cloudstack2
2025-07-28 08:14:00,458 ERROR [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Unexpected arch null, expected x86_64
2025-07-28 08:14:00,459 INFO [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:) Processed new management server list: 192.168.10.221@static
2025-07-28 08:14:00,459 INFO [cloud.agent.Agent] (A

[nlindblo]

I have now done a fresh install of 4.20.1 using Ubuntu 24.04 with a new database, but I am still experiencing the same issue with not being able to provision the host security keys, due to libvirtd restart is failing. I can execute sudo service libvirtd restart manually without problem. Is this a known issue or am I missing some configuration ? Some help would be appreciated

3fa4b7a550, name: cloudstack2]
2025-07-29 10:57:51,199 INFO [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Restarting libvirt after certificate provisioning/renewal
2025-07-29 10:57:51,213 INFO [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Stopping the agent: Reason = sig.kill
2025-07-29 10:57:51,214 WARN [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Execution of process [11120] for command [sudo service libvirtd restart ] failed.
2025-07-29 10:57:51,214 WARN [resource.wrapper.LibvirtPostCertificateRenewalCommandWrapper] (CertificateRenewalTask-1:[]) (logid:) Process [11120] for command [sudo service libvirtd restart ] encountered the error: [].
2025-07-29 10:57:51,216 WARN [cloud.agent.Agent] (CertificateRenewalTask-1:[]) (logid:) Failed to execute post certificate renewal command: java.lang.IllegalStateException: Shutdown in progress
at java.base/java.lang.ApplicationShutdownHooks.remove(ApplicationShutdownHooks.java:82)
at java.base/java.lang.Runtime.removeShutdownHook(Runtime.java:245)
at com.cloud.agent.Agent$PostCertificateRenewalTask.runInContext(Agent.java:1268)
at org.apache.cloudstack.managed.context.ManagedContextTimerTask$1.runInContext(ManagedContextTimerTask.java:30)
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.managed.context.ManagedContextTimerTask.run(ManagedContextTimerTask.java:32)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
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)

[DaanHoogland]

@nlindblo , I’ve been looking at your question for a week and I think you hit a bug but don’t fully understand it yet, so I can’t be sure. 4.20.1 is widly used by now and no one else talked about it so there must be a catalysing circumstance you have that makes you hit this.

the last stack trace is because lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:digit:]].[[:digit:]]+GHz' | sed 's/GHz//g'”; does not yield results. Can you try that manually?

[nlindblo]

I managed to get past this by editing

/etc/default/libvirtd

and appended

LIBVIRTD_ARGS="--listen"

(though the documentation says to uncomment it)

After this, the hosts shows as up. I have another instance running 4.20.1 on Ubuntu 24.04 but has been upgraded in stages since 4.18 (I think), and I noticed that it had the same setting. I may have done other changes as well not recorded while I was trying to bypass the libvirtd restart, but I think the certificates were always provisioned and it was just the restart missing, the LIBVIRTD_ARGS="--listen" was the last change the changed the status to secure.

Heres the manual lscpu output

root@cloudstack2:~# lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:digit:]].[[:digit:]]+GHz' | sed 's/GHz//g'”;
sed: -e expression #1, char 9: unknown option to `s'
root@cloudstack2:~# 

[DaanHoogland]

Heres the manual lscpu output

root@cloudstack2:~# lscpu | grep -i 'Model name' | head -n 1 | egrep -o '[[:digit:]].[[:digit:]]+GHz' | sed 's/GHz//g'”;
sed: -e expression #1, char 9: unknown option to `s'
root@cloudstack2:~# 

ok, that explains the stack trace. I guess sed on ubuntu doesn’t adhere to posix?? I do remember there are some code changes concerning the lscpu query in a PR. They may work around this. cc @weizhouapache , you know?

Great that you got around the problem. Any doc changes you would put in, @nlindblo ?

[nlindblo]

Looking at the documentation again now, it is actually correct, it does say "uncomment LIBVIRTD_ARGS="--listen", for some reason I read it as comment out and when I opened the file initially, I just saw that the line wasn't there, I assumed all was good. So it appears this was user error from my side

[DaanHoogland]

ok, so maybe a smal reformulation of the doc text is in order?

uncomment the line `LIBVIRTD_ARGS="—listen”` if it is there. If not, make sure to add it.

?