jason0x43 / hacs-hubitat

A Hubitat integration for Home Assistant
MIT License
203 stars 47 forks source link

Janky behavior and occasional errors controlling groups of lights #152

Open evelant opened 2 years ago

evelant commented 2 years ago

I've got a bunch of smart bulbs exposed to ha via Hubitat. I have the bulbs in ha groups. When I control the groups the behavior is "jittery", the sliders for level or color temperature will jump all over the place when changed and sometimes the correct values don't get set.

Here is what I see in the logs when I tap the color temperature slider a single time on one of my light groups -- it looks like it sends both an on and a setColorTemperature twice to each light.

2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 1 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 2 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 975
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 3 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 4 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 5 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 978
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 6 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 979
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 7 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 980
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 8 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 981
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 1 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 2 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 975
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 3 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 4 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 5 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 978
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 6 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 979
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 7 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 980
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 8 with {'color_temp': 224}
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command on(None) to 981
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 979
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 979
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 977
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 976
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 978
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 978
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 981
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 981
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 974
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 980
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 980
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 975
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 975
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 978
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 978
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 975
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 975
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 981
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 981
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 979
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 979
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 974
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 977
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 976
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 979
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 980
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 980
2021-12-06 10:19:47 DEBUG (MainThread) [hubitatmaker.hub] Sending command setColorTemperature(4464) to 980
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 978
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 981
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 974
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 975
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 977
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 976
2021-12-06 10:19:47 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 980
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 4', 'deviceId': '977', 'descriptionText': 'Kitchen Lights Bulb 4 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 977 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 4', 'deviceId': '977', 'descriptionText': 'Kitchen Lights Bulb 4 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 977 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 1', 'deviceId': '974', 'descriptionText': 'Kitchen Lights Bulb 1 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 974 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 1', 'deviceId': '974', 'descriptionText': 'Kitchen Lights Bulb 1 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 974 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 6', 'deviceId': '979', 'descriptionText': 'Kitchen Lights Bulb 6 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 979 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 6', 'deviceId': '979', 'descriptionText': 'Kitchen Lights Bulb 6 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 979 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 7', 'deviceId': '980', 'descriptionText': 'Kitchen Lights Bulb 7 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 980 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 7', 'deviceId': '980', 'descriptionText': 'Kitchen Lights Bulb 7 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 980 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 5', 'deviceId': '978', 'descriptionText': 'Kitchen Lights Bulb 5 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 978 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 5', 'deviceId': '978', 'descriptionText': 'Kitchen Lights Bulb 5 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 978 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 3', 'deviceId': '976', 'descriptionText': 'Kitchen Lights Bulb 3 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 976 to 4464
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 3', 'deviceId': '976', 'descriptionText': 'Kitchen Lights Bulb 3 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 976 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Horizon', 'displayName': 'Kitchen Lights Bulb 8', 'deviceId': '981', 'descriptionText': 'Kitchen Lights Bulb 8 color was set to Horizon', 'unit': None, 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorName of 981 to Horizon
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'colorTemperature', 'value': '4464', 'displayName': 'Kitchen Lights Bulb 8', 'deviceId': '981', 'descriptionText': 'Kitchen Lights Bulb 8 colorTemperature was set to 4464°K', 'unit': '°K', 'type': None, 'data': None}
2021-12-06 10:19:48 DEBUG (MainThread) [hubitatmaker.hub] Updating colorTemperature of 981 to 4464
2021-12-06 10:19:49 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [547239546400] Connection closed by client

I also occasionally get an error from the integration about decoding json with an unexpected mime type. This doesn't always happen, maybe 1/10 times when controlling a group of lights.

Here are the relevant logs for the mime type error:

