Failed VR health check

[MartinEmrich]

ISSUE TYPE

• (Maybe) Bug report
• Improvement Request

COMPONENT NAME

VR, Management Server?

CLOUDSTACK VERSION

4.18.1.0

CONFIGURATION

Single Management server, 2 Shared Networks with non-HA VR each.

OS / ENVIRONMENT

Management Server: CentOS 7
Hypervisor: XCP-ng 8.5

SUMMARY

Here and there, we get an e-mail from the management server like this:

Health checks failed: 2 failing checks on router r-6849-VM / b8679d51-5f2b-4dfa-913c-4c73506dee2e

STEPS TO REPRODUCE

Unknown, but I suspect it might happen during VM provisioning?

EXPECTED RESULTS

Have the reason for the (supposed) failure in the email.

ACTUAL RESULTS

It only says that there are Health checks failed. But we notice no real service failure, and at first have no idea what is wrong.

Only after grepping through the management server logs, I noticed these two lines:

2023-11-02 08:57:22,320 INFO  [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-33ca5294) (logid:2e04f053) Found health check com.cloud.network.dao.RouterHealthCheckResultVO@28fabd51- check type: advanced,check name: dhcp_check.py, check result: false, check last update: Thu Nov 02 08:50:02 CET 2023, details: Missing elements in dhcphosts.txt -
1e:00:5a:00:21:8d 10.12.96.9 test-ci-12 which took running duration (ms) 85.2541923523
2023-11-02 08:57:22,322 INFO  [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-33ca5294) (logid:2e04f053) Found health check com.cloud.network.dao.RouterHealthCheckResultVO@6d617c4c- check type: advanced,check name: dns_check.py, check result: false, check last update: Thu Nov 02 08:50:02 CET 2023, details: Missing entries for VMs in /etc/hosts -

A bit above, I found this (good to have DEBUG log level on all the time), I shortened it to the relevant part:

