search

ebaauw / homebridge-hue

Homebridge plugin for Philips Hue
Apache License 2.0
901 stars 91 forks source link

Seeming concurrency issue at Homebridge startup. #1157

Closed rossbacher closed 1 year ago

rossbacher commented 1 year ago

Issue

When homebridge hue is starting it gets stuck with 

[20/05/2023, 10:57:20] [Hue] homebridge: error: Cannot add a Service with the same UUID '00000012-0000-1000-8000-656261617577' as another Service in this Accessory without also defining a unique 'subtype' property.

I disabled all other plugins that I have running and it appears to work then, however what is even stranger is that it happens less often if the system is under load (This is running on an RPI 4) and I can "fix" the issue if I do run stress --cpu 3 on the RPI and then restart homebridge,

Once the system is started I can kill the artificial load generation and all works fine (until the next restart).

I attached a dump file and can provide any other information.

Log Messages

[20/05/2023, 10:56:38] [HB Supervisor] Starting Homebridge with extra flags: -I
[20/05/2023, 10:56:38] [HB Supervisor] Started Homebridge v1.6.1 with PID: 27588
[20/05/2023, 10:56:39] Loaded config.json with 0 accessories and 9 platforms.
[20/05/2023, 10:56:40] Loaded 0 cached accessories from cachedAccessories.
[20/05/2023, 10:56:40] ---
[20/05/2023, 10:56:41] Loaded plugin: homebridge-config-ui-x@4.50.4
[20/05/2023, 10:56:41] Registering platform 'homebridge-config-ui-x.config'
[20/05/2023, 10:56:41] ---
[20/05/2023, 10:56:44] Loaded plugin: homebridge-hue@0.13.61
[20/05/2023, 10:56:44] Registering platform 'homebridge-hue.Hue'
[20/05/2023, 10:56:44] ---
[20/05/2023, 10:56:45] Loaded plugin: homebridge-mieleathome@3.5.0
[20/05/2023, 10:56:45] Registering platform 'homebridge-mieleathome.Miele@home'
[20/05/2023, 10:56:45] ---
[20/05/2023, 10:56:45] Loaded plugin: homebridge-modern-forms@1.0.8
[20/05/2023, 10:56:45] Registering platform 'homebridge-modern-forms.ModernForms'
[20/05/2023, 10:56:45] ---
[20/05/2023, 10:56:48] Loaded plugin: homebridge-mqttthing@1.1.44
[20/05/2023, 10:56:48] Registering accessory 'homebridge-mqttthing.mqttthing'
[20/05/2023, 10:56:48] ---
[20/05/2023, 10:56:48] Loaded plugin: homebridge-myq@2.12.0
[20/05/2023, 10:56:48] Registering platform 'homebridge-myq.myQ'
[20/05/2023, 10:56:48] ---
[20/05/2023, 10:56:49] Loaded plugin: homebridge-nest@4.6.9
[20/05/2023, 10:56:49] Registering platform 'homebridge-nest.Nest'
[20/05/2023, 10:56:49] ---
[20/05/2023, 10:56:49] Loaded plugin: homebridge-nest-cam@7.5.4
[20/05/2023, 10:56:49] Registering platform 'homebridge-nest-cam.Nest-cam'
[20/05/2023, 10:56:49] ---
[20/05/2023, 10:56:49] The plugin "homebridge-platform-wemo" requires Node.js version of ^14.17.2 || ^16.5.0 which does not satisfy the current Node.js version of v18.16.0. You may need to upgrade your installation of Node.js - see https://homebridge.io/w/JTKEF
[20/05/2023, 10:56:49] Loaded plugin: homebridge-platform-wemo@3.3.1
[20/05/2023, 10:56:49] Registering platform 'homebridge-platform-wemo.BelkinWeMo'
[20/05/2023, 10:56:49] ---
[20/05/2023, 10:56:49] Loaded plugin: homebridge-shelly@0.19.1
[20/05/2023, 10:56:49] Registering platform 'homebridge-shelly.Shelly'
[20/05/2023, 10:56:49] ---
[20/05/2023, 10:56:50] Loaded plugin: homebridge-tplink-smarthome@7.0.1
[20/05/2023, 10:56:50] Registering platform 'homebridge-tplink-smarthome.TplinkSmarthome'
[20/05/2023, 10:56:50] ---
[20/05/2023, 10:56:50] Loading 9 platforms...
[20/05/2023, 10:56:50] [Hue] Initializing Hue platform...
[20/05/2023, 10:56:50] [Hue] homebridge-hue v0.13.61, node v18.16.0, homebridge v1.6.1
[20/05/2023, 10:56:50] [Hue] warning: planned changes, see https://github.com/ebaauw/homebridge-hue/issues/1070
[20/05/2023, 10:56:50] [Hue] config.json: nupnp: invalid key
[20/05/2023, 10:56:52] [Hue] zigbee-gw: dresden elektronik deCONZ gateway v2.21.2, api v1.16.0
[20/05/2023, 10:56:52] [Hue] zigbee-gw: warning: support for deCONZ will be deprecated in favour of Homebridge deCONZ
[20/05/2023, 10:57:01] [Hue] zigbee-gw: request 1: GET /
[20/05/2023, 10:57:01] [Hue] zigbee-gw: request 1: timeout after 5 seconds
[20/05/2023, 10:57:01] [Hue] zigbee-gw: timeout after 5 seconds - retrying in 15s
[20/05/2023, 10:57:18] [Hue] zigbee-gw: dresden elektronik deCONZ gateway v2.21.2, api v1.16.0
[20/05/2023, 10:57:18] [Hue] zigbee-gw: warning: support for deCONZ will be deprecated in favour of Homebridge deCONZ
[20/05/2023, 10:57:20] [Hue] zigbee-gw: 21 accessories
[20/05/2023, 10:57:20] [Hue] zigbee-gw: websocket connected to ws://localhost:4531
[20/05/2023, 10:57:20] [Hue] masked debug info dumped to /var/lib/homebridge/homebridge-hue.json.gz
[20/05/2023, 10:57:20] Initializing platform accessory 'zigbee-gw'...
[20/05/2023, 10:57:20] [Hue] zigbee-gw: 4 services
[20/05/2023, 10:57:20] [Hue] homebridge: error: Cannot add a Service with the same UUID '00000012-0000-1000-8000-656261617577' as another Service in this Accessory without also defining a unique 'subtype' property.

