Cluster leader election multiple issues

[jonathandann]

Describe the bug

1. Leader election does not always occur when new nodes added to cluster.
2. Lack of election causes Home Assistant to report none as cluster leader for newly-added nodes.
3. Weights not respected when elections do occur when new nodes are added.

To reproduce
I have 3 nodes: office, lounge, workshop. I have the peer IDs explicitly listed in each config file, auto discovery is disabled, each node is weighted as 10, 2, and 1, respectively. My MQTT broker is running on a different machine on the local network. Home assistant integration and room-assistant logs is used to view leader election.

1. I launch room-assistant on lounge. Wait for discovery of devices
2. I launch room-assistant on office. office reports lounge is added to cluster but office is not elected as leader. office does not log any leader election change. Home Assistant reports office cluster leader as none with 2 instances in cluster.
3. I launch room-assistant on workshop. lounge and office both report workshop as added to cluster. lounge and office both log workshop as being elected as leader. workshop does not log itself as being elected as leader. lounge and office then immediately log office as elected as leader, workshop does not log any leadership change. Home Assistant shows the lounge cluster leader to be lounge while office and workshop show the cluster leader as office.

Relevant logs

lounge

Aug 07 20:34:45 lounge systemd[1]: Started room-assistant service.
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:34:57 lounge room-assistant[4200]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:34:57 lounge node[4200]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:35:01 lounge room-assistant[4200]: 07/08/2021, 20:35:01 - info - IntegrationsModule: Loading integrations: home-assistant, bluetooth-low-energy
Aug 07 20:35:07 lounge room-assistant[4200]: 07/08/2021, 20:35:07 - info - NestFactory: Starting Nest application...
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: AppModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: ConfigModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: NestEmitterModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: IntegrationsModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: HttpModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: DiscoveryModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: PrometheusModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: EventsModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: ClusterModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: TerminusModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: ScheduleModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: BluetoothModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: EntitiesModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: BluetoothLowEnergyModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: HomeAssistantModule dependencies initialized
Aug 07 20:35:08 lounge room-assistant[4200]: 07/08/2021, 20:35:08 - info - InstanceLoader: StatusModule dependencies initialized
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RoutesResolver: EntitiesController {/entities}:
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RouterExplorer: Mapped {/entities, GET} route
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RoutesResolver: StatusController {/status}:
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RouterExplorer: Mapped {/status, GET} route
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RoutesResolver: PrometheusController {/metrics}:
Aug 07 20:35:13 lounge room-assistant[4200]: 07/08/2021, 20:35:13 - info - RouterExplorer: Mapped {/metrics, GET} route
Aug 07 20:35:16 lounge room-assistant[4200]: 07/08/2021, 20:35:16 - info - HomeAssistantService: Successfully connected to MQTT broker at mqtts://mqtt.broker:8883
Aug 07 20:35:17 lounge room-assistant[4200]: 07/08/2021, 20:35:17 - info - ConfigService: Loading configuration from /home/pi/.local/share/nvm/v14.17.4/lib/node_modules/room-assistant/dist/config/definitions/default.js, config/local.yaml (Current: /home/pi/room-assistant)
Aug 07 20:35:17 lounge room-assistant[4200]: 07/08/2021, 20:35:17 - info - NestApplication: Nest application successfully started
Aug 07 20:35:18 lounge room-assistant[4200]: 07/08/2021, 20:35:18 - info - BluetoothLowEnergyService: Discovered new BLE peripheral xxxxxxxx with ID xxxxxxxx and RSSI -82

[... more discovery ...]

Aug 07 20:35:38 lounge room-assistant[4200]: 07/08/2021, 20:35:38 - info - ClusterService: Added 192.x.x.x:6425 to the cluster with id office
Aug 07 20:35:41 lounge room-assistant[4200]: 07/08/2021, 20:35:41 - info - BluetoothLowEnergyService: Discovered new BLE peripheral xxxxxxxx with ID xxxxxxxx-1-58280 and RSSI -90

[... more discovery ...]

