CloudStack fails to start more VMs

[akrasnov-drv]

Hi,

I'm struggling to make CloudStack 4.20.0.0 properly start KVM VMs on Ubuntu 22.

We have isolated network over VLAN.
CloudStack manages to start single VM and to add several more. But when I ask to start more (e.g. 10-30), Cloudstack starts behaving weird.
New VMs produce different errors, then Cloudstack becomes slow, does not clean resources, and at the end stays with number of VMs in Starting state.

I have 5 KVM servers connected, each able to handle 30 VMs alone (in KVM without Cloudstack). VMs use local server storage. I do not see any resource problem.
I tried to debug the issue, and looks like virtual router stops working properly. I found in its log that it restarts managing script at some point, still part of VMs do not get proper network config. Static NAT enable also returns errors.
Error while enabling static nat. Ip Id: 14
Expunge for VMs then also hangs.
In addition sometimes I see KVM hosts stop communicating with management, and stop writing to their local logs.

To recover I need to restart management, delete virtual router and clean stuck resources, sometimes directly in mysql db. Agent restart is also sometimes needed.
Any help to understand and fix the problem is highly appreciated.
I'll provide logs or other info on request.

Thanks,
Alex.

[akrasnov-drv]

libvirt version - 8.0.0-1ubuntu7.10
I see in libvirt log the following messages that may be relevant (at least they started approximately at time of problem start)

Failed to connect socket to '/var/run/libvirt/virtlxcd-sock': No such file or directory
End of file while reading data: Input/output error

Also I see repeating CloudStack agent errors when the problem starts (at least in some of hosts)

2025-01-14 13:51:37,619 WARN  [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:[]) (logid:60e624f6) Can not find a connection for Instance i-2-2157-VM. Assuming the default connection.
2025-01-14 13:51:37,774 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:[]) (logid:60e624f6) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied.
2025-01-14 13:51:37,774 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-2:[]) (logid:60e624f6) Groovy scripting engine is not initialized. Data transformation skipped.
2025-01-14 13:52:25,578 INFO  [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:[]) (logid:f8728dc0) No existing libvirtd connection found. Opening a new one
2025-01-14 13:52:25,579 WARN  [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:[]) (logid:f8728dc0) Can not find a connection for Instance i-2-2160-VM. Assuming the default connection.
2025-01-14 13:52:25,751 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:[]) (logid:f8728dc0) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied.
2025-01-14 13:52:25,751 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:[]) (logid:f8728dc0) Groovy scripting engine is not initialized. Data transformation skipped.
2025-01-14 13:53:35,686 INFO  [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:[]) (logid:cda7a48e) No existing libvirtd connection found. Opening a new one

After libvirt restart, CloudStack agent managed to connect to libvirt, and logs started looking regular.
Seems that's the issue. But we had no issue with our KVM hosts without CloudStack.
Please advise.

[pavanaravapalli]

referred to the link for libvirtd dependency packages along with configs in case of any permission issue.

However if you installed all libvirtd dependencies followed by restarted libvirtd daemon and if it does not show up any error logs, it's good.

Can you try restarting VM's from cloud stack and observe the logs( management-server, agent, libvirtd ).
I hope, restarting VM from Cloud Stack should fixe QEMU guest agent is not connected, as this time libvirtd has no errors.

[akrasnov-drv]

No, it has not solved the issue.
I'm not sure it's root cause, but at least it breaks VMs communications.
Each time when I face this problem, VR is not working properly. One of indications on how I see it - VMs stop getting proper name from VR metadata server.
Another indication - I can't ssh to VMs that are up (even though I could before. Likely also because of VR.

[pavanaravapalli]

Considering the comment, i am suggesting the below for trouble shooting.
If virt-manager GUI is available for KVM host try to get terminal access and see if the network traffic is functioning normal and all network configured properly.

try below alternative approach if virt-manager not available.

get passwd tag from host for the guest vm using the command virsh dumpxml <domain id> | grep passwd ' get the vnc display details from host using the command virsh vncdisplay `

use tiger vnc viewer application and supply above information for getting Guest VM terminal access.

[akrasnov-drv]