2023-11-02 08:57:22,300 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-33ca5294) (logid:2e04f053) Parsing and updating DB health check data for router: 6849 with data: {"basic":{"lastRun <SNIP> "message": "Missing entries for VMs in /etc/hosts -\n10.12.96.9 test-ci-12", "success": "false"}, <SNIP>

That VM was just being created. Maybe the health check ran during VM creation and got an inconsistent snapshot of the situation?

[DaanHoogland]

Thanks @MartinEmrich , sounds like your right (except for the DEBIG should be on all the time part, but hey, cloudstack is good, not perfect ;)

I am not sure how to address this issue. We could:

1. redesign the test procedure so that it only runs on quiet moments. Not sure how that will work, adn for very busy networks that might mean no health check will ever be done. A busy network is being check by use so that last bit might not be a problem.
2. redesign the check script so it recognises the situation.
3. redesign the script so it does a double check on failure.

Not sure which would be the best approach.

[MartinEmrich]

Hmm I don't have sufficient knowledge about the implementation of the system VMs, their management or the health checks to have a well-founded opinion... but as you ask:
I would prefer Option 2 (a mutex between The-Thing-Updating-The-Config(TM) and the health check loop). So whenever the health check runs, the state of the VR is guaranteed to be consistent. This would implicitly include option 1.

Alternative: only alert if a health check fails consecutively multiple times (e.g. 5 times in a row).

[weizhouapache]

@DaanHoogland @MartinEmrich
I had a quick check on the code, it seems the health check only considers the Running vms

cloudstack/server/src/main/java/com/cloud/network/router/VirtualNetworkApplianceManagerImpl.java

Lines 1800 to 1802 in 4bdff06

	if (vm.getState() != VirtualMachine.State.Running) {
	continue;
	}

the code looks good to me.

@MartinEmrich
it would be good to share more information, for example

• the log of the job of vm deployment
• the files in VR (/root/health_checks_data.json, /etc/dhcphosts.txt, /etc/hosts, etc)

[MartinEmrich]

After reading the longs for a while longer, I suspect it's related to renaming or destroying a VM, not creating it.

At 8:49, a VM has been renamed from "test-ci-12" to "test-ci-12-CDSDEL" (our CI/CD tooling adds a suffix to the VM name prior to deletion, to make the name available for a replacement even before Delete/Expunge/Destroy is complete)
At 8:50, the VM has been destroyed (destroyVirtualMachine, expunge=true)
At 8:57, the health check message says "Missing entries for VMs in /etc/hosts -\n10.12.96.9 test-ci-12", so it apparently neither has caught up with that rename, nor the destroy.

That process happens many times, only rarely do we get the Health Check failed email. But with 4.11 it came a few times per year, since upgrading to 4.18, it comes multiple times a week.

@weizhouapache The management server log from that rename up to the health check is 1.4MB, and cleaning all internal data (VM names, host names, user names, domains, IPs) would most probably make it useless. If you have specific questions, I can look it up though.

[weizhouapache]

After reading the longs for a while longer, I suspect it's related to renaming or destroying a VM, not creating it.

Yes, could be.

At 8:49, a VM has been renamed from "test-ci-12" to "test-ci-12-CDSDEL" (our CI/CD tooling adds a suffix to the VM name prior to deletion, to make the name available for a replacement even before Delete/Expunge/Destroy is complete)

Did the CI/CD tool add the suffix by manual db changes or cloudstack API updatevirtualmachine ?
if the API (https://cloudstack.apache.org/api/apidocs-4.18/apis/updateVirtualMachine.html) is used, cloudstack should update the dns in VRs automatically (see #5425)

At 8:50, the VM has been destroyed (destroyVirtualMachine, expunge=true) At 8:57, the health check message says "Missing entries for VMs in /etc/hosts -\n10.12.96.9 test-ci-12", so it apparently neither has caught up with that rename, nor the destroy.

That process happens many times, only rarely do we get the Health Check failed email. But with 4.11 it came a few times per year, since upgrading to 4.18, it comes multiple times a week.

The VR health check feature was introduced in cloudstack 4.14 (see #3575 )

@weizhouapache The management server log from that rename up to the health check is 1.4MB, and cleaning all internal data (VM names, host names, user names, domains, IPs) would most probably make it useless. If you have specific questions, I can look it up though.

[MartinEmrich]

yes, the tool uses updateVirtualMachine to update the VM name. From the logs, I isolated two Context (?) IDs. one for the API request:

# grep ctx-ca192b9b cs-8177-cleanup.log
2023-11-02 08:49:44,889 DEBUG [c.c.a.ApiServlet] (qtp1444635922-151964:ctx-ca192b9b) (logid:7a0443fc) ===START===  10.12.0.248 -- GET  name=test-ci-12-CDSDEL&id=933103d7-9a77-429b-9e51-93b70c06bb5d&command=updateVirtualMachine&apiKey=XXX&signature=XXX
2023-11-02 08:49:44,893 DEBUG [c.c.a.ApiServer] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb) (logid:7a0443fc) CIDRs from which account 'Account [{"accountName":"admin","id":39,"uuid":"813308c2-8405-46c3-aa09-0e6bbd90e3b1"}]' is allowed to perform API calls: 0.0.0.0/0,::/0
2023-11-02 08:49:44,896 WARN  [o.a.c.a.ProjectRoleBasedApiAccessChecker] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb) (logid:7a0443fc) Project is null, ProjectRoleBasedApiAccessChecker only applies to projects, returning API [updateVirtualMachine] for user [User {"username":"admin","uuid":"5be0d35b-ba21-4240-966a-3d4901cabf0c"}.] as allowed.
2023-11-02 08:49:44,896 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb) (logid:7a0443fc) RoleService is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-11-02 08:49:44,897 DEBUG [o.a.c.r.ApiRateLimitServiceImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb) (logid:7a0443fc) API rate limiting is disabled. We will not use ApiRateLimitService.
2023-11-02 08:49:44,897 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter displayvm as the caller is not authorized to pass it in
2023-11-02 08:49:44,897 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter instancename as the caller is not authorized to pass it in
2023-11-02 08:49:44,897 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter extraconfig as the caller is not authorized to pass it in
2023-11-02 08:49:44,897 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter customid as the caller is not authorized to pass it in
2023-11-02 08:49:44,902 DEBUG [c.c.u.AccountManagerImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Access to Account [{"accountName":"admin","id":39,"uuid":"813308c2-8405-46c3-aa09-0e6bbd90e3b1"}] granted to Account [{"accountName":"admin","id":39,"uuid":"c8ef4b22-e803-49ed-9275-1363122ae4b6"}] by DomainChecker
2023-11-02 08:49:44,904 DEBUG [c.c.u.AccountManagerImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Access to VM[User|test-ci-12] granted to Account [{"accountName":"admin","id":39,"uuid":"c8ef4b22-e803-49ed-9275-1363122ae4b6"}] by DomainChecker
2023-11-02 08:49:44,906 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter displayvm as the caller is not authorized to pass it in
2023-11-02 08:49:44,906 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter instancename as the caller is not authorized to pass it in
2023-11-02 08:49:44,906 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter extraconfig as the caller is not authorized to pass it in
2023-11-02 08:49:44,906 DEBUG [o.a.c.a.BaseCmd] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Ignoring parameter customid as the caller is not authorized to pass it in
2023-11-02 08:49:44,910 DEBUG [c.c.u.AccountManagerImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Access to VM instance {"id":6843,"instanceName":"i-39-6843-VM","type":"User","uuid":"933103d7-9a77-429b-9e51-93b70c06bb5d"} granted to Account [{"accountName":"admin","id":39,"uuid":"c8ef4b22-e803-49ed-9275-1363122ae4b6"}] by DomainChecker
2023-11-02 08:49:44,942 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438752: Sending  { Cmd , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:5a:00:21:8d","vmIpAddress":"10.12.96.9","vmName":"test-ci-12-CDSDEL","defaultRouter":"10.12.96.1","defaultDns":"10.12.96.3","duid":"00:03:00:01:1e:00:5a:00:21:8d","isDefault":"true","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-6849-VM","router.guest.ip":"10.12.96.3","router.ip":"169.254.3.7","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2023-11-02 08:49:44,942 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438752: Executing:  { Cmd , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:5a:00:21:8d","vmIpAddress":"10.12.96.9","vmName":"test-ci-12-CDSDEL","defaultRouter":"10.12.96.1","defaultDns":"10.12.96.3","duid":"00:03:00:01:1e:00:5a:00:21:8d","isDefault":"true","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-6849-VM","router.guest.ip":"10.12.96.3","router.ip":"169.254.3.7","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2023-11-02 08:49:47,248 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438752: Received:  { Ans: , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 10, { GroupAnswer } }
2023-11-02 08:49:47,250 DEBUG [c.c.n.NetworkModelImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Service SecurityGroup is not supported in the network id=285
2023-11-02 08:49:47,259 DEBUG [o.a.c.n.t.BasicNetworkTopology] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) SAVE USERDATA TO ROUTE RULES
2023-11-02 08:49:47,259 DEBUG [o.a.c.n.t.BasicNetworkTopology] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Applying save userdata entry in network Network {"id": 285, "name": "CDSKLNetwork", "uuid": "6710de0c-d4f5-48bf-bd8b-1543c4d3f888", "networkofferingid": 15}
2023-11-02 08:49:47,277 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438753: Sending  { Cmd , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.12.96.9","vmName":"test-ci-12-CDSDEL","executeInSequence":"false","accessDetails":{"router.name":"r-6849-VM","router.guest.ip":"10.12.96.3","router.ip":"169.254.3.7","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2023-11-02 08:49:47,277 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438753: Executing:  { Cmd , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.12.96.9","vmName":"test-ci-12-CDSDEL","executeInSequence":"false","accessDetails":{"router.name":"r-6849-VM","router.guest.ip":"10.12.96.3","router.ip":"169.254.3.7","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2023-11-02 08:49:52,092 DEBUG [c.c.a.t.Request] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) Seq 21-4298404369348438753: Received:  { Ans: , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 10, { GroupAnswer } }
2023-11-02 08:49:52,092 DEBUG [c.c.v.UserVmManagerImpl] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) User data successfully updated for vm id:  6843
2023-11-02 08:49:52,240 DEBUG [c.c.a.ApiServlet] (qtp1444635922-151964:ctx-ca192b9b ctx-03f9a4cb ctx-a6398ec2) (logid:7a0443fc) ===END===  10.12.0.248 -- GET  name=test-ci-12-CDSDEL&id=933103d7-9a77-429b-9e51-93b70c06bb5d&command=updateVirtualMachine&apiKey=XXX&signature=XXX

And another one doing the Router update?

# grep ctx-27e7e986 cs-8177-cleanup.log
2023-11-02 08:49:44,942 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5:ctx-27e7e986) (logid:447e0724) Seq 21-4298404369348438752: Executing request
2023-11-02 08:49:44,942 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Transforming com.cloud.agent.api.routing.DhcpEntryCommand to ConfigItems
2023-11-02 08:49:44,943 DEBUG [c.c.a.r.v.f.AbstractConfigItemFacade] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Transformed filename: vm_dhcp_entry.json to: vm_dhcp_entry.json.bd5bf82c-70da-48eb-a2d6-f60c6e535872
2023-11-02 08:49:44,946 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Copying VR with ip 169.254.3.7 config file into host 10.12.16.29
2023-11-02 08:49:45,737 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) VR Config file vm_dhcp_entry.json.bd5bf82c-70da-48eb-a2d6-f60c6e535872 got created in VR, IP: 169.254.3.7 with content
2023-11-02 08:49:45,737 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Processing FileConfigItem, copying 290 characters to vm_dhcp_entry.json.bd5bf82c-70da-48eb-a2d6-f60c6e535872 took 794ms
2023-11-02 08:49:45,737 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Executing command in VR: /opt/cloud/bin/router_proxy.sh update_config.py 169.254.3.7 vm_dhcp_entry.json.bd5bf82c-70da-48eb-a2d6-f60c6e535872
2023-11-02 08:49:47,244 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Processing ScriptConfigItem, executing update_config.py vm_dhcp_entry.json.bd5bf82c-70da-48eb-a2d6-f60c6e535872 took 1507ms
2023-11-02 08:49:47,244 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Seq 21-4298404369348438752: Response Received:
2023-11-02 08:49:47,248 DEBUG [c.c.a.t.Request] (DirectAgent-5:ctx-27e7e986) (logid:7a0443fc) Seq 21-4298404369348438752: Processing:  { Ans: , MgmtId: 139289717972276, via: 21(XXX), Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: ","null - success: "],"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }

I found one of the old VR alert mails, the body was

2020-02-01 02:48:08,201 [ALERT] [dnsmasq] The process detected as running

So possibly unrelated.

[DaanHoogland]

@MartinEmrich any progress on this?

[MartinEmrich]

@DaanHoogland no change, still getting the mails from time to time.

[DaanHoogland]

ok @MartinEmrich , keep us informed.

[MartinEmrich]

@DaanHoogland Unless there's a change coming in 4.18.2.0+ which is not linked here, I don't expect anything new.

The mail just says "Health checks failed: 2 failing checks on router r-6849-VM / b8679d51-5f2b-4dfa-913c-4c73506dee2e", but does not specify which health checks.

I still assume it is triggered by renaming the VM with updateVirtualMachine, and then immediately deleting it, so a two-liner in cloudmonkey might be able to reproduce it, if tried often enough.

An alternative would be an option to persistently (i.e. across VR reboots/replacements/updates) disable these two health checks.

[weizhouapache]

@DaanHoogland no change, still getting the mails from time to time.

@MartinEmrich
can you share the /var/log/cloud.log in the VR if possible ?

[MartinEmrich]

@weizhouapache I have no SSH access to the VR, only via (bitmap-not-text) console using the "well known root password", which even garbles most characters due to German keyboard weirdnesses between ACS, XenServer, the Console Proxy VM and whatever VNC-to-Web-Framework it uses.

So I can "less /var/log/cloud.log" on the virtual console, but not get it out of there, not even with cut&paste.
For now, I can neither find the words "health" nor "check" in it.

If you look for a specific pattern/phrase/message, please let me know.