2021-12-06 10:19:47 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [547264609584] 0, message='Attempt to decode JSON with unexpected mimetype: text/html;charset=utf-8', url=URL('http://192.168.1.25/apps/api/555/devices/975/setColorTemperature/4464?access_token= my_token_here')
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
await handler.job.target(service_call)
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
await self.hass.helpers.service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 667, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 863, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 704, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 496, in async_handle_light_on_service
await light.async_turn_on(**filter_turn_on_params(light, params))
File "/usr/src/homeassistant/homeassistant/components/group/light.py", line 160, in async_turn_on
await self.hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
await handler.job.target(service_call)
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
await self.hass.helpers.service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 667, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 863, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 704, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 496, in async_handle_light_on_service
await light.async_turn_on(**filter_turn_on_params(light, params))
File "/config/custom_components/hubitat/light.py", line 235, in async_turn_on
await self.send_command(CMD_SET_COLOR_TEMP, props["temp"])
File "/config/custom_components/hubitat/device.py", line 156, in send_command
await self._hub.send_command(self.device_id, command, arg)
File "/config/custom_components/hubitat/hub.py", line 381, in send_command
await self._hub.send_command(device_id, command, arg)
File "/usr/local/lib/python3.9/site-packages/hubitatmaker/hub.py", line 219, in send_command
return await self._api_request(path)
File "/usr/local/lib/python3.9/site-packages/hubitatmaker/hub.py", line 380, in _api_request
json = await resp.json()
File "/usr/local/lib/python3.9/site-packages/aiohttp/client_reqrep.py", line 1097, in json
raise ContentTypeError(
aiohttp.client_exceptions.ContentTypeError: 0, message='Attempt to decode JSON with unexpected mimetype: text/html;charset=utf-8', url=URL('http://192.168.1.25/apps/api/555/devices/975/setColorTemperature/4464?access_token=my_token_here')
jason0x43 commented 2 years ago

Hmmm...I haven't seen that issue before. Do you see duplicate commands if you control lights individually vs through groups?

evelant commented 2 years ago

Hmm it doesn't seem to be sending duplicates when I control an individual light, but I do see some odd behavior.

It generally goes like this:

  1. Tap a different value on a brightness or color temp slider on the UI
  2. Slider jumps back to initial position or somewhere in between
  3. Later the slider (sometimes) jumps to the position I set

Looking at the logs I see things like this

2021-12-06 18:35:28 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Kitchen Lights Bulb 1 with {'brightness': 145}
2021-12-06 18:35:28 DEBUG (MainThread) [hubitatmaker.hub] Sending command setLevel(56) to 974
2021-12-06 18:35:28 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 974
2021-12-06 18:35:28 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'level', 'value': '75', 'displayName': 'Kitchen Lights Bulb 1', 'deviceId': '974', 'descriptionText': 'Kitchen Lights Bulb 1 level was set to 75%', 'unit': '%', 'type': None, 'data': None}
2021-12-06 18:35:28 DEBUG (MainThread) [hubitatmaker.hub] Updating level of 974 to 75
2021-12-06 18:35:33 DEBUG (MainThread) [hubitatmaker.hub] Received event: {'name': 'level', 'value': '56', 'displayName': 'Kitchen Lights Bulb 1', 'deviceId': '974', 'descriptionText': 'Kitchen Lights Bulb 1 level was set to 56%', 'unit': '%', 'type': None, 'data': None}
2021-12-06 18:35:33 DEBUG (MainThread) [hubitatmaker.hub] Updating level of 974 to 56

It looks like Hubitat is sending back the current value of the bulb immediately when a command is issued which causes the UI to jump back to original position (or jump all over the place for groups) until another message comes in with the result of the command.

edit: Could it be the Hubitat driver for the bulbs? These are all sengled element color plus bulbs using the built in Hubitat sengled driver.

ben-bays commented 2 years ago

I see the same error when using call service to turn on a single switch from node-red. I have a variety of Z-Wave switches in my house, and I'll see the error for any of them.

2022-04-03 09:46:41 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [548092072672] 0, message='Attempt to decode JSON with unexpected mimetype: text/html;charset=utf-8', url=URL('http://10.0.0.57/apps/api/205/devices/263/on?access_token=xxxxxx')
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 192, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1636, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1673, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 671, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 949, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 708, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 504, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/config/custom_components/hubitat/light.py", line 226, in async_turn_on
    await self.send_command(CMD_ON)
  File "/config/custom_components/hubitat/device.py", line 158, in send_command
    await self._hub.send_command(self.device_id, command, arg)
  File "/config/custom_components/hubitat/hub.py", line 381, in send_command
    await self._hub.send_command(device_id, command, arg)
  File "/usr/local/lib/python3.9/site-packages/hubitatmaker/hub.py", line 219, in send_command
    return await self._api_request(path)
  File "/usr/local/lib/python3.9/site-packages/hubitatmaker/hub.py", line 380, in _api_request
    json = await resp.json()
  File "/usr/local/lib/python3.9/site-packages/aiohttp/client_reqrep.py", line 1103, in json
    raise ContentTypeError(

I see no corresponding error in the habitat log. In fact, the command to turn the switch on/off usually works despite an error being logged. If I plug the link in my web browser, I'm able to access the JSON no problem.

jason0x43 commented 2 years ago

It looks like Hubitat is returning an error page. Do you see it every time you try to control a switch?

ben-bays commented 2 years ago

It looks like Hubitat is returning an error page. Do you see it every time you try to control a switch?

No, but it does appear at least once a day during normal activity. I haven't been able to identify any patterns as of yet.

I have the switches mapped as "lights" in Home Assistant's Hubitat integration. I'm playing around with converting them to straight switches. I'm hoping this might also fix an issue I have where I don't see whether an event has a type of "physical" or not.

ben-bays commented 2 years ago

I see this JSON when I navigate to the URL in my browser.

{"id":"263","name":"Generic Z-Wave Plus Scene Switch","label":"Upstairs Bathroom Light","type":"Generic Z-Wave Plus Scene Switch","attributes":[{"name":"doubleTapped","currentValue":1,"dataType":"NUMBER"},{"name":"held","currentValue":2,"dataType":"NUMBER"},{"name":"numberOfButtons","currentValue":2,"dataType":"NUMBER"},{"name":"pushed","currentValue":1,"dataType":"NUMBER"},{"name":"released","currentValue":2,"dataType":"NUMBER"},{"name":"switch","currentValue":"off","dataType":"ENUM","values":["on","off"]}],"capabilities":["Configuration","Actuator","Refresh","HoldableButton",{"attributes":[{"name":"held","dataType":null}]},"ReleasableButton",{"attributes":[{"name":"released","dataType":null}]},"Switch",{"attributes":[{"name":"switch","dataType":null}]},"PushableButton",{"attributes":[{"name":"numberOfButtons","dataType":null},{"name":"pushed","dataType":null}]},"DoubleTapableButton",{"attributes":[{"name":"doubleTapped","dataType":null}]}],"commands":["configure","doubleTap","hold","off","on","push","refresh","release"]}
jason0x43 commented 2 years ago

As far as the "on" command and the physical vs digital event data go, it shouldn't matter whether the device is a light or a switch. At least, Hubitat is going to send the same data over regardless of what HA classifies the device as, and both switches and lights use the same "on" command (e.g., http://10.0.0.57/apps/api/205/devices/263/on).

If the error is sporadic, it could be that the Hubitat is overloaded for some reason and is returning temporary error page. I'll see about updating the communication code to output the HTML page to the debug log.

hbh7 commented 11 months ago

Hi all, I'm experiencing the same issue actually. I haven't figured out how to gather and go through all the logs yet, but I've got basically the same setup (same bulbs, hubitat, node red, home assistant), behaviors, and issues. Happy to provide more info once I'm able to dive in further for debugging, or if someone can give me a high level overview.

I also have some variety in my setup, so I can compare behaviors too. I've noticed that in node red on home assistant, if I use the call service with data, the light won't turn on (but will have the right color when next turned on). I have to send an additional empty data (the only difference) turn on call. image image The tuya wifi bulbs don't have any issue with the single call with data. They also respond much more quickly and reliably, although I suspect my zigbee network is rather weak (work in progress) and that might be a big part of it. I've had similar behavior directly in the hubitat UI, but I think it's at least a little worse on home assistant. I just haven't had time or varied enough resources for any extensive testing of anything yet haha.

I'd love to help debug and hopefully get this fixed :)

jason0x43 commented 11 months ago

if I use the call service with data, the light won't turn on (but will have the right color when next turned on). I have to send an additional empty data (the only difference) turn on call.

It will be a bit easier to see what's going on when you enable debug logging and look at the Home Assistant log. Calling the light.turn_on service and setting a color should look something like this (here I'm sending the call to a Home Assistant light group with two RGB lights):