I have console access from virsh, np.
And yes, there are problems with VM networking (see below) - part of VMs does not get IP from dnsmasq.
Also failures with static nat.
Though now at list VR looks functioning.

[akrasnov-drv]

Ouch, VR stopped functioning. I'll add more data to the end of thread.

[akrasnov-drv]

After libvirtd restart on all hosts, CloudStack managed to get rid of VMs in Starting state. Though many in Expunging state are still there and are not removed. Refresh of Instances page is a lost slower than before, takes some 12-15 seconds and shows just 49 VMs in Expunging state.

[akrasnov-drv]

If anybody successfully runs CloudStack on Ubuntu, please let me know your versions (Ubuntu, kernel, CloudStack, libvirt, etc.)
I suspect there is some issue between CloudStack and libvirt 8 in Ubuntu 22.

[weizhouapache]

@akrasnov-drv
can you create a L2 network and deploy multiple vms on it in parallel?

[weizhouapache]

@akrasnov-drv
can you test with L2 network which does not have a VR ?

[akrasnov-drv]

I see your point. Unfortunately I currently have no infra for L2, I mean dhcp, router, etc.
But I could test pure VM start, to see if VMs are created and started.
I used cloudstack cli to do it. And after some maybe 10 executions I started getting TimeoutError on connecting to api. CloudStack UI also became unresponsive (maybe I need to properly clean the env, restart agents and server, and try again).
Nevertheless all 120 VMs I requested were created in CloudStack, 9 finished with Error Error while deploying Vm, the rest started.

Also I did another test, I executed start of 120 VMs in parallel in isolated network but without additional user-data or additional network config (we usually use static nat).
In this case CloudStack managed to start about 80 VM, several more failed with Error, others stayed in Starting state (maybe they'll do finally). After start, most of VMs got proper hostname from VR, but part stayed with localhost.
In any case it's a lot better then when we used user-data and static nat.
And now I see that primary VR is in Unknown state. Nevertheless, the backup one does not take primary role, and I'm still able to ssh to the "primary" one.
Also I see again that the host where VR runs again has log "frozen"
I executed VM start at about 15:30, the log was last updated at 15:55, and the last 2 lines are:

2025-01-15 15:33:15,742 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:[]) (logid:37db33e3) Attempting to create volume c8cbfca6-ea45-4698-8221-a578a7b8576d (Filesystem) in pool a0bdff3a-8016-4760-8cd4-eaeb5809ddc7 with size (6.00 GB) 6442450944
2025-01-15 15:55:31,242 WARN  [kvm.resource.LibvirtComputingResource] (Script-5:[]) (logid:) Interrupting script.

btw, this host (where VR runs) managed to start just 2 VMs from that 120.

I restarted libvirtd, and as before agent immediately returned to life and wrote this to its log

