Rack controller status flapping when "ClusterClient connection lost" messages in rackd.log

These messages are harmless, but we recognize they are annoying and misleading. We should improve this.

PS: 3.3.0 is not released yet, so this is subjected to change at any moment

Via MAAS chat:

New installations of MAAS 3.3 (both new installations and upgrades) where the region+rack controllers are going up and down constantly. maas.log show messages like this:

maas.rpc.rackcontrollers: [info] Existing rack controller 'xxx' running version 3.3.0-13159-g.1c22f7beb has connected to region 'yyy'

and rackd.log shows this:

rack controller 'mqrfwf' registered (via xxx:pid=1416) with MAAS version 3.3.0-13159-g.1c22f7beb
both repeating all the time.

Hi all,

I've been investigating this issue and I think it might be more than just a cosmetic issue. The logs get thousands of this connection established/lost messages because each connection lives around 10-15 minutes. As there are several connections in the pool there is always some connection being created or destroyed.
I looked at a network dump and there is nothing strange there, the party that starts the connections ends them normally after a few minutes.

MAAS uses connection pooling and the behaviour with creating new connections is expected and harmless. We will improve the log spam by changing the log level from INFO to DEBUG, where these messages belong.

It seems more serious, it might cause frequent kill of DHCP agent. So DHCPd is very short lived "
In my case in HA setup that prevent machines to being commisioned

Also some machines are dissapearing when be ncommisioned in the same time.

MAAS version
installed: 3.3.2-13177-g.a73a6e2bd (27109) 138MB -

maas-01:~$ sudo maas status
bind9 RUNNING pid 272671, uptime 1 day, 6:17:34
dhcpd RUNNING pid 2288973, uptime 0:04:05
dhcpd6 STOPPED Not started
http RUNNING pid 272521, uptime 1 day, 6:17:35
ntp RUNNING pid 2228029, uptime 0:13:06
proxy RUNNING pid 1865584, uptime 1:06:39
rackd RUNNING pid 263370, uptime 1 day, 6:18:38
regiond RUNNING pid 263371, uptime 1 day, 6:18:38
syslog RUNNING pid 276172, uptime 1 day, 6:17:06
maas-02:~$ sudo maas status
bind9 RUNNING pid 1616842, uptime 1 day, 6:14:20
dhcpd RUNNING pid 1047478, uptime 0:00:47
dhcpd6 STOPPED Not started
http RUNNING pid 1620198, uptime 1 day, 6:13:32
ntp RUNNING pid 1622263, uptime 1 day, 6:12:48
proxy RUNNING pid 923083, uptime 1:02:36
rackd RUNNING pid 1616845, uptime 1 day, 6:14:20
regiond RUNNING pid 1616847, uptime 1 day, 6:14:20
syslog RUNNING pid 1622253, uptime 1 day, 6:12:48

I finally managed to reproduce this and want to add that just changing the log level of the messages might not be enough. In the interval between a connection is lost and is established again the Controllers page on the web interface shows that controller as degraded. This is confusing for the users.

If this is normal, maybe we should not notify the web page that the controller is degraded until something abnormal happens.

Thanks

Message about racks is very strange. That was not an issue in case 3.2.7

92% rackd available.

The UI behavior needs to be looked at, see attached screenshot.

Please have a look at the UI behavior.

I have seen happening now in 3.2.8

I am also affected although i am currently running snap 3.3.4

```
$ sudo snap list maas
Name Version Rev Tracking Publisher Notes
maas 3.3.4-13189-g.f88272d1e 28521 3.3/stable canonical✓ -
```

As stated earlier, this is not only a cosmetic bug since each time a connection lost is logged, dhcpd is restarted by rackd (i saw the `supervisorctl restart dhpcd` in the process list).

So not displaying in UI or changing log level won't solve the dhpcd restart.

Moreover, this can be highly frequent: i once got a restart every 10s and had to stop all rackd and restart them in sequence to get out of this forever loop. I will look into regiond logs to find out why connection was closed.

For maas-ui we need to

1. check what's wrong with that number and where it is coming from
2. think about a different way to display this

Hello,

Just thought I'd report that I, too, am seeing this flapping behavior on my couple of rack controllers - both on MAAS 3.3.4. Throwing my comment on this since this bug is reportedly fixed in the 3.3.x branch, yet persists for me:
---
root # snap list maas
Name Version Rev Tracking Publisher Notes
maas 3.3.4-13189-g.f88272d1e 28521 3.3/stable canonical✓ -

root # tail -n1 /var/snap/maas/common/log/rackd.log
2023-09-25 22:36:25 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:192.168.1.200', port=43998, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:192.168.1.46', port=5252, flowInfo=0, scopeID=0))

root # date
Mon Sep 25 10:36:46 PM UTC 2023
---

It's worth noting that I am NOT seeing the dhcpd service restarts on every disconnect/reconnect, however - in my particular example, insofar as I can see, there is no loss of functionality and it is purely cosmetic.

I am also still seeing this behavior in MAAS 3.4.0rc2.