2023-12-29 23:21:57.892 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2023-12-29 23:21:57.892 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2023-12-29 23:21:57.894 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Virtual RGB Light 2 with {'hs_color': (285.405, 78.307)}
2023-12-29 23:21:57.894 DEBUG (MainThread) [custom_components.hubitat.light] Light Virtual RGB Light 2 turn-on props: {'hue': 79, 'sat': 78.307}
2023-12-29 23:21:57.894 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 10
2023-12-29 23:21:57.896 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Virtual RGB Light with {'hs_color': (285.405, 78.307)}
2023-12-29 23:21:57.896 DEBUG (MainThread) [custom_components.hubitat.light] Light Virtual RGB Light turn-on props: {'hue': 79, 'sat': 78.307}
2023-12-29 23:21:57.896 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 6
2023-12-29 23:21:57.984 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 10
2023-12-29 23:21:57.984 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColor({"hue": 79, "saturation": 78.307, "level": 100}) to 10
2023-12-29 23:21:57.989 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 6
2023-12-29 23:21:57.989 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColor({"hue": 79, "saturation": 78.307, "level": 100}) to 6
2023-12-29 23:21:58.036 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Virtual RGB Light 2', 'deviceId': '10', 'descriptionText': 'Virtual RGB Light 2 switch was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-29 23:21:58.036 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 10 to on (None)
2023-12-29 23:21:58.052 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Virtual RGB Light', 'deviceId': '6', 'descriptionText': 'Virtual RGB Light switch was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-29 23:21:58.052 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 6 to on (None)
2023-12-29 23:21:58.103 DEBUG (MainThread) [custom_components.hubitat.device] sent setColor to 10
2023-12-29 23:21:58.130 DEBUG (MainThread) [custom_components.hubitat.device] sent setColor to 6
2023-12-29 23:21:58.141 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Violet', 'displayName': 'Virtual RGB Light 2', 'deviceId': '10', 'descriptionText': 'Virtual RGB Light 2 colorName is Violet', 'unit': None, 'type': None, 'data': None}
2023-12-29 23:21:58.141 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorName of 10 to Violet (None)
2023-12-29 23:21:58.145 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'hue', 'value': '79', 'displayName': 'Virtual RGB Light 2', 'deviceId': '10', 'descriptionText': 'Virtual RGB Light 2 hue was set to 79%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 23:21:58.146 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating hue of 10 to 79 (%)
2023-12-29 23:21:58.224 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'saturation', 'value': '78', 'displayName': 'Virtual RGB Light 2', 'deviceId': '10', 'descriptionText': 'Virtual RGB Light 2 saturation was set to 78%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 23:21:58.224 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating saturation of 10 to 78 (%)
2023-12-29 23:21:58.264 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'hue', 'value': '79', 'displayName': 'Virtual RGB Light', 'deviceId': '6', 'descriptionText': 'Virtual RGB Light hue was set to 79%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 23:21:58.264 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating hue of 6 to 79 (%)
2023-12-29 23:21:58.270 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Violet', 'displayName': 'Virtual RGB Light', 'deviceId': '6', 'descriptionText': 'Virtual RGB Light colorName is Violet', 'unit': None, 'type': None, 'data': None}
2023-12-29 23:21:58.270 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorName of 6 to Violet (None)
2023-12-29 23:21:58.362 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'saturation', 'value': '78', 'displayName': 'Virtual RGB Light', 'deviceId': '6', 'descriptionText': 'Virtual RGB Light saturation was set to 78%', 'unit': '%', 'type': None, 'data': None}