Aug 07 20:36:30 lounge room-assistant[4200]: 07/08/2021, 20:36:30 - info - ClusterService: Added 192.x.x.y:6425 to the cluster with id workshop
Aug 07 20:36:30 lounge room-assistant[4200]: 07/08/2021, 20:36:30 - info - ClusterService: workshop has been elected as leader
Aug 07 20:36:30 lounge room-assistant[4200]: 07/08/2021, 20:36:30 - info - ClusterService: office has been elected as leader

[... more discovery ...]

office

Aug 07 20:35:37 voron room-assistant[28722]: 07/08/2021, 20:35:37 - info - IntegrationsModule: Loading integrations: home-assistant, bluetooth-low-energy
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - NestFactory: Starting Nest application...
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: AppModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: ConfigModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: NestEmitterModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: IntegrationsModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: HttpModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: DiscoveryModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: PrometheusModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: EventsModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: ClusterModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: TerminusModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: ScheduleModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: BluetoothModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: EntitiesModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: BluetoothLowEnergyModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: HomeAssistantModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - InstanceLoader: StatusModule dependencies initialized
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RoutesResolver: EntitiesController {/entities}:
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RouterExplorer: Mapped {/entities, GET} route
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RoutesResolver: StatusController {/status}:
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RouterExplorer: Mapped {/status, GET} route
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RoutesResolver: PrometheusController {/metrics}:
Aug 07 20:35:38 voron room-assistant[28722]: 07/08/2021, 20:35:38 - info - RouterExplorer: Mapped {/metrics, GET} route
Aug 07 20:35:39 voron room-assistant[28722]: 07/08/2021, 20:35:39 - info - HomeAssistantService: Successfully connected to MQTT broker at mqtts://mqtt.broker:8883
Aug 07 20:35:39 voron room-assistant[28722]: 07/08/2021, 20:35:39 - info - ConfigService: Loading configuration from /home/pi/.local/share/nvm/v14.17.4/lib/node_modules/room-assistant/dist/config/definitions/default.js, config/local.yaml (Current: /home/pi/room-assistant)
Aug 07 20:35:39 voron room-assistant[28722]: 07/08/2021, 20:35:39 - info - NestApplication: Nest application successfully started
Aug 07 20:35:39 voron room-assistant[28722]: 07/08/2021, 20:35:39 - info - ClusterService: Added 192.x.x.z:6425 to the cluster with id lounge
Aug 07 20:35:39 voron room-assistant[28722]: 07/08/2021, 20:35:39 - info - BluetoothLowEnergyService: Discovered new BLE peripheral xxxxxxxx with ID xxxxxxxx and RSSI -75

[... more discovery ...]

Aug 07 20:36:30 voron room-assistant[28722]: 07/08/2021, 20:36:30 - info - ClusterService: Added 192.x.x.y:6425 to the cluster with id workshop
Aug 07 20:36:30 voron room-assistant[28722]: 07/08/2021, 20:36:30 - info - ClusterService: workshop has been elected as leader
Aug 07 20:36:30 voron room-assistant[28722]: 07/08/2021, 20:36:30 - info - HomeAssistantService: Refreshing entity states
Aug 07 20:36:30 voron room-assistant[28722]: 07/08/2021, 20:36:30 - info - ClusterService: office has been elected as leader

workshop

