virt-v2v conflicts with cloudstack-agent in version 4.21

[mahdiadnan]

problem

After upgrading the clustering to version 4.21 from version 4.20, following the document https://docs.cloudstack.apache.org/en/latest/upgrading/upgrade/upgrade-4.20.html
cloudstack-agent failed to start with sig=kill

Logs from agent.log

2025-09-10 14:21:01,960 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Agent started
2025-09-10 14:21:01,963 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Implementation Version is 4.21.0.0
2025-09-10 14:21:01,964 INFO [cloud.agent.AgentShell] (main:[]) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties
2025-09-10 14:21:01,994 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to using properties file for storage
2025-09-10 14:21:01,995 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to the constant time backoff algorithm
2025-09-10 14:21:02,021 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Using default Java settings for IPv6 preference for agent connection
2025-09-10 14:21:02,088 INFO [cloud.agent.Agent] (main:[]) (logid:) Initialising agent [id: 34, uuid: b3e4fd47-bc22-4feb-9673-c35dc06727db, name: xxxx]
2025-09-10 14:21:02,094 ERROR [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) uefi properties file not found due to: Unable to find file uefi.properties.
2025-09-10 14:21:02,270 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) IO uring driver for Qemu: enabled
2025-09-10 14:21:02,349 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.LinstorStorageAdaptor
2025-09-10 14:21:02,350 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.StorPoolStorageAdaptor
2025-09-10 14:21:02,351 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.ScaleIOStorageAdaptor
2025-09-10 14:21:02,352 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.IscsiAdmStorageAdaptor
2025-09-10 14:21:02,352 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.ManagedNfsStorageAdaptor
2025-09-10 14:21:02,359 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.FiberChannelAdapter
2025-09-10 14:21:02,359 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver.
2025-09-10 14:21:02,490 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) iscsi session clean up is disabled
2025-09-10 14:21:02,493 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-09-10 14:21:02,493 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-09-10 14:21:02,495 INFO [cloud.agent.Agent] (main:[]) (logid:) Agent [id = 34, uuid = b3e4fd47-bc22-4feb-9673-c35dc06727db, name = xxx, type = LibvirtComputingResource, zone = 2, pod = 2, workers = 5, port = 8250] with host = xxx, local id = 1
2025-09-10 14:21:02,836 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Host uses control group [cgroup2fs].
2025-09-10 14:21:02,836 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) Calculating the max shares of the host.
2025-09-10 14:21:02,837 INFO [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:[]) (logid:) The max shares of the host is [200000].
2025-09-10 14:21:04,134 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Process agent startup answer, agent [id: 0, uuid: , name: ] connected to the server
2025-09-10 14:21:04,135 INFO [cloud.agent.Agent] (Agent-Handler-2:[]) (logid:) Startup Response Received: agent [id: 0, uuid: , name: ]
2025-09-10 14:21:04,526 INFO [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:5618826b) Processing agent ready command, agent id = 34, uuid = b3e4fd47-bc22-4feb-9673-c35dc06727db, name = xxx
2025-09-10 14:21:04,527 INFO [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:5618826b) Ready command is processed for agent [id: 34, uuid: b3e4fd47-bc22-4feb-9673-c35dc06727db, name: xxx]
2025-09-10 14:21:05,169 INFO [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Stopping the agent: Reason = sig.kill

versions

From v 4.20.1 to 4.21
OS is Alma Linux 9.6 <kernel 5.14.0-570.37.1.el9_6.x86_64>
virt-v2v version 1:2.7.1-10.el9_6

The steps to reproduce the bug

1. Update the cloudstack-agent using dnf
2. Restart the cloudstack-agent.service using systemctl
3. Agent logs showing the service was getting killed with sig=kill
   ...

What to do about it?

After removing virt-v2v package, the agent starts without issues.

[boring-cyborg]

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

[nvazquez]

Hi @mahdiadnan, thanks for reporting the issue. For troubleshooting purposes, could you increase the agent logs level to DEBUG (sed -i 's/INFO/DEBUG/g' /etc/cloudstack/agent/log4j-cloud.xml) and retry after installing virt-v2v? This would be useful to detect what is the failure causing the agent to be killed

[mahdiadnan]

Hi @nvazquez Here's the logs after installing virt-v2v and restarting the agent with DEBUG enabled. agent.log

[nvazquez]

Thanks @mahdiadnan - for quick reference the error comes from an evaluation of uefiEnabled not the virt-v2v binary per se.

025-09-10 16:22:32,576 DEBUG [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Executing command [/bin/bash -c virt-v2v --version | awk '{print $2}' ].
2025-09-10 16:22:32,597 DEBUG [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Successfully executed process [1344008] for command [/bin/bash -c virt-v2v --version | awk '{print $2}' ].
2025-09-10 16:22:32,598 DEBUG [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Executing command [/bin/bash -c ovftool --version ].
2025-09-10 16:22:32,601 WARN  [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Execution of process [1344014] for command [/bin/bash -c ovftool --version ] failed.
2025-09-10 16:22:32,601 DEBUG [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Exit value of process [1344014] for command [/bin/bash -c ovftool --version ] is [127].
2025-09-10 16:22:32,601 WARN  [utils.script.Script] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Process [1344014] for command [/bin/bash -c ovftool --version ] encountered the error: [127].
2025-09-10 16:22:32,602 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-4:[]) (logid:cd17e03c) Seq 32-1666331862127083527:  { Ans: , MgmtId: 90520743250181, via: 32, Ver: v1, Flags: 110, [{"com.cloud.agent.api.ReadyAnswer":{"detailsMap":{"host.virtv2v.version":"2.7.1rhel=9"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2025-09-10 16:22:32,648 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:cd17e03c) Request:Seq -1--1:  { Cmd , MgmtId: -1, via: -1, Ver: v1, Flags: 111, [{"com.cloud.agent.api.ReadyCommand":{"_details":"java.lang.NullPointerException: Cannot invoke "String.equals(Object)" because "uefiEnabled" is null","wait":"0","bypassHostMaintenance":"false"}}] }
2025-09-10 16:22:32,648 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:cd17e03c) Processing command: com.cloud.agent.api.ReadyCommand
2025-09-10 16:22:32,648 DEBUG [cloud.agent.Agent] (AgentRequest-Handler-2:[]) (logid:cd17e03c) Not ready to connect to mgt server: java.lang.NullPointerException: Cannot invoke "String.equals(Object)" because "uefiEnabled" is null
2025-09-10 16:22:32,648 INFO  [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Stopping the agent: Reason = sig.kill
2025-09-10 16:22:32,649 DEBUG [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Sending shutdown to management server
2025-09-10 16:22:32,696 DEBUG [utils.nio.NioClient] (Agent-NioConnectionHandler-1:[]) (logid:) Location 1: Socket Socket[addr=/10.4.19.4,port=8250,localport=54680] closed on read.  Probably -1 returned: Connection closed with -1 on reading size.
2025-09-10 16:22:32,697 DEBUG [utils.nio.NioClient] (Agent-NioConnectionHandler-1:[]) (logid:) Closing socket Socket[addr=/10.4.19.4,port=8250,localport=54680]

Can you check the host details for this host on the host_details table with host_id = <internal ID of the host> for a setting with name host.uefi.enable? It seems like it doesn't exist and the code is expecting it, which causes the NPE.

As a test can you try adding a setting on host_details in which host_id = <internal ID of the host>, name = 'host.uefi.enable' and value = 'false'?

[weizhouapache]

this seems to be a regression of #11019

@nvazquez
can you create a fix ?

[nvazquez]

Sure @weizhouapache - I have created PR #11610

[weizhouapache]

fixed by #11610, thanks @nvazquez

[Shivamkashyap08]

@weizhouapache @nvazquez We have added the above-mentioned entry in the DB, but the cloudstack agent upgrade is still stuck in the same place.

Attaching the DB Entry and logs for the reference -

2025-10-16 13:45:50,260 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:4ae59f86) Trying to fetch storage pool d54f4382-5db9-31f6-9428-5bf073171a1a from libvirt
2025-10-16 13:45:50,369 INFO [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:4ae59f86) Asking libvirt to refresh storage pool d54f4382-5db9-31f6-9428-5bf073171a1a
2025-10-16 13:46:28,169 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
2025-10-16 13:47:55,634 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Agent started
2025-10-16 13:47:55,641 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Implementation Version is 4.20.1.0
2025-10-16 13:47:55,643 INFO [cloud.agent.AgentShell] (main:[]) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties
2025-10-16 13:47:55,691 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to using properties file for storage
2025-10-16 13:47:55,692 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Defaulting to the constant time backoff algorithm
2025-10-16 13:47:55,727 INFO [cloud.utils.LogUtils] (main:[]) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml
2025-10-16 13:47:55,727 INFO [cloud.agent.AgentShell] (main:[]) (logid:) Using default Java settings for IPv6 preference for agent connection
2025-10-16 13:47:55,782 INFO [cloud.agent.Agent] (main:[]) (logid:) Initialising agent [id: 39, uuid: null, name: null]
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) uefi.properties file found at /etc/cloudstack/agent/uefi.properties
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) guest.nvram.template.legacy = null
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) guest.loader.legacy = null
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) guest.nvram.template.secure = null
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) guest.loader.secure =null
2025-10-16 13:47:55,788 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) guest.nvram.path = null
2025-10-16 13:47:55,818 INFO [kvm.resource.LibvirtConnection] (main:[]) (logid:) No existing libvirtd connection found. Opening a new one
2025-10-16 13:47:56,700 INFO [kvm.resource.LibvirtComputingResource] (main:[]) (logid:) IO uring driver for Qemu: enabled
2025-10-16 13:47:56,791 INFO [kvm.storage.KVMStoragePoolManager] (main:[]) (logid:) Adding storage adaptor for com.cloud.hypervisor.kvm.storage.LinstorStorageAdaptor

[nvazquez]

Hi @Shivamkashyap08 can you share the full agent logs with DEBUG level enabled for this new failure?