The key things are that an on command is sent to each light in the group, and then a setColor command is sent to each light. At some point after each command is sent, Hubitat will respond with one or more events indicating the new state of the target light device.

If the expected commands are being sent, then lights should be updating. If they're not, there's likely an issue somewhere on the Hubitat side (either in Hubitat itself or with the light network) that I can try to work around if we can nail down what it is.

hbh7 commented 11 months ago

Alright, I spent some more time debugging, and after getting very confused about things suddenly working, I've got some more information.

At some point in my testing, I updated to v0.9.10 after reading the changelog and not thinking anything of it. Turns out it fixed a bunch of things related to this. I don't have the issue where scenes don't turn on the bulbs anymore, or the one where the call service with data wasn't turning the bulb on. I've got some logs to compare the versions too.

This is on v0.9.8 turning on 3 lights using a scene with SmartBulb7 already on. All bulbs change to the set color data, but 1 and 6 do not turn on.

2023-12-29 20:59:18.907 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 20:59:18.908 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 72
2023-12-29 20:59:18.908 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb1 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 20:59:18.909 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 67
2023-12-29 20:59:18.910 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb6 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 20:59:18.910 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 71
2023-12-29 20:59:19.193 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 71
2023-12-29 20:59:19.193 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 71
2023-12-29 20:59:19.198 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 72
2023-12-29 20:59:19.199 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 72
2023-12-29 20:59:19.245 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 67
2023-12-29 20:59:19.246 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 67
2023-12-29 20:59:19.253 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 20:59:19.253 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 100 (%)
2023-12-29 20:59:19.260 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 20:59:19.261 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 67 to 100 (%)
2023-12-29 20:59:19.492 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 71
2023-12-29 20:59:19.537 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 67
2023-12-29 20:59:19.541 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 72
2023-12-29 20:59:20.269 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 20:59:20.270 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 72 to 100 (%)

This is on v0.9.10 turning on 3 lights using a scene with SmartBulb7 already on. All bulbs change to the set color data, and 1 and 6 now do turn on.

2023-12-29 21:32:00.820 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 21:32:00.821 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb7 turn-on props: {'temp': 2000}
2023-12-29 21:32:00.821 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 72
2023-12-29 21:32:00.822 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb6 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 21:32:00.822 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb6 turn-on props: {'temp': 2000}
2023-12-29 21:32:00.822 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 71
2023-12-29 21:32:00.823 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb1 with {'brightness': 255, 'color_temp': 500, 'color_temp_kelvin': 2000}
2023-12-29 21:32:00.823 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb1 turn-on props: {'temp': 2000}
2023-12-29 21:32:00.823 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 67
2023-12-29 21:32:01.526 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 71
2023-12-29 21:32:01.526 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 71
2023-12-29 21:32:01.530 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 67
2023-12-29 21:32:01.530 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 67
2023-12-29 21:32:01.541 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 72
2023-12-29 21:32:01.541 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2000) to 72
2023-12-29 21:32:01.758 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '1', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 1%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:01.758 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 1 (%)
2023-12-29 21:32:01.768 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-29 21:32:01.768 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 71 to on (None)
2023-12-29 21:32:01.820 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '1', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 level was set to 1%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:01.820 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 67 to 1 (%)
2023-12-29 21:32:01.823 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-29 21:32:01.823 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 67 to on (None)
2023-12-29 21:32:01.878 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 72
2023-12-29 21:32:01.920 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 71
2023-12-29 21:32:01.964 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 67
2023-12-29 21:32:02.597 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '80', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 80%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:02.597 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 80 (%)
2023-12-29 21:32:02.700 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '79', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 level was set to 79%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:02.700 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 67 to 79 (%)
2023-12-29 21:32:03.588 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '81', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 81%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:03.588 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 81 (%)
2023-12-29 21:32:03.695 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:32:03.696 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 67 to 100 (%)

This is on v0.9.8 turning on a light using Node-Red with the previously mentioned call service + data setup. The light does not turn on.

2023-12-29 21:26:53.551 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb2 with {'brightness': 100, 'color_temp': 370, 'color_temp_kelvin': 2700}
2023-12-29 21:26:53.551 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(39) to 66
2023-12-29 21:26:53.779 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 66
2023-12-29 21:26:53.779 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2702) to 66
2023-12-29 21:26:53.806 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '39', 'displayName': 'Sengled-SmartBulb2', 'deviceId': '66', 'descriptionText': 'Sengled-SmartBulb2 level was set to 39%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:26:53.806 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 66 to 39 (%)
2023-12-29 21:26:54.048 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 66

This is on v0.9.10 turning on a light using Node-Red with the previously mentioned call service + data setup. The light now does turn on.