2025-01-15 16:13:49,367 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:[]) (logid:bce375d5) Process [760381] for command [/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.206.35 vm_metadata.json.479c1074-4d9c-4bff-b06a-0fb61a9125ed ] timed out. Output is [java.io.IOException: Stream clos
ed
        at java.base/java.io.BufferedReader.ensureOpen(BufferedReader.java:123)
        at java.base/java.io.BufferedReader.ready(BufferedReader.java:444)
        at com.cloud.utils.script.OutputInterpreter$TimedOutLogger.interpret(OutputInterpreter.java:72)
        at com.cloud.utils.script.Script$Task.run(Script.java:490)
        at com.cloud.utils.script.Script.execute(Script.java:298)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeInVR(LibvirtComputingResource.java:553)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfigToVR(VirtualRoutingResource.java:303)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfig(VirtualRoutingResource.java:318)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.executeRequest(VirtualRoutingResource.java:165)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:35)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:29)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1945)
        at com.cloud.agent.Agent.processRequest(Agent.java:686)
        at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1109)
        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-01-15 16:13:49,373 WARN  [cloud.agent.Agent] (agentRequest-Handler-5:[]) (logid:bce375d5) Unable to send response: Seq 4-6283647380088688564:  { Ans: , MgmtId: 108380656826451, via: 4, Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: Creating file in VR, with ip: 169.254.206.35, file: vm_password.json.b
67bbb7a-3116-4255-bf06-a198e3faa3b9","null - success: Invalid unit name "[email protected],10.10.245.127" escaped as "[email protected]\x2c10.10.245.127" (maybe you should use systemd-escape?).
"],"result":"true","wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: Creating file in VR, with ip: 169.254.206.35, file: vm_metadata.json.479c1074-4d9c-4bff-b06a-0fb61a9125ed","null - failed: timeout"],"result":"false","wait":"0","bypassHostMaintenance":"false"}}] }
2025-01-15 16:13:52,803 INFO  [cloud.agent.AgentShell] (main:[]) (logid:) Agent started
2025-01-15 16:13:52,816 INFO  [cloud.agent.AgentShell] (main:[]) (logid:) Implementation Version is 4.20.0.0

then returned to normal.
2 of start VM tasks cloudstack deployVirtualMachine finished with error 530 just after that.
And only then backup VR got primary function.
After the above I managed to start additional VM, and it got proper name from VR.

To summon, looks like under load some script running in libvirt makes the agent unusable.
I'd think maybe about /usr/share/cloudstack-agent/lib/libvirtqemuhook that is placed to /etc/libvirt/hooks/qemu, but appeared it exists on all my hosts except the one where VR was stuck.

[weizhouapache]

I wonder if there was an issue with the storage.
if you have other vms (systemvm, user vms or vrs), can you check if there are some logs in the time period ?

[akrasnov-drv]

All my VMs use local storage, and actually system ones too, even though I have NFS for both primary and secondary.

[akrasnov-drv]

I checked secondary storage VM, it's up for several days, and there is something strange indeed - some lines are not full, looks like several records are missing, e.g.

2025-01-15T15:23:13,339 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:24:13,681 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-4:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:25:14,071 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:26:14,489 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
entRequest-Handler-2:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:28:15,444 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:29:15,980 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-4:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T15:30:16,532 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
...
2025-01-15T16:28:57,071 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T16:29:57,623 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-4:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
entRequest-Handler-1:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T16:32:26,723 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-5:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T16:33:27,268 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-2:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3
2025-01-15T16:34:27,815 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-3:[]) Determined host 10.10.67.3 corresponds to IP 10.10.67.3

It's even more strange that this VM runs on the same host where NFS share is.

[akrasnov-drv]

One more peace of info
I see CloudStack agent stuck in 1 of my hosts. The last message in its log is
2025-01-15 09:21:59,544 WARN [kvm.resource.LibvirtComputingResource] (Script-10:[]) (logid:) Interrupting script.
Then CloudStack stops processing expunge, for all hosts.
After restarting libvirtd, I've got this addition to agent log (so agent was not really stuck, but rather waiting)

2025-01-15 11:03:07,848 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:[]) (logid:bba1b4b7) Process [168078] for command [/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.130.62 vm_metadata.json.4846fe83-e605-4882-a203-45ef732d05aa ] timed out. Output is [java.io.IOException: Stream closed
        at java.base/java.io.BufferedReader.ensureOpen(BufferedReader.java:123)
        at java.base/java.io.BufferedReader.ready(BufferedReader.java:444)
        at com.cloud.utils.script.OutputInterpreter$TimedOutLogger.interpret(OutputInterpreter.java:72)
        at com.cloud.utils.script.Script$Task.run(Script.java:490)
        at com.cloud.utils.script.Script.execute(Script.java:298)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeInVR(LibvirtComputingResource.java:553)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfigToVR(VirtualRoutingResource.java:303)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfig(VirtualRoutingResource.java:318)
        at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.executeRequest(VirtualRoutingResource.java:165)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:35)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:29)
        at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
        at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1945)
        at com.cloud.agent.Agent.processRequest(Agent.java:686)
        at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1109)
        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-01-15 11:03:07,849 INFO  [cloud.agent.Agent] (AgentShutdownThread:[]) (logid:) Stopping the agent: Reason = sig.kill : Detail =
2025-01-15 11:03:10,743 INFO  [cloud.agent.AgentShell] (main:[]) (logid:) Agent started

Then most of VMs were expunged.

[akrasnov-drv]

As I wrote above, while Primary VR was in unknown redundancy, and VMs did not get hostname from metadata server, I was still able to ssh to that VR.
I'll upload cloud.log as soon as VR misbehaves again.