Aug 07 20:36:01 workshop systemd[1]: Started room-assistant service.
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:36:13 workshop room-assistant[8806]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 07 20:36:13 workshop node[8806]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Aug 07 20:36:18 workshop room-assistant[8806]: 07/08/2021, 20:36:18 - info - IntegrationsModule: Loading integrations: home-assistant, bluetooth-low-energy
Aug 07 20:36:23 workshop room-assistant[8806]: 07/08/2021, 20:36:23 - info - NestFactory: Starting Nest application...
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: AppModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: ConfigModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: NestEmitterModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: IntegrationsModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: HttpModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: DiscoveryModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: PrometheusModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: EventsModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: ClusterModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: TerminusModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: ScheduleModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: BluetoothModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: EntitiesModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: BluetoothLowEnergyModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: HomeAssistantModule dependencies initialized
Aug 07 20:36:24 workshop room-assistant[8806]: 07/08/2021, 20:36:24 - info - InstanceLoader: StatusModule dependencies initialized
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RoutesResolver: EntitiesController {/entities}:
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RouterExplorer: Mapped {/entities, GET} route
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RoutesResolver: StatusController {/status}:
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RouterExplorer: Mapped {/status, GET} route
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RoutesResolver: PrometheusController {/metrics}:
Aug 07 20:36:30 workshop room-assistant[8806]: 07/08/2021, 20:36:30 - info - RouterExplorer: Mapped {/metrics, GET} route
Aug 07 20:36:33 workshop room-assistant[8806]: 07/08/2021, 20:36:33 - info - HomeAssistantService: Successfully connected to MQTT broker at mqtts://mqtt.broker:8883
Aug 07 20:36:33 workshop room-assistant[8806]: 07/08/2021, 20:36:33 - info - ConfigService: Loading configuration from /home/pi/.local/share/nvm/v14.17.4/lib/node_modules/room-assistant/dist/config/definitions/default.js, config/local.yaml (Current: /home/pi/room-assistant)
Aug 07 20:36:34 workshop room-assistant[8806]: 07/08/2021, 20:36:34 - info - NestApplication: Nest application successfully started
Aug 07 20:36:34 workshop room-assistant[8806]: 07/08/2021, 20:36:34 - info - BluetoothLowEnergyService: Discovered new BLE peripheral xxxxxxxx with ID xxxxxxxx and RSSI -80

[... more discovery ...]

Relevant configuration
All of the configs look like this. Only the instanceName and weight differs.

global:
  instanceName: office
  integrations:
    - homeAssistant
    - bluetoothLowEnergy
cluster:
  port: 6425
  weight: 10
  autoDiscovery: false
  peerAddresses:
    - 192.x.x.x:6425 # office
    - 192.x.x.y:6425 # workshop
    - 192.x.x.z:6425 # lounge
homeAssistant:
  mqttUrl: 'mqtts://mqtt.broker:8883'
  mqttOptions:
    username: AzureDiamond
    password: hunter2
    rejectUnauthorized: false
bluetoothLowEnergy:
  hciDeviceId: 0
  timeout: 61
  allowlist:
    - xxxxxx-xxxx-xxxx
  tagOverrides:
    xxxxxx-xxxx-xxxx:
      name: iPhone BLE

Expected behavior

1. lounge should first log itself as leader. It's the only node.
2. office should be elected as leader when added to the cluster. It has the highest weight (10). However it was not.
3. office should publish the current value of the leader (even if incorrect) to MQTT, not none (which may be the absence of a publication) because no re-election has taken place.
4. lounge should log the addition of office to the cluster. It does not.
5. workshop should be added to the cluster but never elected as leader.
6. All leadership changes should be logged by all nodes
7. MQTT messages should always be published by all nodes if leader changes.
8. After all 3 nodes are launched, Home Assistant should show office as leader for the cluster as reported by each node's "cluster leader" sensor. It does not.

Environment

• room-assistant version: 2.18.4
• installation type: node 14.7.4 running under NVM
• hardware: office is an Raspberry Pi 4 on ethernet, lounge and workshop are Raspberry Pi Zero W on Wi-Fi. MQTT broker is hardwired home server running mosquitto in Docker on Ubuntu 21.04 on an Intel Core i5 10400, 32 GB RAM.
• OS: Raspbian Buster

[jonathandann]

Following on from this: if I restart a node in the cluster while all are running, the restarted node is always elected as leader. This should not happen if the weights were respected. If the leader is restarted the next-highest weighted node should become leader until the restart has completed and the higher-weighted node takes over.

[github-actions]

There hasn't been any activity on this issue recently. In an effort to provide a better overview of current issues we automatically clean some of the old ones. Many of them may already be resolved in newer versions of room-assistant.
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[townsmcp]

Is there a way of reopening this issue? I am seeing the same behaviour on v3 beta 4 (HA addon is beta 3):
RPI zero 2 W = 3.0.0.beta 4
RPI 4B = 3.0.0.beta 4
HA addon = 3.0.0 beta 3

[mKeRix]

I re-opened the issue for transparency. I believe this won't be handled as fixes to the current mechanism though. Instead, #780 seems like the best way forward to me.