2023-12-29 21:47:38.311 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb2 with {'brightness': 100, 'color_temp': 370, 'color_temp_kelvin': 2700}
2023-12-29 21:47:38.312 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb2 turn-on props: {'temp': 2702}
2023-12-29 21:47:38.312 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 66
2023-12-29 21:47:38.586 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 66
2023-12-29 21:47:38.587 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(2702) to 66
2023-12-29 21:47:38.692 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Sengled-SmartBulb2', 'deviceId': '66', 'descriptionText': 'Sengled-SmartBulb2 was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-29 21:47:38.692 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 66 to on (None)
2023-12-29 21:47:38.717 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '1', 'displayName': 'Sengled-SmartBulb2', 'deviceId': '66', 'descriptionText': 'Sengled-SmartBulb2 level was set to 1%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:47:38.717 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 66 to 1 (%)
2023-12-29 21:47:38.857 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 66
2023-12-29 21:47:39.676 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '79', 'displayName': 'Sengled-SmartBulb2', 'deviceId': '66', 'descriptionText': 'Sengled-SmartBulb2 level was set to 79%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:47:39.676 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 66 to 79 (%)
2023-12-29 21:47:40.670 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb2', 'deviceId': '66', 'descriptionText': 'Sengled-SmartBulb2 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 21:47:40.670 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 66 to 100 (%)

Something else of possible interest is the settings I'm using in Hubitat for the Sengled bulbs. I think the attribute reporting interval combined with the transition time and/or prestaging might be why the color/hue/brightness bars jump around when changing. From the logs at least, it seems to match up to the 1s reporting interval, but over 3 seconds which doesn't really add up to me (lot more than 500ms as set). image

I also ran into the json parse error when turning off a nested group (using the off switch on an entities card with 3 lights and 1 light group which contains those 3 lights). Looks like it doesn't realize the containment and therefore sends the the commands twice, but I'm not sure why the json parse fails as it seems valid to me.... Something within the data failing validation then perhaps? Is it just that it's set as html and therefore it doesn't even try to parse as json? Is the mime type being wrong a hubitat / maker api issue, or does the request specify the return type?