[akrasnov-drv]

I cleaned the env, restarted all components, and re-executed tests. After I recently recreated network with own offering that has VR HA and 65K bandwidth limit, and also set VR CPU to 2Ghz, the situation looks better. Now the main problems I see:

• part of VMs does not get IP from dnsmasq
• numerous STATICNAT.ENABLE errors
  I tried executing dhclient there, and got no IP either. Expectedly, reboot did not help. But if I execute VM reinstall from UI, it sometimes fixes the issue of missing IP.
  I'm attaching cloud.log (it's packed as originally it's 180Mb) from VR and also dnsmasq.log
  I found 59 hosts mentioned in dnsmasq.log at the same time there were more than 150 VMs created, about 80 running and destroyed, and the rest stayed in Starting state (console is not available yet after 3-30 min)
  cloud.log.1.gz
  cloud.log.gz
  dnsmasq.log
  .

[akrasnov-drv]

Just after I posted logs I found VR in unknown state again.
The one expected to be primary has cloud.log of size 0.
I'm attaching what's missing from the attached above
cloud.log.1_new.gz
please notice there:

2025-01-16 16:36:06,935 INFO     Setting router to fault
...
2025-01-16 16:44:18,734 INFO     Route state => BACKUP
2025-01-16 16:44:18,735 INFO     Router switched to backup mode

UI shows it as Unknown, but the 2nd one is still in backup state

[akrasnov-drv]

Just checked backup VR, it also has cloud.log of 0
and the last lines in the rotated log are

2025-01-16 16:34:04,977 INFO     Copied /opt/cloud/templates/conntrackd.conf.templ.bkp to /opt/cloud/templates/conntrackd.conf.templ
2025-01-16 16:34:04,977 INFO     Executing: rm -rf /opt/cloud/templates/conntrackd.conf.templ.bkp
2025-01-16 16:34:04,979 INFO     Nothing to commit. The /etc/cron.d/heartbeat file did not change
2025-01-16 16:34:04,979 INFO     Executing: ps aux

now it's 17:27

[akrasnov-drv]

Finally, backup VR is promoted to primary (17:30), but its cloud.log stays empty so far.

[PPisz]

Similar issue afer upgrade to 4.20 (Ubuntu 22), but I couldn't run any VM (unfortunately, we had to withdraw the upgrade, I cannot provide more detailed information) agent.log:

