search

basnijholt / adaptive-lighting

Adaptive Lighting custom component for Home Assistant
https://basnijholt.github.io/adaptive-lighting/
Apache License 2.0
1.94k stars 139 forks source link

Error doing job: Task exception was never retrieved after update to v1.18.0 #682

Closed bouwew closed 1 year ago

bouwew commented 1 year ago

Home Assistant Adaptive Lighting Issue Template

Bug Reports

If you need help with using or configuring Adaptive Lighting, please open a Q&A discussion thread here instead.

Before submitting a bug report, please follow these troubleshooting steps:

Please confirm that you have completed the following steps:

Required information for bug reports:

Please include the following information in your issue.

Issues missing this information may not be addressed.

In HA Core v2023.8.0b1 (I don't see the errors when I roll back to v2023.7.3) I see these errors in the LOG:

  1. Debug logs captured while the issue occurred. See here for instructions on enabling debug logging:
Logger: homeassistant
Source: custom_components/adaptive_lighting/switch.py:1418
Integration: Adaptieve verlichting ([documentation](https://github.com/basnijholt/adaptive-lighting#readme), [issues](https://github.com/basnijholt/adaptive-lighting/issues))
First occurred: 11:33:14 (1 occurrences)
Last logged: 11:33:14
Error doing job: Task exception was never retrieved

Traceback (most recent call last):
  File "/config/custom_components/adaptive_lighting/switch.py", line 1159, in _async_update_at_interval_action
    await self._update_attrs_and_maybe_adapt_lights(
  File "/config/custom_components/adaptive_lighting/switch.py", line 1418, in _update_attrs_and_maybe_adapt_lights
    assert isinstance(adapt_color, bool)
AssertionError

I also see this Error:

Logger: homeassistant.components.switch
Source: custom_components/adaptive_lighting/switch.py:1418
Integration: Schakelaar ([documentation](https://rc.home-assistant.io/integrations/switch), [issues](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+switch%22))
First occurred: 11:27:57 (2 occurrences)
Last logged: 11:27:57

    Error adding entities for domain switch with platform adaptive_lighting
    Error while setting up adaptive_lighting platform for switch

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 510, in async_add_entities
    await asyncio.gather(*tasks)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 750, in _async_add_entity
    await entity.add_to_platform_finish()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1003, in add_to_platform_finish
    await self.async_added_to_hass()
  File "/config/custom_components/adaptive_lighting/switch.py", line 993, in async_added_to_hass
    await self.async_turn_on(adapt_lights=not self._only_once)
  File "/config/custom_components/adaptive_lighting/switch.py", line 1144, in async_turn_on
    await self._update_attrs_and_maybe_adapt_lights(
  File "/config/custom_components/adaptive_lighting/switch.py", line 1418, in _update_attrs_and_maybe_adapt_lights
    assert isinstance(adapt_color, bool)
AssertionError
  1. Your Adaptive Lighting configuration:
  1. (If using Zigbee2MQTT), provide your configuration files (remove all personal information before posting):
    • devices.yaml
    • groups.yaml
    • configuration.yaml ⚠️; Warning REMOVE ALL of the PERSONAL INFORMATION BELOW before posting ⚠️;
      • mqtt: server:
      • mqtt: user:
      • mqtt: password:
      • advanced: pan_id:
      • advanced: network_key:
      • anything in log_syslog if you use this
    • Brand and model number of problematic light(s) 


4.  Describe the bug and how to reproduce it:

5. Steps to reproduce the behavior:
basnijholt commented 1 year ago

It seems like your adapt_color switch is not properly initialized for some reason. Are you sure there were no more errors messages at the start of the logs?

bouwew commented 1 year ago

No, no other errors, just these two. I've rolled back to HA 2023.7.3 to get rid of the issue.

Sorry, I'm looking at the HA LOG once more, the error is present in HA 2023.7.3 too:

Logger: homeassistant.components.script.turn_up_k_lights
Source: custom_components/adaptive_lighting/switch.py:1418
Integration: Script ([documentation](https://www.home-assistant.io/integrations/script), [issues](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+script%22))
First occurred: 14:22:28 (1 occurrences)
Last logged: 14:22:28
turn_up_k_lights: Error executing script. Unexpected error for call_service at pos 4:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 1965, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2005, in _execute_service
    return await cast(
           ^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 235, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 848, in entity_service_call
    response_data = task.result()  # pop exception if have
                    ^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1192, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 892, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/config/custom_components/adaptive_lighting/switch.py", line 1144, in async_turn_on
    await self._update_attrs_and_maybe_adapt_lights(
  File "/config/custom_components/adaptive_lighting/switch.py", line 1418, in _update_attrs_and_maybe_adapt_lights
    assert isinstance(adapt_color, bool)
AssertionError
bouwew commented 1 year ago

I will downgrade to v1.17.5 to see if that make a difference.

Update: after the downgrade I see a similar error in the HA LOG.

Update 2: hmm, I'm still seeing v1.18.0 in the manifest.json file. I'll try to downgrade once more.

Update 3: Now the downgrade succeeded. Checking the logfile...

Update 4: with v1.17.5 installed the error is gone. And my lights I'm testing with are working normally again. So looks like the AssertionError on assert isinstance(adapt_color, bool) is only present in v1.18.0.

bcutter commented 1 year ago

Hi,

I can also confirm this in the logs after updating to 1.18.0:

Dieser Fehler wurde von einer benutzerdefinierten Integration verursacht

Logger: homeassistant
Source: custom_components/adaptive_lighting/switch.py:2456
Integration: Adaptive Lighting (documentation, issues)
First occurred: 11:15:45 (7 occurrences)
Last logged: 18:46:51

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/config/custom_components/adaptive_lighting/switch.py", line 1543, in _light_state_event_action
    if await self.manager.just_turned_off(
  File "/config/custom_components/adaptive_lighting/switch.py", line 2499, in just_turned_off
    if self._off_to_on_state_event_is_from_turn_on(entity_id, off_to_on_event):
  File "/config/custom_components/adaptive_lighting/switch.py", line 2456, in _off_to_on_state_event_is_from_turn_on
    assert not is_our_context(off_to_on_event.context)
AssertionError

This happens when I flash lights in control of Adaptive Lighting (using device type in automation or the light.turn_on service with flash option). Usually the light flashes for 1 to 3 seconds and is not even turned on. Since AL 1.18.0 the lights stay on until their dedicated automation (switches on by motion triggers) turns them off after time.

Interestingly, when running the flash service manually I sometimes get additionally to AL log entry a) this in the UI grafik b) and this in the log

Logger: homeassistant.helpers.script.websocket_api_script
Source: components/deconz/light.py:234
First occurred: 18:42:15 (6 occurrences)
Last logged: 18:58:04

websocket_api script: Error executing script. Unexpected error for device at pos 1: {'address': '/lights/23/state/bri', 'description': 'parameter, bri, is not modifiable. Device is set to off.', 'type': 201}
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 451, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 692, in _async_device_step
    await device_action.async_call_action_from_config(
  File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 76, in async_call_action_from_config
    await platform.async_call_action_from_config(hass, config, variables, context)
  File "/usr/src/homeassistant/homeassistant/components/light/device_action.py", line 85, in async_call_action_from_config
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1745, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1782, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/config/custom_components/adaptive_lighting/hass_utils.py", line 62, in service_func_proxy
    await existing_service.job.target(call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 678, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 943, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 715, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 570, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/deconz/light.py", line 234, in async_turn_on
    await self.api.set_state(id=self._device.resource_id, **data)
  File "/usr/local/lib/python3.10/site-packages/pydeconz/interfaces/lights.py", line 174, in set_state
    return await self.gateway.request_with_retry(
  File "/usr/local/lib/python3.10/site-packages/pydeconz/gateway.py", line 142, in request_with_retry
    return await self.request(method, path, json)
  File "/usr/local/lib/python3.10/site-packages/pydeconz/gateway.py", line 167, in request
    response: dict[str, Any] = await self._request(
  File "/usr/local/lib/python3.10/site-packages/pydeconz/gateway.py", line 194, in _request
    _raise_on_error(response)
  File "/usr/local/lib/python3.10/site-packages/pydeconz/gateway.py", line 225, in _raise_on_error
    raise_error(data["error"])
  File "/usr/local/lib/python3.10/site-packages/pydeconz/errors.py", line 80, in raise_error
    raise pydeconzException(error)
pydeconz.errors.pydeconzException: {'address': '/lights/23/state/bri', 'description': 'parameter, bri, is not modifiable. Device is set to off.', 'type': 201}

I see all of this for the very first time since AL 1.18.0 update. I used an older version before, I think it was 1.14.0. Also checked former HA log prior to the restart (2023-07-01 until 2023-07-29) and beginning of effective usage of 1.18.0 - yes, 100 % been introduced with AL 1.18.0, former HA log only contained other AL entries which had no practical impact afaict.

basnijholt commented 1 year ago

@bouwew could you share your script.turn_up_k_lights script?

basnijholt commented 1 year ago

@bcutter I’ll check what happens with the flash. Is the expected behavior that the lights turn off after flashing?

giannoug commented 1 year ago

Same here. Lights turn on, but stay at 1% brightness after upgrade to v1.18.0.

Logger: homeassistant
Source: custom_components/adaptive_lighting/switch.py:2456
Integration: Adaptive Lighting ([documentation](https://github.com/basnijholt/adaptive-lighting#readme), [issues](https://github.com/basnijholt/adaptive-lighting/issues))
First occurred: 2:41:28 PM (1 occurrences)
Last logged: 2:41:28 PM

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/config/custom_components/adaptive_lighting/switch.py", line 1514, in _light_state_event_action
    and not self.manager._off_to_on_state_event_is_from_turn_on(
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/adaptive_lighting/switch.py", line 2456, in _off_to_on_state_event_is_from_turn_on
    assert not is_our_context(off_to_on_event.context)
AssertionError
basnijholt commented 1 year ago

@giannoug, do you know what you did to trigger error?

giannoug commented 1 year ago

@basnijholt I updated yesterday at around midnight. I believe lights were working correctly before I went to bed. Today afternoon it seems that they do not work (I use the Sensor Light automation).

BTW I have an issue where lights controlled by this automation turn on at 1% brightness and then take either a second or a couple more to turn to the correct color. I haven't found time to fix that yet.

Here's the weird part. Lights controlled by the automation above have the issue reported here and lag when turning on. Lights controlled by switches do not seem to be affected by these bugs 🤔 My first guess when I was trying to debug the 1% brightness issue I have was transitions, but I'm a bit new to HA and all these stuff so I hit a wall fast.

bcutter commented 1 year ago

@bcutter I’ll check what happens with the flash. Is the expected behavior that the lights turn off after flashing?

After flashing the light should turn back to its previous state. So yes, if it is off and it flashes, it should turn off again.

I am not sure and can't test it currently, but it might be the light's entity state might even not been on during flashing - but really not sure.

basnijholt commented 1 year ago

@bouwew, your issue is solved in https://github.com/basnijholt/adaptive-lighting/pull/686.

This is a strange race condition which happens when initializing the AdaptiveSwitch is done before initializing the other switches (e.g., sleep, adapt_brightness, or adapt_color).

This condition has been present in all previous versions, however, for some reason it is more likely to occur now.

basnijholt commented 1 year ago

@bcutter and @giannoug, your issue should be fixed by #687.

I released 1.18.2.

bcutter commented 1 year ago

@bcutter and @giannoug, your issue should be fixed by #687.

I released 1.18.2.

Quick test: should indeed be fixed. Will monitor it for a while. Thanks for fabulously quick response 👍

giannoug commented 1 year ago

I'm not seeing the errors in log, but my automatic lights still seem to be stuck at 1% 🤔 Lights controlled by switches seem fine though. Anyway this should be the other issue I'm having

basnijholt commented 1 year ago

If you can enable debugging logging and share them I can help you better

giannoug commented 1 year ago

Didn't think of that. It has some interesting info there.

2023-07-31 00:25:09.197 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Transition finished for light light.nightstands
2023-07-31 00:25:13.887 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] No (or multiple) adaptive switch(es) found for entity light.lounge_automatic_lights, skipping adaptation by intercepting service call
2023-07-31 00:25:15.116 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.tv' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'TV single', 'TV double'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'TV', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MB1VKSNHBFJXR0V5ASR8TV'
2023-07-31 00:25:15.117 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.countertops' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'Countertop small', 'Countertop big'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'Countertops', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MB1VPB1MQP4WF9KYPQ69SB'
2023-07-31 00:25:15.118 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Detected an 'off' → 'on' event for 'light.tv' with context.id='01H6MB1VKSNHBFJXR0V5ASR8TV'
2023-07-31 00:25:15.118 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MB1VKSNHBFJXR0V5ASR8TV'
2023-07-31 00:25:15.119 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Ignoring 'off' → 'on' event for 'light.tv' with context.id='01H6MB1VKSNHBFJXR0V5ASR8TV' because 'light.turn_on' was not called by HA and 'detect_non_ha_changes' is False
2023-07-31 00:25:15.119 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Marking 'light.tv' as manually controlled.
2023-07-31 00:25:15.120 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Detected an 'off' → 'on' event for 'light.countertops' with context.id='01H6MB1VPB1MQP4WF9KYPQ69SB'
2023-07-31 00:25:15.120 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MB1VPB1MQP4WF9KYPQ69SB'
2023-07-31 00:25:15.120 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Ignoring 'off' → 'on' event for 'light.countertops' with context.id='01H6MB1VPB1MQP4WF9KYPQ69SB' because 'light.turn_on' was not called by HA and 'detect_non_ha_changes' is False
2023-07-31 00:25:15.120 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Marking 'light.countertops' as manually controlled.

It shouldn't be marking them as manually controlled. Maybe because I'm using the Hue group and the Hue integration is doing something weird under the hood?

If you feel this is out of scope, we can move discussion in another issue.

basnijholt commented 1 year ago

I see, this means that you are turning on the lights outside of Home Assistant, and Home Assistant is only picking up the state change.

Whenever detect_non_ha_changes: false adaptive lighting will ignore these types of events and it considers the light manually controlled.

You need to enable detect_non_ha_changes: true to start adapting on these type of events that do not have a light.turn_on.

giannoug commented 1 year ago

I'm not turning on the lights outside of Home Assistant though. The lights should be turned on by the automation (through HA). I see I've mixed groups in Adaptive Lighting and the automation. For example, I had set light.lounge_automatic_lights in the automation and light.tv / light.countertops in Adaptive Lighting. The light.lounge_automatic_lights contains the other 2 groups in the Hue app. Those are all defined in the Hue app and after the 1.18.0 update they stopped working. I've now fixed the entities and they seem to be turning on, but still they get stuck on 1% for a couple of seconds.

Checking with debugging logging to see if anything interesting comes up

basnijholt commented 1 year ago

Ok good to know! Thanks for your patience.

Would you be able to share how you configured that automation? Maybe it’s turning on devices instead of entities.

giannoug commented 1 year ago

Here are some logs. The Adaptive Lighting integration I'm debugging is "Lounge automatic lights" which includes two entities, light.tv and light.countertops. Those same entities I'm controlling through the automation. From what I've read, maybe its an issue with transitions?

image image

2023-07-31 00:54:34.273 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Kitchen: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H6MCQHN1:al:JNUX:ntrv:1E' lights: 'None', transition: '45.0', force: 'False'
2023-07-31 00:54:34.300 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Kitchen: filtered_lights: '['light.kitchen_hidden', 'light.kitchen_displays', 'light.kitchen_spots']'
2023-07-31 00:54:34.301 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Living room: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H6MCQHNX:al:JRUX:ntrv:1E' lights: 'None', transition: '45.0', force: 'False'
2023-07-31 00:54:34.328 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Living room: filtered_lights: '['light.l_room_single', 'light.l_room_double']'
2023-07-31 00:54:37.788 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H6MCQN2W:al:IRSX:ntrv:07' lights: 'None', transition: '45.0', force: 'False'
2023-07-31 00:54:37.816 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: filtered_lights: '['light.desk']'
2023-07-31 00:54:37.817 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.desk' with transition 45.0 and context.id=01H6MCQN2W:al:IRSX:ntrv:07
2023-07-31 00:54:37.820 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: Setting color_temp of light light.desk
2023-07-31 00:54:37.821 DEBUG (MainThread) [custom_components.adaptive_lighting.adaptation_utils] Preparing adaptation data for light.desk with service data {'entity_id': 'light.desk', 'transition': 45.0, 'brightness': 65, 'color_temp_kelvin': 2700}
2023-07-31 00:54:37.821 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: execute_cancellable_adaptation_calls with data: AdaptationData(entity_id='light.desk', context=<homeassistant.core.Context object at 0x7fc6d0f75620>, sleep_time=45.0, service_call_datas=<async_generator object _create_service_call_data_iterator at 0x7fc6d0fec040>, max_length=1, which='both', initial_sleep=False)
2023-07-31 00:54:37.824 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Desk: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.desk', 'transition': 45.0, 'brightness': 65, 'color_temp_kelvin': 2700} with context.id='01H6MCQN2W:al:IRSX:ntrv:07'
2023-07-31 00:54:37.828 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.desk']')' event with context.id='01H6MCQN2W:al:IRSX:ntrv:07'
2023-07-31 00:54:42.915 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.tv', 'light.countertops']')' event with context.id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.231 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.tv' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'TV single', 'TV double'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'TV', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.234 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.countertops' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'Countertop small', 'Countertop big'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'Countertops', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.235 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Detected an 'off' → 'on' event for 'light.tv' with context.id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.235 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.235 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.235 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] just_turned_off: State change 'off' → 'on' triggered by 'light.turn_on'
2023-07-31 00:54:44.236 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H6MCQVCC:al:JRXX:lght:1N' lights: '['light.tv']', transition: '1.0', force: 'True'
2023-07-31 00:54:44.260 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: filtered_lights: '['light.tv']'
2023-07-31 00:54:44.260 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.tv' with transition 1.0 and context.id=01H6MCQVCC:al:JRXX:lght:1N
2023-07-31 00:54:44.260 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.262 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Setting color_temp of light light.tv
2023-07-31 00:54:44.262 DEBUG (MainThread) [custom_components.adaptive_lighting.adaptation_utils] Preparing adaptation data for light.tv with service data {'entity_id': 'light.tv', 'transition': 1.0, 'brightness': 140, 'color_temp_kelvin': 2700}
2023-07-31 00:54:44.262 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: execute_cancellable_adaptation_calls with data: AdaptationData(entity_id='light.tv', context=<homeassistant.core.Context object at 0x7fc6ce7562f0>, sleep_time=1.0, service_call_datas=<async_generator object _create_service_call_data_iterator at 0x7fc6dc224a40>, max_length=1, which='both', initial_sleep=False)
2023-07-31 00:54:44.264 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Detected an 'off' → 'on' event for 'light.countertops' with context.id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.264 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.264 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.264 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] just_turned_off: State change 'off' → 'on' triggered by 'light.turn_on'
2023-07-31 00:54:44.264 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: '_update_attrs_and_maybe_adapt_lights' called with context.id='01H6MCQVD8:al:JRXX:lght:1O' lights: '['light.countertops']', transition: '1.0', force: 'True'
2023-07-31 00:54:44.276 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: filtered_lights: '['light.countertops']'
2023-07-31 00:54:44.276 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.countertops' with transition 1.0 and context.id=01H6MCQVD8:al:JRXX:lght:1O
2023-07-31 00:54:44.276 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] is_proactively_adapting_context='False', context_id='01H6MCQT135W91YJMK5GA2634H'
2023-07-31 00:54:44.280 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Setting color_temp of light light.countertops
2023-07-31 00:54:44.280 DEBUG (MainThread) [custom_components.adaptive_lighting.adaptation_utils] Preparing adaptation data for light.countertops with service data {'entity_id': 'light.countertops', 'transition': 1.0, 'brightness': 140, 'color_temp_kelvin': 2700}
2023-07-31 00:54:44.281 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: execute_cancellable_adaptation_calls with data: AdaptationData(entity_id='light.countertops', context=<homeassistant.core.Context object at 0x7fc6de1df470>, sleep_time=1.0, service_call_datas=<async_generator object _create_service_call_data_iterator at 0x7fc6d55a6840>, max_length=1, which='both', initial_sleep=False)
2023-07-31 00:54:44.359 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.tv', 'transition': 1.0, 'brightness': 140, 'color_temp_kelvin': 2700} with context.id='01H6MCQVCC:al:JRXX:lght:1N'
2023-07-31 00:54:44.360 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.countertops', 'transition': 1.0, 'brightness': 140, 'color_temp_kelvin': 2700} with context.id='01H6MCQVD8:al:JRXX:lght:1O'
2023-07-31 00:54:44.403 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.tv']')' event with context.id='01H6MCQVCC:al:JRXX:lght:1N'
2023-07-31 00:54:44.404 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.countertops']')' event with context.id='01H6MCQVD8:al:JRXX:lght:1O'
2023-07-31 00:54:45.465 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.tv' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 70, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'TV single', 'TV double'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'TV', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQVCC:al:JRXX:lght:1N'
2023-07-31 00:54:45.465 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] AdaptiveLightingManager: New adapt '<state light.tv=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], color_mode=color_temp, brightness=70, color_temp_kelvin=2702, color_temp=370, hs_color=(28.391, 65.659), rgb_color=(255, 166, 87), xy_color=(0.526, 0.387), is_hue_group=True, hue_scenes=set(), hue_type=zone, lights={'TV single', 'TV double'}, dynamics=False, icon=mdi:lightbulb-group, friendly_name=TV, supported_features=40 @ 2023-07-31T00:54:44.065916+03:00>' found for light.tv
2023-07-31 00:54:45.466 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Start transition timer of 1.0 seconds for light light.tv
2023-07-31 00:54:45.466 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.tv' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 140, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'TV single', 'TV double'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'TV', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQVCC:al:JRXX:lght:1N'
2023-07-31 00:54:45.467 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] AdaptiveLightingManager: State change event of 'light.tv' is already in 'self.last_state_change' (01H6MCQVCC:al:JRXX:lght:1N) adding this state also
2023-07-31 00:54:45.467 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.countertops' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 70, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'Countertop small', 'Countertop big'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'Countertops', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQVD8:al:JRXX:lght:1O'
2023-07-31 00:54:45.467 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] AdaptiveLightingManager: New adapt '<state light.countertops=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], color_mode=color_temp, brightness=70, color_temp_kelvin=2702, color_temp=370, hs_color=(28.391, 65.659), rgb_color=(255, 166, 87), xy_color=(0.526, 0.387), is_hue_group=True, hue_scenes=set(), hue_type=zone, lights={'Countertop small', 'Countertop big'}, dynamics=False, icon=mdi:lightbulb-group, friendly_name=Countertops, supported_features=40 @ 2023-07-31T00:54:44.220746+03:00>' found for light.countertops
2023-07-31 00:54:45.468 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Start transition timer of 1.0 seconds for light light.countertops
2023-07-31 00:54:45.468 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.countertops' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 140, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'Countertop small', 'Countertop big'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'Countertops', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQVD8:al:JRXX:lght:1O'
2023-07-31 00:54:45.469 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] AdaptiveLightingManager: State change event of 'light.countertops' is already in 'self.last_state_change' (01H6MCQVD8:al:JRXX:lght:1O) adding this state also
2023-07-31 00:54:46.472 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Transition finished for light light.tv
2023-07-31 00:54:46.474 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Transition finished for light light.countertops
basnijholt commented 1 year ago

@giannoug, when I read your logs it seems like AL is adapting the lights you mentioned.

Here you turn on the lights (with your automation?) 2023-07-31 00:54:42.915 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.tv', 'light.countertops']')' event with context.id='01H6MCQT135W91YJMK5GA2634H' then for some reason it takes 2 seconds for the state_change to register: 2023-07-31 00:54:44.231 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.tv' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'TV single', 'TV double'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'TV', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQT135W91YJMK5GA2634H' 2023-07-31 00:54:44.234 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.countertops' 'state_changed' event: '{'min_color_temp_kelvin': 2000, 'max_color_temp_kelvin': 6535, 'min_mireds': 153, 'max_mireds': 500, 'supported_color_modes': [<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], 'color_mode': <ColorMode.COLOR_TEMP: 'color_temp'>, 'brightness': 1, 'color_temp_kelvin': 2702, 'color_temp': 370, 'hs_color': (28.391, 65.659), 'rgb_color': (255, 166, 87), 'xy_color': (0.526, 0.387), 'is_hue_group': True, 'hue_scenes': set(), 'hue_type': 'zone', 'lights': {'Countertop small', 'Countertop big'}, 'dynamics': False, 'icon': 'mdi:lightbulb-group', 'friendly_name': 'Countertops', 'supported_features': <LightEntityFeature.FLASH|TRANSITION: 40>}' with context.id='01H6MCQT135W91YJMK5GA2634H' then within 42 ms AL takes over: 2023-07-31 00:54:44.276 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Lounge automatic lights: Calling _adapt_light from _update_attrs_and_maybe_adapt_lights: 'light.countertops' with transition 1.0 and context.id=01H6MCQVD8:al:JRXX:lght:1O

This might indeed be due to a transition in your light.turn_on call in your automation. Could you try it with 0 transition?

Unfortunately, it is Home Assistant that reports these state changes and this cannot be sped up.

basnijholt commented 1 year ago

BTW currently, AL can only do instantaneous adaptation with single lights. After https://github.com/basnijholt/adaptive-lighting/pull/679 is merged you likely will see instantaneous changes for the light.turn_on calls that target multiple lights.

bouwew commented 1 year ago

@basnijholt I've upgraded to v1.18.2. I can confirm that the errors in HA LOG are gone :+1:

But, unfortunately, this script does not give the correct result, the group of light doesn't turn off:

turn_off_k_lights:
  sequence:
    - service: switch.turn_off
      entity_id:
        - switch.adaptive_lighting_keuken_dimmed
        - switch.adaptive_lighting_keuken
        - switch.adaptive_lighting_cabinet
    - delay:
        milliseconds: 300
    - service: light.turn_off
      entity_id:
        - light.keukenlampen
        - light.cabinet
    - service: input_boolean.turn_off
      entity_id: input_boolean.k_lights_on_k_sensor
    - service: input_boolean.turn_on
      entity_id: input_boolean.k_lights_off_by_autm

The group of lights turns on OK based on movement detection, but the group does not turn off when the related timer ends. I'll troubleshoot more later today when I'm back from work.

giannoug commented 1 year ago

BTW currently, AL can only do instantaneous adaptation with single lights. After #679 is merged you likely will see instantaneous changes for the light.turn_on calls that target multiple lights.

Lights that worked yesterday with switches, stay at 1% today 🥴 How does AL know a switch is a group or a single light? From what I undestand, grouped lights are on the Hue level and exposed to HA as a single one