2023-12-29 22:12:03.541 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb12
2023-12-29 22:12:03.541 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 77
2023-12-29 22:12:03.543 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb5
2023-12-29 22:12:03.544 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 70
2023-12-29 22:12:03.544 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb4
2023-12-29 22:12:03.544 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 69
2023-12-29 22:12:03.545 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb12
2023-12-29 22:12:03.545 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 77
2023-12-29 22:12:03.545 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb5
2023-12-29 22:12:03.545 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 70
2023-12-29 22:12:03.546 DEBUG (MainThread) [custom_components.hubitat.light] Turning off Sengled-SmartBulb4
2023-12-29 22:12:03.546 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command off(None) to 69
2023-12-29 22:12:03.850 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 70
2023-12-29 22:12:03.851 WARNING (MainThread) [custom_components.hubitat.hubitatmaker.hub] Unable to parse as JSON: {"id":"70","name":"Sengled Element Plus","label":"Sengled-SmartBulb5","type":"Sengled Element Color Plus","room":null,"attributes":[{"name":"colorName","currentValue":"Red","dataType":"STRING"},{"name":"RGB","currentValue":null,"dataType":"STRING"},{"name":"colorTemperature","currentValue":2000,"dataType":"NUMBER"},{"name":"saturation","currentValue":67,"dataType":"NUMBER"},{"name":"switch","currentValue":"on","dataType":"ENUM","values":["on","off"]},{"name":"hue","currentValue":2,"dataType":"NUMBER"},{"name":"color","currentValue":null,"dataType":"STRING"},{"name":"colorMode","currentValue":"RGB","dataType":"ENUM","values":["CT","RGB"]},{"name":"colorName","currentValue":"Red","dataType":"STRING"},{"name":"switch","currentValue":"on","dataType":"ENUM","values":["on","off"]},{"name":"level","currentValue":1,"dataType":"NUMBER"}],"capabilities":["Configuration","Actuator","ColorTemperature",{"attributes":[{"name":"colorTemperature","dataType":null},{"name":"colorName","dataType":null}]},"ColorMode",{"attributes":[{"name":"colorMode","dataType":null}]},"ColorControl",{"attributes":[{"name":"hue","dataType":null},{"name":"saturation","dataType":null},{"name":"color","dataType":null},{"name":"colorName","dataType":null},{"name":"RGB","dataType":null}]},"ChangeLevel","SwitchLevel",{"attributes":[{"name":"level","dataType":null}]},"Light",{"attributes":[{"name":"switch","dataType":null}]},"Switch",{"attributes":[{"name":"switch","dataType":null}]}],"commands":["configure","off","on","refresh","setColor","setColorTemperature","setHue","setLevel","setSaturation","startLevelChange","stopLevelChange","updateFirmware"]}
2023-12-29 22:12:03.852 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] GET request to devices/70/off failed with 0, message='Attempt to decode JSON with unexpected mimetype: text/html;charset=utf-8', url=URL('https://<hubitat>/apps/api/35/devices/70/off?access_token=<token>'). Retrying...
2023-12-29 22:12:03.858 WARNING (MainThread) [custom_components.hubitat.hubitatmaker.hub] Unable to parse as JSON: {"id":"77","name":"Sengled Element Plus","label":"Sengled-SmartBulb12","type":"Sengled Element Color Plus","room":null,"attributes":[{"name":"colorName","currentValue":"Sodium","dataType":"STRING"},{"name":"RGB","currentValue":null,"dataType":"STRING"},{"name":"colorTemperature","currentValue":2000,"dataType":"NUMBER"},{"name":"saturation","currentValue":93,"dataType":"NUMBER"},{"name":"switch","currentValue":"on","dataType":"ENUM","values":["on","off"]},{"name":"hue","currentValue":4,"dataType":"NUMBER"},{"name":"color","currentValue":null,"dataType":"STRING"},{"name":"colorMode","currentValue":"CT","dataType":"ENUM","values":["CT","RGB"]},{"name":"colorName","currentValue":"Sodium","dataType":"STRING"},{"name":"switch","currentValue":"on","dataType":"ENUM","values":["on","off"]},{"name":"level","currentValue":1,"dataType":"NUMBER"}],"capabilities":["Configuration","Actuator","ColorTemperature",{"attributes":[{"name":"colorTemperature","dataType":null},{"name":"colorName","dataType":null}]},"ColorMode",{"attributes":[{"name":"colorMode","dataType":null}]},"ColorControl",{"attributes":[{"name":"hue","dataType":null},{"name":"saturation","dataType":null},{"name":"color","dataType":null},{"name":"colorName","dataType":null},{"name":"RGB","dataType":null}]},"ChangeLevel","SwitchLevel",{"attributes":[{"name":"level","dataType":null}]},"Light",{"attributes":[{"name":"switch","dataType":null}]},"Switch",{"attributes":[{"name":"switch","dataType":null}]}],"commands":["configure","off","on","refresh","setColor","setColorTemperature","setHue","setLevel","setSaturation","startLevelChange","stopLevelChange","updateFirmware"]}
2023-12-29 22:12:03.859 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] GET request to devices/77/off failed with 0, message='Attempt to decode JSON with unexpected mimetype: text/html;charset=utf-8', url=URL('https://<hubitat>/apps/api/35/devices/77/off?access_token=<token>'). Retrying...
2023-12-29 22:12:03.860 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 77
2023-12-29 22:12:03.870 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 69
2023-12-29 22:12:03.963 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 69
2023-12-29 22:12:04.498 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'off', 'displayName': 'Sengled-SmartBulb5', 'deviceId': '70', 'descriptionText': 'Sengled-SmartBulb5 was turned off', 'unit': None, 'type': None, 'data': None}
2023-12-29 22:12:04.498 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 70 to off (None)
2023-12-29 22:12:04.556 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'off', 'displayName': 'Sengled-SmartBulb12', 'deviceId': '77', 'descriptionText': 'Sengled-SmartBulb12 was turned off', 'unit': None, 'type': None, 'data': None}
2023-12-29 22:12:04.556 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 77 to off (None)
2023-12-29 22:12:04.584 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'off', 'displayName': 'Sengled-SmartBulb4', 'deviceId': '69', 'descriptionText': 'Sengled-SmartBulb4 was turned off', 'unit': None, 'type': None, 'data': None}
2023-12-29 22:12:04.584 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 69 to off (None)
2023-12-29 22:12:04.654 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 70
2023-12-29 22:12:04.670 DEBUG (MainThread) [custom_components.hubitat.device] sent off to 77
2023-12-29 22:12:04.689 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '0', 'displayName': 'Sengled-SmartBulb5', 'deviceId': '70', 'descriptionText': 'Sengled-SmartBulb5 level was set to 0%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 22:12:04.689 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 70 to 0 (%)
2023-12-29 22:12:04.694 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '0', 'displayName': 'Sengled-SmartBulb12', 'deviceId': '77', 'descriptionText': 'Sengled-SmartBulb12 level was set to 0%', 'unit': '%', 'type': None, 'data': None}
2023-12-29 22:12:04.694 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 77 to 0 (%)

Anywho, thanks for working through this with me and for your changes in the latest updates!

jason0x43 commented 11 months ago

Thanks for the logs! Interesting...

I'd guess some lights weren't turning on with 0.9.8 because they weren't being sent an explicit on command. Some lights will turn on with just a setLevel, but some bulbs need an explicit on.

I think the attribute reporting interval combined with the transition time and/or prestaging might be why the color/hue/brightness bars jump around when changing.

Yeah, if the transition is implemented manually by Hubitat, or the bulbs are sending Hubitat, multiple updates while transitioning, it could result in Hubitat is sending a series of update events as each bulb settles, which could make things jump around a bit.

The JSON error is very interesting. That's the first time I've actually seen data with that error (I finally added some logging for that in April, but this is the first time I've seen output from it). It looks like the message content is valid JSON, but for some reason Hubitat gave it the content type of text/html, which confused the response parser.

Hopefully 0.9.10 has taken care of most of the issues. I just published 0.9.11 with a workaround for the "Unable to parse as JSON" errors.

hbh7 commented 11 months ago

Makes sense with the transition stuff, I imagine that's a limitation of the bulb reporting then, which I imagine is either bulb firmware or the driver in Hubitat. Unfortunate but not the problem of this integration I don't think. :)

Looks like the JSON error is gone too now! I imagine that's a bug in the Maker API maybe? Wonder if there's an issue open for it...