``2025-01-10 12:28:30,179 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:fb2d5891) Exit value of process [3708958] for command [/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.93.185 vm_dhcp_entry.json.82a5c90f-4744-4bba-abe0-df28dfaa3c0c ] is [1].
2025-01-10 12:28:30,180 WARN [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:fb2d5891) Exception [Stream closed] occurred when attempting to run command [/usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.93.185 vm_dhcp_entry.json.82a5c90f-4744-4bba-abe0-df28dfaa3c0c ].
java.io.IOException: Stream closed
at java.base/java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:168)
at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:281)
at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:324)
at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:189)
at java.base/java.io.InputStreamReader.read(InputStreamReader.java:177)
at java.base/java.io.BufferedReader.fill(BufferedReader.java:162)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:329)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:396)
at com.cloud.utils.script.OutputInterpreter.processError(OutputInterpreter.java:38)
at com.cloud.utils.script.Script.execute(Script.java:313)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeInVR(LibvirtComputingResource.java:546)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfigToVR(VirtualRoutingResource.java:302)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfig(VirtualRoutingResource.java:317)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.executeRequest(VirtualRoutingResource.java:164)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:35)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:29)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1929)
at com.cloud.agent.Agent.processRequest(Agent.java:683)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1106)
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-01-10 12:28:30,181 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:fb2d5891) Executing script in VR: update_config.py
2025-01-10 12:28:30,181 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-1:null) (logid:fb2d5891) Processing ScriptConfigItem, executing update_config.py vm_dhcp_entry.json.82a5c90f-4744-4bba-abe0-df28dfaa3c0c took 363ms
2025-01-10 12:28:30,190 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:fb2d5891) Seq 5-2621376458106339390: { Ans: , MgmtId: 222320990092816, via: 5, Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: Creating file in VR, with ip: 169.254.93.185, file: vm_dhcp_entry.json.82a5c90f-4744-4bba-abe0-df28dfaa3c0c","null - failed: java.io.IOException: Stream closed
at java.base/java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:168)
at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:281)
at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:324)
at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:189)
at java.base/java.io.InputStreamReader.read(InputStreamReader.java:177)
at java.base/java.io.BufferedReader.fill(BufferedReader.java:162)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:329)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:396)
at java.base/java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:168)
at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:281)
at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:324)
at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:189)
at java.base/java.io.InputStreamReader.read(InputStreamReader.java:177)
at java.base/java.io.BufferedReader.fill(BufferedReader.java:162)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:329)
at java.base/java.io.BufferedReader.readLine(BufferedReader.java:396)
at com.cloud.utils.script.OutputInterpreter.processError(OutputInterpreter.java:38)
at com.cloud.utils.script.Script.execute(Script.java:313)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeInVR(LibvirtComputingResource.java:546)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfigToVR(VirtualRoutingResource.java:302)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.applyConfig(VirtualRoutingResource.java:317)
at com.cloud.agent.resource.virtualnetwork.VirtualRoutingResource.executeRequest(VirtualRoutingResource.java:164)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:35)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtNetworkElementCommandWrapper.execute(LibvirtNetworkElementCommandWrapper.java:29)
at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:78)
at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1929)
at com.cloud.agent.Agent.processRequest(Agent.java:683)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1106)
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)
"],"result":"false","wait":"0","bypassHostMaintenance":"false"}}] }
2025-01-10 12:28:31,311 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing command [/usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms ].
2025-01-10 12:28:31,429 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Successfully executed process [3708972] for command [/usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms ].
2025-01-10 12:28:31,430 DEBUG [agent.properties.AgentPropertiesFileHandler] (UgentTask-5:null) (logid:) Property [hypervisor.uri] has empty or null value. Using default value [null].
2025-01-10 12:28:31,430 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system`

and managemen.log:

2025-01-10 12:28:30,981 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:[ctx-6edbbbab, job-69848/job-69851, ctx-ce398d8d]) (logid:fb2d5891) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":557,"instanceName":"i-39-557-VM","type":"User","uuid":"90f85f42-ed81-42e3-953f-20edba0b1304"}Scope=interface com.cloud.dc.DataCenter; id=1 2025-01-10 12:28:30,981 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:[ctx-6edbbbab, job-69848/job-69851, ctx-ce398d8d]) (logid:fb2d5891) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":557,"instanceName":"i-39-557-VM","type":"User","uuid":"90f85f42-ed81-42e3-953f-20edba0b1304"}Scope=interface com.cloud.dc.DataCenter; id=1 2025-01-10 12:28:30,981 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:[ctx-6edbbbab, job-69848/job-69851]) (logid:fb2d5891) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 557, job origin: 69848 2025-01-10 12:28:30,981 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:[ctx-6edbbbab, job-69848/job-69851]) (logid:fb2d5891) Unable to complete AsyncJobVO: {id:69851, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAACLXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHBw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 222320990092816, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Jan 10 12:26:04 CET 2025, removed: null}, job origin: 69848 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":557,"instanceName":"i-39-557-VM","type":"User","uuid":"90f85f42-ed81-42e3-953f-20edba0b1304"}Scope=interface com.cloud.dc.DataCenter; id=1 at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1237) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5467) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:569) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:106) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5591) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:99) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:652) 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.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:600) 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.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)

[PPisz]

VMs did not start either on 4.20 hosts or on 4.19.3. A new isolated network was being created (VR started without a problem and there was communication to it via cloud0 all the time), VMs did not start in the new network with the message as above.

[weizhouapache]

just to confirm, are the management server, cloudstack agent and systemvm template all upgraded to 4.20 ?

[PPisz]

Yes, we will try to upgrade again next weekend

[PPisz]

At the same time we definitely had a problem with this: #10117 (comment)

[akrasnov-drv]

I provided logs and additional info above in corresponding threads.
In shot

• under load part of VMs stays in Starting state, and UI becomes unresponsive, libvirt restart revives UI and expunging of VMs
• part of VMs that manage to start do not get IPs
• most fail to get static nat configured (I have enough free public IPs)
• at the end primary VR fails but backup one is not promoted to primary for some 30-60 min

[akrasnov-drv]

Appeared that when I start VMs with static nat, VR cpu is quite high. Hardly understand what it does on 2.1Ghz to get

11:40:44 up 39 min,  1 user,  load average: 20.37, 8.19, 4.08

but I'll try to increase VR CPU

[akrasnov-drv]

Just checked my network offering, and service_offering_id is set to NULL. The same as for all other network offerings. So should not be the issue. Still network restart did not help as VRs were recreated with default System offering.
Then I removed my network and recreated it. And again got VRs with default System offering.
Looks like the only way to have my VR system offering is to specify it in network offering directly.
Please advise.

[weizhouapache]

have you changed zone or global setting system.vm.use.local.storage to true ?

[akrasnov-drv]

Thank you. Indeed I forgot, I set it to true in zone during creation.
Setting it to false made VMs to use shared storage.

Also I had to re-create my isolated network offering, specifying my new VR offering. The field is marked as required, so I can't keep it empty to use global settings, and occasionally its overrides global.

After creating VR offering and recreating network with updated network offering I managed to get 4 cores in my VRs.

[akrasnov-drv]

All the same, after increasing VRs, I've got failing STATICNAT.ENABLE just after 3 properly started VMs, all the rest is failing.
Primary VR Redundant state is shown as UNKNOWN.

[akrasnov-drv]

root@r-3449-VM:~# uptime
09:46:40 up 16 min, 1 user, load average: 2.65, 2.15, 1.04
its cloud.log is attached
cloud.log.gz

[weizhouapache]

@akrasnov-drv

1. can you upload the logs in agent.log as well?
2. can you test network/vpc without redundant VRs ?

[akrasnov-drv]

So, I recreated network with standard isolated network offering, restarted agent where VR runs and reproduced the failure just after some 5 min of VR uptime
I see it started failing at about 19 minutes 35 seconds
The logs are attached.
logs.tgz

[weizhouapache]

So, I recreated network with standard isolated network offering, restarted agent where VR runs and reproduced the failure just after some 5 min of VR uptime I see it started failing at about 19 minutes 35 seconds The logs are attached. logs.tgz

there are few agent logs which do not give clue.

do you have other agent logs ? can you change the log level to DEBUG ?

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

any exception on management server ?

[akrasnov-drv]

I'm still trying to find something in logs, but have not managed to find real thing yet. Management server is already set to debug.
I'll switch agent logs to debug and upload it later.
Meanwhile
I believe ae752c51-cc8b-4cf8-a5ba-ad043b65fa6a is the uuid of VM that failed first, so I executed on management server
egrep "ERR|WARN|ae752c51-cc8b-4cf8-a5ba-ad043b65fa6a" /var/log/cloudstack/*/* > /root/mgmt.log
and am attaching it here.
Be aware it's about 120Mb inside!
mgmt.log.gz
The failure started at about 15:19:35 UTC

[weizhouapache]

it looks like the VR is Starting so rules/userdata cannot be applied.

[weizhouapache]

@akrasnov-drv
just for your information, we have faced some issues which seem to be same as yours

• /var/www/html/latest/.htaccess is very large, which caused more than 10 seconds (even more than 2 mins) to apply metadata for a user vm in VR
• VR was rebooted for unknown reason. we suspect it is caused by the issue above.
• when deploy multiple vms (20 or 50), only the first few vms are deployed (less than 10), the others are stuck at Starting.

To solve the issues, we have

• increased global setting workers (Number of worker threads handling remote agent connections.) to 50, and restart cloudstack-management. it can be increased to be larger value.
• cleaned /var/www/html/latest/.htaccess and kept only the first 39 lines (till hypervisor-host-name)
• applied the fix VR: fix duplicated lines in .htaccess #10254 in the VR (/opt/cloud/bin/configure.py) manually.

cc @NuxRo @DaanHoogland @vishesh92

[akrasnov-drv]

Thank you @weizhouapache
I see the PR is not merged yet. I tried to apply the change myself to existing qcow template (mount qcow, update, compress to bz2, and reload), but then appeared that my changes are "overwritten" by the next layer of qcow when VR is started (my change is in the backingStore):

<disk type='file' device='disk'>
      <driver name='qemu' type='qcow2' cache='none'/>
      <source file='/mnt/4798c891-2d66-35c8-b0e3-706fedb51483/31fde825-d5a6-4860-a5b8-a0582e63ff0d' index='2'/>
      <backingStore type='file' index='3'>
        <format type='qcow2'/>
        <source file='/mnt/4798c891-2d66-35c8-b0e3-706fedb51483/7ed14888-2a17-42f3-8c06-e7879041e4d1'/>
        <backingStore/>
      </backingStore>

Could you point me from where it comes (I mean the 2nd layer that reverts the fix)?
Alternatively,
Are there nightly builds where I can take updated template from?
When 4.20.1 (with the fix) is expected?

[weizhouapache]

@akrasnov-drv
you do not need to replace the systemvm template.

instead, you need to change the file /usr/share/cloudstack-common/vms/cloud-scripts.tgz

• create a folder and copy the file to folder
• unzip the file
• change the file opt/cloud/bin/configure.py
• create new zip
• copy the file to all management and kvm hosts

[akrasnov-drv]

Thank you.
Likely you saved me hours.

[loth]

@weizhouapache Would this affect DHCP leases failing to generate properly? We recently had an issue where the RVM dropped all entries in the /etc/dhcphosts.txt file and it was a case of a massive amount of VM's on the node/network with a 4MB htaccess file.

[weizhouapache]

maybe the VR has been rebooted
worth checking

[akrasnov-drv]

I can confirm now that the fix improves scale a lot, still I have the same issues, though not after 3 but after several dozens of nodes

• .htaccess still has a lot of duplicates

31587 /var/www/html/latest/.htaccess
root@r-21-VM:~# cat /var/www/html/latest/.htaccess|sort -u | wc -l
37

• static nat still starts to fail after those successful

2025-01-28 11:38:06,904 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:08,024 ERROR    Command 'nft list tables ip6 | grep ip6_acl' returned non-zero exit status 1.
2025-01-28 11:38:08,100 ERROR    Command 'nft list tables ip6 | grep ip6_firewall' returned non-zero exit status 1.
2025-01-28 11:38:11,765 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:14,035 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:16,218 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:18,418 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:20,823 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:23,168 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:25,616 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:28,143 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:30,503 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:32,953 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:35,446 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:37,940 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:40,671 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:43,361 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:45,849 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:48,571 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:51,267 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:54,037 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:56,822 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:38:59,496 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:39:02,098 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:39:04,752 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:39:07,630 ERROR    Not able to setup source-nat for a regular router yet
2025-01-28 11:39:10,739 ERROR    Not able to setup source-nat for a regular router yet

[akrasnov-drv]

btw, after removing all the VMs, I see .htaccess still with all 59427 lines.
I'd say it's at least not consistent. Likely it should not be updated by deployVirtualMachine at all, otherwise removal of VMs should revert changes.

[weizhouapache]

in my testing VR

root@r-xxx-VM:~# grep -n seek /opt/cloud/bin/configure.py 
935:            fh.seek(0)
973:            fh.seek(0)
979:            fh.seek(0)

[akrasnov-drv]

My fault, I placed it inside if.
Checking again. Sorry.
Additionally I started 100 VMs with user-data, and 99 were fine. Pretty good.

[akrasnov-drv]

Testing again 100 nodes with user-data (5 VMs each 5 sec)

root@r-844-VM:~# grep -n seek /opt/cloud/bin/configure.py
935:            fh.seek(0)
973:            fh.seek(0)
979:            fh.seek(0)
root@r-844-VM:~# cat /var/www/html/latest/.htaccess | wc -l
25

All started properly and this time just within some 7 min.
.htaccess is also good now

root@r-844-VM:~# cat /var/www/html/latest/.htaccess | wc -l
39

Thank you!
Proceeding to static nat tests.

[akrasnov-drv]

Unfortunately static nat problem persists.
I'll close this discussion and open another (dedicated) one.
Thank you for fixing .htaccess problem