Debug Files

homebridge-hue.json.gz

ebaauw commented 1 year ago

00000012-0000-1000-8000-656261617577 is the UUID of the Hue Bridge service (that holds Heartrate, Transition Time, etc. Looks like the timeout on GET / isn't handled correctly and causes the bridge to be exposed again, erroneously creating a second instance of this service. Strictly speaking, this is a bug, but I don't think I'll be fixing it. The startup sequence of Homebridge Hue, still a static platform accessories plugin, is delegate, and I daren't touch it, without extensive testing. I'd rather spend my time on Homebridge deCONZ and Homebridge Hue2.

Since this is related to the system load, I suggest giving the deCONZ gateway a bit more time to answer, before timing out, by setting timeout in config.json to 15 or 30 seconds. I suppose that when the system is under load, the GET / gets issued at a later time, where it is less likely to timeout.

Is this when just restarting Homebridge, or when rebooting the server, also restarting deCONZ? In that case, you might want to add a delay before launching Homebridge, making sure deCONZ has initialised when Homebridge Hue starts. Also, running Homebridge Hue in a child bridge will cause it to start later, and allows you to restart only the child bridge, should Homebridge Hue still end up in startup loop. I would also shield Homebridge Hue from other plugins potentially blocking NodeJS, and contributing to the timeout.

rossbacher commented 1 year ago

Increasing the timeout actually seemes to have fixed it (I just did 10 restarts and it started fine every time, without the artificial load "trick").

This is happening on both Homebridge restart and and when the server is rebooting. I already did play with the deCONZ <-> Homebridge timing and ensured that Homebridge starts after deCONZ.

Also totally understand this is a wontfix thank you very much for looking into it!