Unfortunately I think I found a new problem haha. Using the built in home assistant sliders and such no longer works lol. I'm on 0.9.11 and the new Hubitat update that just came out, but I think it's the integration. Here's some logs from me clicking the slider to two different brightnesses.

2023-12-30 13:48:21.553 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 235}
2023-12-30 13:48:21.553 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb7 turn-on props: {}
2023-12-30 13:48:21.553 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 72
2023-12-30 13:48:21.812 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 72
2023-12-30 13:48:30.168 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 89}
2023-12-30 13:48:30.169 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb7 turn-on props: {}
2023-12-30 13:48:30.169 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 72
2023-12-30 13:48:30.420 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 72

Looks like perhaps it's forgetting to send the brightness info and only sending the turn on command? Using scenes to change doesn't seem to work anymore either, log below (do note that bulb1 isn't responding properly and can be ignored, but the other two definitely aren't changing, only turning on)

2023-12-30 13:54:38.121 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb1 with {'brightness': 7, 'hs_color': (10.8, 93.0)}
2023-12-30 13:54:38.121 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb1 turn-on props: {'hue': 3, 'sat': 93.0}
2023-12-30 13:54:38.121 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 67
2023-12-30 13:54:38.123 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 7, 'hs_color': (3.6, 92.0)}
2023-12-30 13:54:38.124 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb7 turn-on props: {'hue': 1, 'sat': 92.0}
2023-12-30 13:54:38.124 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 72
2023-12-30 13:54:38.124 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb6 with {'brightness': 7, 'hs_color': (14.4, 92.0)}
2023-12-30 13:54:38.124 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb6 turn-on props: {'hue': 4, 'sat': 92.0}
2023-12-30 13:54:38.124 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command on(None) to 71
2023-12-30 13:54:38.386 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 67
2023-12-30 13:54:38.386 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColor({"hue": 3, "saturation": 93.0, "level": 0}) to 67
2023-12-30 13:54:38.397 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 72
2023-12-30 13:54:38.398 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColor({"hue": 1, "saturation": 92.0, "level": 69}) to 72
2023-12-30 13:54:38.402 DEBUG (MainThread) [custom_components.hubitat.device] sent on to 71
2023-12-30 13:54:38.402 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColor({"hue": 4, "saturation": 92.0, "level": 100}) to 71
2023-12-30 13:54:38.648 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-30 13:54:38.649 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 71 to on (None)
2023-12-30 13:54:38.715 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'switch', 'value': 'on', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 was turned on', 'unit': None, 'type': None, 'data': None}
2023-12-30 13:54:38.715 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating switch of 72 to on (None)
2023-12-30 13:54:38.721 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '1', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 level was set to 1%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:38.721 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 72 to 1 (%)
2023-12-30 13:54:38.737 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '1', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 1%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:38.737 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 1 (%)
2023-12-30 13:54:38.743 DEBUG (MainThread) [custom_components.hubitat.device] sent setColor to 67
2023-12-30 13:54:38.829 DEBUG (MainThread) [custom_components.hubitat.device] sent setColor to 72
2023-12-30 13:54:38.842 DEBUG (MainThread) [custom_components.hubitat.device] sent setColor to 71
2023-12-30 13:54:39.609 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '84', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 84%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:39.609 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 84 (%)
2023-12-30 13:54:39.678 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '62', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 level was set to 62%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:39.679 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 72 to 62 (%)
2023-12-30 13:54:40.531 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:40.531 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 100 (%)
2023-12-30 13:54:40.607 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '69', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 level was set to 69%', 'unit': '%', 'type': None, 'data': None}
2023-12-30 13:54:40.607 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 72 to 69 (%)

I think it might be responding to color temp changes (but not RGB color changes) with the scenes, but I didn't mess with it enough to know if it reliably is changing. Brightness definitely isn't changing, but the bulbs are turned on if off.

One more round of debugging? :)

hbh7 commented 11 months ago

Actually, I've been playing around more with manually changing colors, that seems functional but Home Assistant isn't realizing the change. I can see in the Hubitat device view that things are changing.

Changing white temperature seems to work and report back properly.

Brightness is not getting sent or updating.

On/off works fine.

jason0x43 commented 10 months ago

The issue there happened when I refactored the light entity to use the color_modes property when deciding how to handle light properties passed to the turn_on on command. The entity was only paying attention to the brightness property if the light reported that it supported ColorMode.BRIGHTNESS. However, a light should only report ColorMode.BRIGHTNESS if brightness is the only thing it supports, so RGB and color temp bulbs don't report that mode, which caused the integration to ignore the brightness property.

This is fixed in v0.9.14.

hbh7 commented 10 months ago

Thanks for all your help so far, but unfortunately I think something's still amis. I'm on Hubitat 2.3.7.145, integration v0.9.19, and HomeAssistant (core) 2024.1.1.

Log during scene change to full brightness daylight white, where all but bulb 7 are off, at minimum brightness, and blue. Only bulb 7 visually changes, but the others are at the correct settings once manually turned on.

