Repository navigation
Backup virtual router of a redundant VPC stays in starting state after restart with clean up. #8055
Description
ISSUE TYPE
- Bug Report
COMPONENT NAME
VR, VPC
CLOUDSTACK VERSION
4.18.1
CONFIGURATION
Advance zone with isolated network
SUMMARY
One of our CloudStack environments has been upgraded from 4.17.2 to 4.18.1, last week. Then we restarted a big VPC with 11 tiers and ACLs that have 8 rules in them.
After restarting that VPC, we noticed the following behavior:
- The backup VR stopped and destroyed (expected).
- The new VR created and put in Starting state (expected).
- The new VR stayed in Starting state for approximately 30 minutes. Then it turned into Stopped state.
- 1 hour later the Async job poll returned error "Unable to serialize: Job is cancelled as it has been blocking others for too long".
- The new VR remains in Stopped state.
We checked these, they weren't the case:
- Pod, host and cluster have enough capacity to start the VR.
- VR uses the correct system vm template.
- We removed all of our custom features from Cloudstack and ran exactly the community version but that didn't help.
STEPS TO REPRODUCE
1. Create a VPC with redundant VRs with 11 tiers in it.
2. Create ACLs with 10 rules and use it for all the tiers to make sure you have big amount of firewall rules in each VPC tier.
3. Attach VMs to each tier and make sure the VMs are started, so all VPC tiers turn into "Implemented" state.
4. Try to restart VPC with cleanup.
EXPECTED RESULTS
Both VRs will be reprovisioned in reasonable amount of time (several minutes).
ACTUAL RESULTS
One of the VRs will be recreated but never started.
ADDITIONAL INFORMATION
We notice that the actual libvirt domain of VR was never even attempted to be provisioned on the hypervisor.
Looks like the management server holds this job until it gets cancelled by some timeout.
Watching the management server log with grep by VR instance name shows the following behavior:
tail -f /var/log/cloudstack/management/management-server.log | grep r-27209-VM
2023-10-09 12:57:50,398 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 firewall Egress rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 12:57:50,399 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 Ipv6 firewall rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 12:57:50,408 DEBUG [c.c.n.r.VpcVirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 3 network ACLs to apply as a part of VPC VR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start for guest network id=4140
2023-10-09 12:57:50,455 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating monitoring services on VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
# 1,5 minutes later
2023-10-09 12:59:22,010 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Reapplying dhcp entries as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
2023-10-09 12:59:22,023 DEBUG [c.c.n.r.CommandSetupHelper] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating dhcp entry for vm VM instance {"id":27189,"instanceName":"i-877-27189-VM","type":"User","uuid":"f34641cc-1885-430e-9eef-0f2560527f69"} on domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"}.
2023-10-09 12:59:22,037 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Reapplying vm data (userData and metaData) entries as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
2023-10-09 12:59:22,048 DEBUG [c.c.n.r.CommandSetupHelper] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating user data entry for vm VM instance {"id":27189,"instanceName":"i-877-27189-VM","type":"User","uuid":"f34641cc-1885-430e-9eef-0f2560527f69"} on domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"}
2023-10-09 12:59:22,092 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 firewall Egress rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 12:59:22,092 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 Ipv6 firewall rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 12:59:22,100 DEBUG [c.c.n.r.VpcVirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 3 network ACLs to apply as a part of VPC VR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start for guest network id=4141
2023-10-09 12:59:22,146 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating monitoring services on VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
# 1,5 minutes later
2023-10-09 13:00:56,723 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Reapplying dhcp entries as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
2023-10-09 13:00:56,734 DEBUG [c.c.n.r.CommandSetupHelper] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating dhcp entry for vm VM instance {"id":27190,"instanceName":"i-877-27190-VM","type":"User","uuid":"4aa04dae-091d-4f78-bc32-af5da5a1ca2d"} on domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"}.
2023-10-09 13:00:56,747 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Reapplying vm data (userData and metaData) entries as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
2023-10-09 13:00:56,758 DEBUG [c.c.n.r.CommandSetupHelper] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating user data entry for vm VM instance {"id":27190,"instanceName":"i-877-27190-VM","type":"User","uuid":"4aa04dae-091d-4f78-bc32-af5da5a1ca2d"} on domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"}
2023-10-09 13:00:56,797 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 firewall Egress rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 13:00:56,798 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 0 Ipv6 firewall rule(s) to apply as a part of domR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start.
2023-10-09 13:00:56,805 DEBUG [c.c.n.r.VpcVirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Found 3 network ACLs to apply as a part of VPC VR VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start for guest network id=4142
2023-10-09 13:00:56,851 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-ba2a3ea5 job-2776242/job-2776251 ctx-b405daf9) (logid:46201edd) Creating monitoring services on VM instance {"id":27209,"instanceName":"r-27209-VM","type":"DomainRouter","uuid":"b78b470a-2a88-4705-9909-26ba84277fca"} start...
... and it contines iterating over networks, one network per 1,5 minutes. The router hasn't started on the node yet.
Activity
soreana commentedon Oct 9, 2023
Any suggestion appreciated.
weizhouapache commentedon Oct 9, 2023
@soreana
what hypervisor do you use ?
can you check if all mgmt servers and hypervisors are upgraded to 4.18.1.0 ?
can you ssh into the backup router (from kvm host), and share the /var/log/cloud.log ?
I suspect you are facing the issue fixed by #7953
phsm commentedon Oct 9, 2023
@weizhouapache
Thanks for prompt reply.
Yes, both management server and hypervisors are updated to 4.18.1.0.
However, it doesn't seem this is the bug you mentioned.
As per Cloudstack management server, the job for creating a new virtual router is created, but the hypervisor never receives the command to start the new routerVM.
Here are the last messages from the management server regarding starting new VM:
After this line, no activity on this job anymore (the new routerVM appears as "Starting").
The hypervisor that is chosen for the routerVM doesn't have any mentions of its name in the agent.log:
It looks like the management server doesn't even send VM creation command to the hypervisor.
An hour later the job ends with the following message:
The running routerVM (the one in Running state while Cloudstack is trying to create the second routerVM) indeed shows the lines from the bug you've mentioned:
However the timestamps in the log correspond to the VPC creation time (I created this test VPC at 09 Oct 2023 08:39:10).
I'm still attempting to figure out the cause of the bug by removing VPC elements and trying to restart it. So far I have a suspicion that large amount of tiers (the VPC has 11 tiers) is the cause but it is yet to be confirmed.
I will post an update here with the reproduce scenario once I have it.
weizhouapache commentedon Oct 9, 2023
@soreana
do other vpcs have the same issue ?
soreana commentedon Oct 9, 2023
@weizhouapache When VPC has a lot of tiers (around 10 to 11 tiers) the issue happens.
weizhouapache commentedon Oct 9, 2023
It is strange that primary router works but backup does not.
there is no difference on the management server for them. (The primary/backup role is determined by the keepalived running inside VRs.)
can you try the steps below
soreana commentedon Oct 10, 2023
@weizhouapache Thanks for the comment. They didn't help.
I've updated the issue description with more information. Any help appreciated 🙏
weizhouapache commentedon Oct 11, 2023
@kriegsmanj
Oh, I thought that the primary router has been recreated successfully ...
This seems to be a critical issue.
as @soreana said, you have created another VPC with same configuration, it works, right ?
soreana commentedon Oct 11, 2023
@weizhouapache
We did several tests:
We created another VPC with the same configuration on the same platform: it also fails to recreate VR when restarting with cleanup.
We created a VPC with the same configuration on a different cloudstack installation, that has lot less load on it: we could not reproduce the issue there.
However, we noticed that it takes approximately 20 minutes before VR instance even appears in the hypervisor's "virsh list" output. Once its appreared on the hypervisor, it reports as online in Cloudstack within couple of minutes.
We tried reproducing this behavior on 4.17: it seems that 4.17 is not affected. The same VPC configuration fully restarts in 9 minutes.
Do you have any suggestion?
weizhouapache commentedon Oct 11, 2023
@soreana @kriegsmanj
I created a vpc with 12 tiers (each tier has a vm), restart with cleanup worked well.
there is not such long time intervan between these 2 logs
I did not see any code changes between 4.17 and 4.18 which might cause the issue.
weizhouapache commentedon Oct 18, 2023
@soreana @kriegsmanj
any update on this issue ?
phsm commentedon Oct 18, 2023
We have tried to reporoduce the bug multiple times under different circumstances.
Unfortunately, there's no reliable reproduce scenario so far. Here are our findings:
If a VPC has many tiers, the amount of time for the routervm to appear becomes too much. In this case a hypervisor fencing mechanism reports to the management server that the VM is missing, and it is turned into "Stopped" state.
We continue our investigation.
soreana commentedon Nov 3, 2023
@weizhouapache We have been performing more tests and now are suspecting that ACL with multiple rules could be the cause of this delay in deploying routers. A VPC with 6 tiers and 7 customer ACL rules took more than 30 minutes to create, while the same VPC with default ACL rule took about 15 minutes (50% quicker).
Can you please explain the process of creation of ACL rules within a VPC and where it is taking so long to apply? Also how we could speed up this process in order to verify if it helps.
Thanks in advance!
weizhouapache commentedon Nov 8, 2023
@soreana @kriegsmanj
can you search "vr_cfg.sh" in the management-server.log and agent.log ?
weizhouapache commentedon Nov 10, 2023
@soreana @kriegsmanj
can you search "vr_cfg.sh" in the management-server.log and agent.log ?
is your issue same as #8201 ?
soreana commentedon Nov 10, 2023
@weizhouapache Sorry about the delay, it was a busy day.
I checked the
vr_cfg.shin management servers and agents logs. There were nothing in the management server, and only three agents has thevr_cfg.shin their logs.node1
node2:
node3:
IPs are as follow:
169.254.1.144is primary router IP the VPC-01169.254.3.248is backup router IP the VPC-01169.254.3.155is router ip of an isolated networkphsm commentedon Dec 19, 2023
@weizhouapache
An update on this issue:
This bug only occurs on VPCs on large platforms "with history": the platforms that have a lot of both live and removed VMs, NICs etc.
The mechanics of the process:
With trusty s_logger.debug() I was able to narrow down the VR start execution procedure to a specific method that introduces such a big delay. It is this method: getRouterHealthChecksConfig
More specifically, its this call inside the method that introduces the delay: userVmJoinDao.search(scvm, null)
It is executed in a loop for each virtual router NIC. Each call to search() is expensive, so the getRouterHealthChecksConfig() takes 10-20 seconds to complete.
But there is more: getRouterHealthChecksConfig() is executed for each VPC tier as a part of createMonitorServiceCommand() call during VR startup process.
The createMonitorServiceCommand() is a part of finalizeMonitorService() method.
And finalizeMonitorService() method is executed twice here: 1, 2
So eventually the getRouterHealthChecksConfig() is executed more than a hundred times during the VR startup, and each time it adds its 10-20 seconds to the process.
What do I propose
It seems that getRouterHealthChecksConfig() returns the same result per VR object. That means that it can be executed once in the beginning of VR initialisation instead of deep inside of foreach loops.
But my Java knowledge unfortunately isn't good enough to actually implement it.
weizhouapache commentedon Dec 19, 2023
@phsm
Great, thanks for the update
maybe @soreana can pick this up ?
phsm commentedon Dec 20, 2023
@weizhouapache
Hi Wei,
I've actually managed to implement the patch myself.
The test looks promising:
Without this patch applied, the 10-tier VPC took 61 minutes to fully restart
With this patch applied, the same VPC took 9 minutes to fully restart
Can you take a look at it? If it looks good to you, I can make a PR with it.
weizhouapache commentedon Dec 20, 2023
@phsm
looks good.
can you create a PR ?
vpc: optimize createMonitorServiceCommand() execution (#8385)
weizhouapache commentedon Feb 19, 2024
fixed by #8385
vpc: optimize createMonitorServiceCommand() execution (apache#8385)