2024-01-05 19:24:26.779 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb6 with {'brightness': 255, 'color_temp': 254, 'color_temp_kelvin': 3937}
2024-01-05 19:24:26.779 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb6 turn-on props: {'level': 100, 'temp': 3937}
2024-01-05 19:24:26.780 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 71
2024-01-05 19:24:26.781 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb7 with {'brightness': 255, 'color_temp': 254, 'color_temp_kelvin': 3937}
2024-01-05 19:24:26.781 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb7 turn-on props: {'level': 100, 'temp': 3937}
2024-01-05 19:24:26.781 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 72
2024-01-05 19:24:26.782 DEBUG (MainThread) [custom_components.hubitat.light] Turning on Sengled-SmartBulb1 with {'brightness': 255, 'color_temp': 254, 'color_temp_kelvin': 3937}
2024-01-05 19:24:26.782 DEBUG (MainThread) [custom_components.hubitat.light] Light Sengled-SmartBulb1 turn-on props: {'level': 100, 'temp': 3937}
2024-01-05 19:24:26.782 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setLevel(100) to 67
2024-01-05 19:24:27.076 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 72
2024-01-05 19:24:27.076 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(3937) to 72
2024-01-05 19:24:27.119 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 67
2024-01-05 19:24:27.119 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(3937) to 67
2024-01-05 19:24:27.147 DEBUG (MainThread) [custom_components.hubitat.device] sent setLevel to 71
2024-01-05 19:24:27.147 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Sending command setColorTemperature(3937) to 71
2024-01-05 19:24:27.189 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2024-01-05 19:24:27.190 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 71 to 100 (%)
2024-01-05 19:24:27.205 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2024-01-05 19:24:27.206 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 67 to 100 (%)
2024-01-05 19:24:27.387 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 72
2024-01-05 19:24:27.436 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 71
2024-01-05 19:24:27.447 DEBUG (MainThread) [custom_components.hubitat.device] sent setColorTemperature to 67
2024-01-05 19:24:27.593 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorMode', 'value': 'CT', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 colorMode was set to CT', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.594 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorMode of 72 to CT (None)
2024-01-05 19:24:27.611 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Moonlight', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 color was set to Moonlight', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.611 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorName of 72 to Moonlight (None)
2024-01-05 19:24:27.612 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorMode', 'value': 'CT', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 colorMode was set to CT', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.612 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorMode of 71 to CT (None)
2024-01-05 19:24:27.618 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Moonlight', 'displayName': 'Sengled-SmartBulb6', 'deviceId': '71', 'descriptionText': 'Sengled-SmartBulb6 color was set to Moonlight', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.618 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorName of 71 to Moonlight (None)
2024-01-05 19:24:27.651 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorMode', 'value': 'CT', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 colorMode was set to CT', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.651 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorMode of 67 to CT (None)
2024-01-05 19:24:27.663 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'colorName', 'value': 'Moonlight', 'displayName': 'Sengled-SmartBulb1', 'deviceId': '67', 'descriptionText': 'Sengled-SmartBulb1 color was set to Moonlight', 'unit': None, 'type': None, 'data': None}
2024-01-05 19:24:27.663 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating colorName of 67 to Moonlight (None)
2024-01-05 19:24:28.149 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Received event: {'name': 'level', 'value': '100', 'displayName': 'Sengled-SmartBulb7', 'deviceId': '72', 'descriptionText': 'Sengled-SmartBulb7 level was set to 100%', 'unit': '%', 'type': None, 'data': None}
2024-01-05 19:24:28.150 DEBUG (MainThread) [custom_components.hubitat.hubitatmaker.hub] Updating level of 72 to 100 (%)

Hopefully another quick fix...? :)

hbh7 commented 10 months ago

At quick glance, looks like my previous analysis is still the case on integration v0.9.21, just as some more info. Let me know if there's anything else I can provide. Thanks!

jason0x43 commented 10 months ago

It seems like your lights may require an on command even when setLevel is called. Apparently Sengled bulbs can be a bit flakey about turning on when just the level is set with no transition time.

Hmmm...I could have the integration just always send an on command, although that might cause issues with other bulbs that do handle setLevel by itself.

If you call setLevel from the Hubitat UI (assuming the Sengled driver provides a setLevel control) without first explicitly turning on the bulb, does it work? Does the driver have a default transition time option you can set? If you add a small transition time, does setLevel work on its own?

hbh7 commented 10 months ago

Current settings: image image image If I use the setLevel button while the bulb is off, the level changes but the bulb remains off. image

After further testing, changing the duration, transition time, and the color prestaging had no effect (at least in white mode), but turning off level pre-staging changed the behavior of setLevel to now turn the bulb on. Very interesting... I'm not quite sure what to make of this yet... Thoughts?

hbh7 commented 10 months ago

Some additional testing, disabling color pre-staging also makes the bulbs turn on when they're white and off, then set to a color.

Is there a "correct" way to have things? I guess this means I can pick between manually preloading a color and then turning it on, or having it in one step but the color is slightly weird as the bulb turns on (which honestly it is either way lol, silly bulbs). Hmm...

hbh7 commented 10 months ago

Yeah, according to this post, this might be working as intended, whoops. Good to know though. I'll keep an eye on things over the next few days and make sure everything makes sense, but maybe all is well... :)

jason0x43 commented 10 months ago

I think the integration would need more work to handle pre-staging well. Presumably it would want to wait for acknowledgement that the initial commands had completed before sending an on command. It might also need to take transition times into account. Tricky.