Lights randomly come back on after shut off

This has only happened to me twice, and I don't have a way to replicate it, but I will turn off a light using lovelace and after 10-15 seconds or so it turns itself back on. If I find a way to replicate it I can turn on debugging but I have no way to track it down so it wouldn't do much good right now. I am running d67479d now, and if I see it happen with this version I will let you know but like I said this has only happened twice over the week or so I've been running AL.

Would it be possible to enable debugging logging with:

logger:
  default: warning
  logs:
    custom_components.adaptive_lighting: debug

and post the log after it occurred?

I have a suspicion as to why it is happening but not sure.

I just enabled debugging to see if it happens again. It just happened again on the latest version before I turned on debugging. I believe the only lights I have seen this occur on are Sengled Zigbee bulbs. Hopefully I can catch the full debug going forward.

This has happened a bunch of times since I last posted but unfortunately I messed up my Zha yesterday and had to turn off the debug to fix it. I’ll try to get it going again now that things seem to be stable

I caught one this evening in my sons room. Turned off the light via home assistant and it turned back on a few seconds later.

2020-10-18 20:19:23 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] State of 'light.justins_light' didn't change wrt change event nr. 0 (context.id=adapt_lgt_769d_interval_938)
2020-10-18 20:19:23 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Justins Bedroom: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.justins_light', 'transition': 45.0, 'brightness': 108, 'color_temp': 500} with context.id='adapt_lgt_769d_interval_938'
2020-10-18 20:19:23 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.justins_light']')' event with context.id='adapt_lgt_769d_interval_938'
2020-10-18 20:19:24 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.justins_light' 'state_changed' event: '{'min_mireds': 154, 'max_mireds': 500, 'brightness': 108, 'color_temp': 500, 'hs_color': (0, 0), 'rgb_color': (255, 255, 255), 'xy_color': (0.323, 0.329), 'off_brightness': None, 'friendly_name': 'Justins Light', 'icon': 'mdi:lamp', 'supported_features': 59}' with context.id='adapt_lgt_769d_interval_938'
2020-10-18 20:19:36 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_off('['light.justins_light']', transition=None)' event with context.id='c516bd2511a011eb9e71e3aac25616a3'
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.justins_light' 'state_changed' event: '{'min_mireds': 154, 'max_mireds': 500, 'brightness': 108, 'color_temp': 500, 'hs_color': (0, 0), 'rgb_color': (255, 255, 255), 'xy_color': (0.323, 0.329), 'off_brightness': None, 'friendly_name': 'Justins Light', 'icon': 'mdi:lamp', 'supported_features': 59}' with context.id='d89b48aa11a011eb98e8b794d03648fc'
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Justins Bedroom: Detected an 'off' → 'on' event for 'light.justins_light' with context.id='d89b48aa11a011eb98e8b794d03648fc'
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], 1.0, force=True, context.id=adapt_lgt_769d_light_event_939)' called
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Justins Bedroom: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.justins_light', 'transition': 1.0, 'brightness': 107, 'color_temp': 500} with context.id='adapt_lgt_769d_light_event_939'
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.justins_light']')' event with context.id='adapt_lgt_769d_light_event_939'
2020-10-18 20:20:09 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.justins_light' 'state_changed' event: '{'min_mireds': 154, 'max_mireds': 500, 'brightness': 107, 'color_temp': 500, 'hs_color': (0, 0), 'rgb_color': (255, 255, 255), 'xy_color': (0.323, 0.329), 'off_brightness': None, 'friendly_name': 'Justins Light', 'icon': 'mdi:lamp', 'supported_features': 59}' with context.id='adapt_lgt_769d_light_event_939'
2020-10-18 20:20:17 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_off('['light.justins_light']', transition=None)' event with context.id='dd58269f11a011eba1913116e45fac2e'
2020-10-18 20:20:55 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_940)' called
2020-10-18 20:22:25 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_941)' called
2020-10-18 20:23:55 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_942)' called
2020-10-18 20:25:25 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_943)' called
2020-10-18 20:26:55 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_944)' called
2020-10-18 20:28:25 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_945)' called
2020-10-18 20:29:55 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_946)' called
2020-10-18 20:31:25 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Justins Bedroom: '_adapt_lights(['light.justins_light'], None, force=False, context.id=adapt_lgt_769d_interval_947)' called

I see that this happened:

at 20:19:36 light.turn_off called
at 20:20:09, the light reports it's on after polling, so AL proceeds to adapt it
at 20:20:17, something/someone called light.turn_off again, I presume that's you clicking the off button?

This is not really a bug of AL, but rather that the light reports that it's on, while it is actually off. Still there might be something that we can do. Maybe I can ignore any off -> on events that do not result from light.turn_on for a minute or so. What do you think?

that could be, my zigbee network has been a little flakey lately. Unfortunately most of my zigbee devices are sengled bulbs which are only endpoint devices, not routers. Working on trying to rectify that.

I'm sure I'm not the only one with a less than 100% stable zigbee network, so if there is some way to ignore those events then it would probably be for the best. Especially if it was an optional configuration.

I switched to ZHA and I am now seeing these problems too. Unfortunately, it doesn't seem like there is a lot to do. I will probably switch back to deCONZ... :'(

My issue is reported here https://github.com/zigpy/zigpy-deconz/issues/140.

I will watch that thread but I may need to pick up a new zigbee stick. What are you using with deconz?

that could be, my zigbee network has been a little flakey lately. Unfortunately most of my zigbee devices are sengled bulbs which are only endpoint devices, not routers. Working on trying to rectify that.

I started with Conbee II & deCONZ in HomeSeer (before I started HA) but had random turn-on's with Eria but initially only in Bedroom Lamp 2. I returned that bulb and then the Eria in Bedroom Lamp 1 randomly turned on a couple of times so I sent it back to Amazon also. I replaced them with Sengled and no more hiccups. Then I switched to HA using ZHA with Conbee II (no hiccups) but recently replaced Conbee II with CC2652 Stick which has an external antenna attached to the dongle and it has better range. The Sengled's are in bedroom but I have Osram Lightify in office and currently do not have any random turn-ons. I might try the Eria again now that my platform and controller have changed.

I'm having this same issue. It started after I installed adaptive lighting. My Sengled bulbs will get turned off by an automation and then just turn back on for no reason. It seems to only happen at night when adaptive lighting is running.

@profesaurus, could you please add your logs (see https://github.com/basnijholt/adaptive-lighting#having-problems)?

I'm having this same issue. It started after I installed adaptive lighting. My Sengled bulbs will get turned off by an automation and then just turn back on for no reason. It seems to only happen at night when adaptive lighting is running.

Is the 'off automation' an automation in HA? Can you verify that after the off automation runs that their status in HA shows off? Also, after they've randomly turned on, does their status in HA show on?

...and include your logs as requested by @basnijholt !

@basnijholt I have adjusted HA to log debug outputs from AL. If/when it happens again I'll post here with the logs.

@danielbrunt57

The automation is an automation in HA. This is the only action in the automation:

Here's the logbook entry for when the automation turned the lights off, but then back on:

The top log is interesting because the lights are turned on by the action above....which is a light.turn_off service???

Also, that automation is only triggered once at the time the lights initially turn off:

The history does show the lights turning off, then back on:

I did find a post on the HA forums about an issue with zha light groups and Circadian Lighting and AL.

I am using zha light groups, so as a test, in AL's settings I unchecked the light groups and checked the individual lights within the groups. I don't know if this will fix it or if I'll need to try the recommended automation in the post.

Let me know if you have any other questions, I'm happy to help.

Very interesting.
I have 2 Sengled bulbs (ZHA) in master bedroom. They are motion controlled by Entity Controller, not an HA automation. I've no issues with them turning off and staying off. They are now in a group light.bedroom_lights. I say now because they were in group.bedroom_lights hence the reason for the "#" in the code below as that was needed for EC to observe and ignore changes in the light entities' brightness and color attributes by CL and now AL.

  bedroom_lights_control:
    friendly_name: Bedroom Lights Control
    sensor: binary_sensor.lumi_sensor_motion_bedroom
    sensor_type: duration
    state_attributes_ignore:
      - color_temp
      - brightness
    entity: light.bedroom_lights
    override: 
      - input_boolean.sleep_mode
#    state_entities:
#      - light.bedroom_lamp_1_level_light_color_on_off
#      - light.bedroom_lamp_2_level_light_color_on_off
    service_data:
      brightness: 30
    service_data_on: 
      transition: 3
    service_data_off: 
      transition: 5
    start_time: sunset - 00:30:00
    end_time: sunrise + 00:30:00
    end_time_action: "off"

In AL, I defined them individually as that was when I had group.bedroom_lights.

BTW, any ideas why I have a field sizing issue in the options window?

@basnijholt & @danielbrunt57, I've got some logs for you. I have two AL setups. As I mentioned in my previous message, in my main AL setup I unchecked the ZHA groups from the settings and checked the individual lights. I haven't seen any issues with this one since doing that. <---- EDIT: This is not true, check my next post.

But I have another AL setup where I left the ZHA light groups in the settings and that one just had an issue with lights turning on after being turned off. In the settings the light.kids_bathroom_lights is the group I'm referring to:

I manually turned this group off in HA and they almost immediately came back on:

These lights have no automations attached to them, so there's nothing I did in HA that could be turning these lights on.

Here are the relevant logs:

2020-12-04 21:34:43 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_off('['light.kids_bathroom_lights']', transition=None)' event with context.id='86b79a45c997779df8683d5efa08b3b3' 2020-12-04 21:34:44 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.kids_bathroom_lights' 'state_changed' event: '{'brightness': 5, 'off_brightness': None, 'friendly_name': 'Kids Bathroom Lights', 'supported_features': 41}' with context.id='86b79a45c997779df8683d5efa08b3b3' 2020-12-04 21:34:48 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.kids_bathroom_lights' 'state_changed' event: '{'brightness': 5, 'off_brightness': None, 'friendly_name': 'Kids Bathroom Lights', 'supported_features': 41}' with context.id='86b79a45c997779df8683d5efa08b3b3' 2020-12-04 21:34:48 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Kids Adaptive Lighting: Detected an 'off' → 'on' event for 'light.kids_bathroom_lights' with context.id='86b79a45c997779df8683d5efa08b3b3' 2020-12-04 21:34:48 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Waiting with adjusting 'light.kids_bathroom_lights' for 0.746035 2020-12-04 21:34:49 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.kids_bathroom_lights' 'state_changed' event: '{'brightness': 4, 'off_brightness': None, 'friendly_name': 'Kids Bathroom Lights', 'supported_features': 41}' with context.id='06ecf7490dfee424bb4057cc7d1ae373'

Please let me know if you need any further info. I'm happy to help.

I posted too soon. Looking through my logbook I discovered that my main AL setup had another issue today. And again, these issues only occur when AL is activated in the evening, so I'm pretty confident AL is playing some role in this.

I had an automation turn off a ZHA group, light.master_closet_lights, then about 20 seconds later 2 of the 3 lights in the group (light.master_closet_1 & light.master_closet_3) turned on. These lights are in the same light fixture, so it's not like two can be manually switched on without the others. Here are the logbook entries:

The AL settings:

And the logs:

2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_3' 'state_changed' event: '{'brightness': 254, 'off_brightness': None, 'friendly_name': 'Master Closet Light 3', 'supported_features': 41}' with context.id='49aebeb61a3a36006be15fd9e6d8fdc8' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Detected an 'off' → 'on' event for 'light.master_closet_3' with context.id='49aebeb61a3a36006be15fd9e6d8fdc8' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: '_update_attrs_and_maybe_adapt_lights' called with context.id='adapt_lgt_e2cf_light_event_80' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Adaptive Lighting: '_adapt_lights(['light.master_closet_3'], 1.0, force=True, context.id=adapt_lgt_e2cf_light_event_80)' called 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.master_closet_3', 'transition': 1.0, 'brightness': 168} with context.id='adapt_lgt_e2cf_light_event_80' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 254, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='a80bb0aabe5af9d5224ea1d10c18c8ed' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.master_closet_3']')' event with context.id='adapt_lgt_e2cf_light_event_80' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Detected an 'off' → 'on' event for 'light.master_closet_1' with context.id='a80bb0aabe5af9d5224ea1d10c18c8ed' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: '_update_attrs_and_maybe_adapt_lights' called with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Adaptive Lighting: '_adapt_lights(['light.master_closet_1'], 1.0, force=True, context.id=adapt_lgt_e2cf_light_event_81)' called 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.master_closet_1', 'transition': 1.0, 'brightness': 168} with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.master_closet_1']')' event with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_3' 'state_changed' event: '{'brightness': 168, 'off_brightness': None, 'friendly_name': 'Master Closet Light 3', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_80' 2020-12-04 17:50:28 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 168, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_2' 'state_changed' event: '{'brightness': 254, 'off_brightness': None, 'friendly_name': 'Master Closet Light 2', 'supported_features': 41}' with context.id='093dc58985c4bf33963b210c8021e8a3' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Detected an 'off' → 'on' event for 'light.master_closet_2' with context.id='093dc58985c4bf33963b210c8021e8a3' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: '_update_attrs_and_maybe_adapt_lights' called with context.id='adapt_lgt_e2cf_light_event_82' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Adaptive Lighting: '_adapt_lights(['light.master_closet_2'], 1.0, force=True, context.id=adapt_lgt_e2cf_light_event_82)' called 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.master_closet_2', 'transition': 1.0, 'brightness': 168} with context.id='adapt_lgt_e2cf_light_event_82' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.master_closet_2']')' event with context.id='adapt_lgt_e2cf_light_event_82' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 174, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] State change event of 'light.master_closet_1' is already in 'self.last_state_change' (adapt_lgt_e2cf_light_event_81) adding this state also 2020-12-04 17:50:29 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_2' 'state_changed' event: '{'brightness': 168, 'off_brightness': None, 'friendly_name': 'Master Closet Light 2', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_82' 2020-12-04 17:50:30 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 168, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_81' 2020-12-04 17:50:30 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] State change event of 'light.master_closet_1' is already in 'self.last_state_change' (adapt_lgt_e2cf_light_event_81) adding this state also

2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 167, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='7cb77154a2817828037d33c85423661a' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Detected an 'off' → 'on' event for 'light.master_closet_1' with context.id='7cb77154a2817828037d33c85423661a' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: '_update_attrs_and_maybe_adapt_lights' called with context.id='adapt_lgt_e2cf_light_event_89' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Adaptive Lighting: '_adapt_lights(['light.master_closet_1'], 1.0, force=True, context.id=adapt_lgt_e2cf_light_event_89)' called 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.master_closet_1', 'transition': 1.0, 'brightness': 166} with context.id='adapt_lgt_e2cf_light_event_89' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.master_closet_1']')' event with context.id='adapt_lgt_e2cf_light_event_89' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_1' 'state_changed' event: '{'brightness': 166, 'off_brightness': None, 'friendly_name': 'Master Closet Light 1', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_89' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_3' 'state_changed' event: '{'brightness': 167, 'off_brightness': None, 'friendly_name': 'Master Closet Light 3', 'supported_features': 41}' with context.id='00ef699d40e73439198ae6e629f7dc8d' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Detected an 'off' → 'on' event for 'light.master_closet_3' with context.id='00ef699d40e73439198ae6e629f7dc8d' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: '_update_attrs_and_maybe_adapt_lights' called with context.id='adapt_lgt_e2cf_light_event_90' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Adaptive Lighting: '_adapt_lights(['light.master_closet_3'], 1.0, force=True, context.id=adapt_lgt_e2cf_light_event_90)' called 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Adaptive Lighting: Scheduling 'light.turn_on' with the following 'service_data': {'entity_id': 'light.master_closet_3', 'transition': 1.0, 'brightness': 166} with context.id='adapt_lgt_e2cf_light_event_90' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected an 'light.turn_on('['light.master_closet_3']')' event with context.id='adapt_lgt_e2cf_light_event_90' 2020-12-04 17:54:18 DEBUG (MainThread) [custom_components.adaptive_lighting.switch] Detected a 'light.master_closet_3' 'state_changed' event: '{'brightness': 166, 'off_brightness': None, 'friendly_name': 'Master Closet Light 3', 'supported_features': 41}' with context.id='adapt_lgt_e2cf_light_event_90'

I can also confirm that with my Osram Zigbee lamp

I did some testing and it looks like the problem is as suggested by @basnijholt: The states of ZHA devices are a bit unreliable. If a device is seen as on in HA, adaptive light tries to adjust its brightness/temperature according to your settings. Unfortunately lights turn on, on brightness change. This seems to be an expected behavior in HA itself.

@basnijholt i think it would be reasonable to add a flag ignore off -> on state change for 1 intervall (or x sec). This might mitigate the error here

I can confirm the same behavior with Philips and Ikea lights on a Conbee2 stick with Deconz. More then with the original circadian lighting component. Think it relates to the combination of Deconz groups, single light bulbs and HA light groups. Will make that more sophisticated on my side but would like to share my initial thought...

Has anyone been able to figure out what is happening here? I have two Sengled bulbs which seem to be doing something similar to this... where they sometimes come on randomly, but only at night. It started with one of my bulbs, and has been happening off and on (sometimes doesn't happen at all, sometimes happens many times in a night) for a few months. It just started last night with the second bulb.

Both bulbs are bound directly to one Lutron Aurora each, and none of my Zigbee devices are part of any group (HA or Zigbee). I use ZHA with an HZUSBZ-1 stick.

I can confirm the same behavior with Philips and Ikea lights on a Conbee2 stick with Deconz. More then with the original circadian lighting component. Think it relates to the combination of Deconz groups, single light bulbs and HA light groups. Will make that more sophisticated on my side but would like to share my initial thought...

I did my checkings and refactored it entirely... Using groups or not using them doesn't differ. I do have one positive thing here... it happens quite a lot and most of the time when shutting down several entities. I will raise loglevels to give some valuable input later on.

I seem to have been able to fix it. I think the problem comes in if a light is transitioning while it is shut off, the transition continues which turns the light back on. I fixed this by setting the transition to 1 second. Haven’t had the issue since.

I seem to have been able to fix it. I think the problem comes in if a light is transitioning while it is shut off, the transition continues which turns the light back on. I fixed this by setting the transition to 1 second. Haven’t had the issue since.

Trying this right now.

Additionally, I created an automation that fires a light.turn_off ~10 seconds after the first turn off. Elegant? Nah, but it definitly turns the lights off, when I leave home.

I seem to have been able to fix it. I think the problem comes in if a light is transitioning while it is shut off, the transition continues which turns the light back on. I fixed this by setting the transition to 1 second. Haven’t had the issue since.

Doesn't work for me unfortunately. Problem seems to be the slow refresh of zigbee lights (thinking light is still on)

Not using separate_turn_on_commands fixed it for me with Hue and Ikea lights.

I seem to have been able to fix it. I think the problem comes in if a light is transitioning while it is shut off, the transition continues which turns the light back on. I fixed this by setting the transition to 1 second. Haven’t had the issue since.

Doesn't work for me unfortunately. Problem seems to be the slow refresh of zigbee lights (thinking light is still on)

Yes, I think the problem is related to a delay from the zigbee network and HA, specially when controlled outside HA (for instance binding devices).

I think this is very related to the this issue: https://github.com/basnijholt/adaptive-lighting/issues/96

IMHO, disabling brightness control and updating temperature not "turning on" the device (just changing temperature) could fix it.

I developed this issue about 1-2 weeks ago with my office & bedroom lights. Would appear to have been a fight between adaptive lighting and magic areas. I disabled AL for office and the lights stopped coming back on after magic area turned them off. A few upgrades later, re-enabled AL for office and they seem to be okay again now...

I spoke to soon. It JUST happened again...

I have the exact same problem / behavior. I use ZHA first with an Silicon Labs EmberZNet based coordinator (belows) and now a Conbee 2 (deconz) coordinator. Same behaviour like describes with random lamps of all kinds in my automation (Ikea, Philips, innr, Paulmann, Osram). Regardless of whether these are grouped in ZHA or not. Only turning the AL switch off solves the problem permanently. That is really very annoying - otherwise the integration is great.

Same issue for me, ZHA with conbee2. I have aurora dimmer, dumb lamps. Only happens when the adaption is running and light turned off before it completes. Usually turns on full brightness in the day as I tend to override turning the light off although I have managed to turn off the lights in the evening before fully dim and they've turned back on.

Same here. ZHA with Conbee 2. Four Hue bulbs set up in a ZHA zigbee group. After installing and setting up Adaptive Lighting I'm unable to turn them off permanently in the evening. They're controlled by an automation calling light.turn_off after a 5 minutes of no motion. I can also turn them off manually with my bedside Hue dimmer. They consistently turn back on after a few seconds.

WAF took a huge hit last night after my wife triggered the motion sensor and could not get the lights to turn off again at all. They stayed on all night.

We're both very happy with how our lights behave after installing Adaptive Lighting, Really excellent work! However, this issue specifically makes AL not usable for us.

I also had this issue since implementing adaptive lighting. I think I finally found the culprit.

What I did:

Going into HA > Configuration > Integrations > Adaptive Lighting, then selecting the group that is turning back on
Select Options
Find "Transition" then drop that value down to something minimal, like 1.

I haven't played around with other values, this may be able to be higher than 1, but I've confirmed a transition set to 1 will prevent the light that just turned off from turning back on immediately after.

I also had this issue since implementing adaptive lighting. I think I finally found the culprit.

What I did:
* Going into HA > Configuration > Integrations > Adaptive Lighting, then selecting the group that is turning back on

* Select Options

* Find "Transition" then drop that value down to something minimal, like 1.
I haven't played around with other values, this may be able to be higher than 1, but I've confirmed a transition set to 1 will prevent the light that just turned off from turning back on immediately after.

Okay, so that supports the theory that this bug occurs when the lights are turned off during an ongoing transition - Lowering the transition time reduces the likelihood of this happening.

I'll definitely try lowering the transition time and find a good compromise between transition time and interval. As long as the transitions aren't too noticeable that should work fine.

Of course, there's will still be a chance that this bug occurs but it should be rare.

So that's the issue! I just finished migrating away from Magic Areas and Adaptive Lighting to a cool Circadian subroutine and Node-RED. I finally delved into NR a week ago and after many MANY hours I have my motion routines setup and circadian implemented where I have dimmable, color controlled bulbs.

So I've spent what seems like an eternity inside Node_RED implementing my own version of Magic Areas and Adaptive Lighting using code from Circadian/Adaptive Lighting NodeRed. I've experienced the light(s)s turning back on if turned off within the transition period within my Node-RED implementation. Bedroom Lamp 1 (Sengled Zigbee) was doing it. It was part of a zigbee group bedroom_lights with bedroom_lamp_1 and bedroom_lamp2. I removed the group and experimented with the individual lights and only lamp_1 has the problem, not lamp_2, BUT only when turning it off from the HA UI! If I turn it off from a button injection in Node-RED, no problem. So, the issue would seem to lie somewhere (deep) within HA and only when HA is controlling the light AND seems to be device dependent since lamp 2 is not affected. I have 5 of these bulbs and all have the same firmware so its not that. I've not played yet with the 3 bulbs in the office or the dimmer switch for the bathroom lights where I also saw random turn-ons...

It's also an issue from here...

IMO, it's NOT Adaptive Lighting, it's HA. If I turn the lights on from within HA UI (which triggers my circadian routine in NR with transition of 10s) and then turn them off within the transition time of 10s, lamp_1 turns back on...

I also tested with two different browser views into HA...one where I called service light.turn_on with a transition of 20s and one with light.turn_off and was able to reproduce the problem WITH MY NR CIRCADIAN DISABLED!

Lamp 1 came back on...

Wow, @danielbrunt57! Thanks a lot for your excellent analysis. I already had a suspicion that this wasn't related to Adaptive-lighting itself because nothing in the logs indicates that this should happen.

What do you think would be your suggestion to tackle this problem?

I think we wait for HA to review issue #48534.
It is very late here but it kind of looks like an issue with core to me. Since posting I did experience a lamp_1 turn on using a transition of 0 and also no transition in my circadian routine so it's possible it might be something in ZHA since only lamp_1 is turning back on and not lamp_2. Strange though that it's only when the service is called straight from HA. If I trigger off from NR it does not come back on...

The issue seems to occur when the brightness_pct is different from the previous one. usingtransition: 20

9:26:00 turn_on transition: 20 brightness_pct: 80 9:26:00 turn_off

9:27:45 turn_on transition: 20 brightness_pct: 90 9:27:50 turn_on 9:28:05 turned on by itself

9:29:00 turn_on transition: 20 brightness_pct: 90 9:29:05 turn_off

9:30:00 turn_on transition: 20 brightness_pct: 70 Note: no logbook entry for this 9:30:05 turn_off Note: no logbook entry for this 9:30:20 turned on by itself

2021-03-31 09:25:53 DEBUG (MainThread) [zigpy.zcl] [0x091a:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x8f request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x90 request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=143 command_id=Command.Default_Response>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x91 request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=144 command_id=Command.Default_Response>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=145 command_id=Command.Default_Response>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=60 command_id=Command.Report_Attributes>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x92 request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x93 request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=147 command_id=Command.Default_Response>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=146 command_id=Command.Default_Response>
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x94 request
2021-03-31 09:26:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=148 command_id=Command.Default_Response>
2021-03-31 09:26:05 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x95 request
2021-03-31 09:26:05 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x96 request
2021-03-31 09:26:05 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=149 command_id=Command.Default_Response>
2021-03-31 09:26:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=150 command_id=Command.Default_Response>
2021-03-31 09:26:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=61 command_id=Command.Report_Attributes>
2021-03-31 09:26:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:26:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:26:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=30 command_id=Command.Read_Attributes>
2021-03-31 09:26:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:26:09 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=111 command_id=Command.Report_Attributes>
2021-03-31 09:26:09 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32548>)]]
2021-03-31 09:26:09 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32548
2021-03-31 09:26:32 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=62 command_id=Command.Report_Attributes>
2021-03-31 09:26:32 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:26:32 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:26:33 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=94 command_id=Command.Report_Attributes>
2021-03-31 09:26:33 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:26:33 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:26:39 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=142 command_id=Command.Report_Attributes>
2021-03-31 09:26:39 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32594>)]]
2021-03-31 09:26:39 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32594
2021-03-31 09:26:44 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0019] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=39 command_id=1>
2021-03-31 09:26:44 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0019] ZCL request 0x0001: [0, 4448, 1, 46, None]
2021-03-31 09:26:44 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0019] OTA query_next_image handler for 'sengled Z01-A19NAE26': field_control=0, manufacture_id=4448, image_type=1, current_file_version=46, hardware_version=None
2021-03-31 09:26:44 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0019] No OTA image is available
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x97 request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x98 request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=151 command_id=Command.Default_Response>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x99 request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=153 command_id=Command.Default_Response>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x9a request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=152 command_id=Command.Default_Response>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=63 command_id=Command.Report_Attributes>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x9b request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=154 command_id=Command.Default_Response>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=155 command_id=Command.Default_Response>
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x9c request
2021-03-31 09:26:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=156 command_id=Command.Default_Response>
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x9d request
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0x9e request
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=157 command_id=Command.Default_Response>
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=158 command_id=Command.Default_Response>
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=64 command_id=Command.Report_Attributes>
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:26:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=11 command_id=Command.Report_Attributes>
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=151>)]]
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] Attribute report received: measured_value=151
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=12 command_id=Command.Report_Attributes>
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=bitmap8, value=bitmap8.1>)]]
2021-03-31 09:26:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] Attribute report received: occupancy=1
2021-03-31 09:27:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=91 command_id=Command.Read_Attributes>
2021-03-31 09:27:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:27:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=173 command_id=Command.Report_Attributes>
2021-03-31 09:27:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32524>)]]
2021-03-31 09:27:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32524
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=65 command_id=Command.Report_Attributes>
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=97 command_id=Command.Report_Attributes>
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:27:17 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:27:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=204 command_id=Command.Report_Attributes>
2021-03-31 09:27:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32505>)]]
2021-03-31 09:27:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32505
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0x9f request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xa0 request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=159 command_id=Command.Default_Response>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xa1 request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=161 command_id=Command.Default_Response>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xa2 request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=160 command_id=Command.Default_Response>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xa3 request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=66 command_id=Command.Report_Attributes>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=162 command_id=Command.Default_Response>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=163 command_id=Command.Default_Response>
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xa4 request
2021-03-31 09:27:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=164 command_id=Command.Default_Response>
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xa5 request
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xa6 request
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=165 command_id=Command.Default_Response>
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=166 command_id=Command.Default_Response>
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=67 command_id=Command.Report_Attributes>
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:27:51 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=13 command_id=Command.Report_Attributes>
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=150>)]]
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] Attribute report received: measured_value=150
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=14 command_id=Command.Report_Attributes>
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=bitmap8, value=bitmap8.1>)]]
2021-03-31 09:27:59 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] Attribute report received: occupancy=1
2021-03-31 09:28:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=68 command_id=Command.Report_Attributes>
2021-03-31 09:28:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:28:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:28:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=152 command_id=Command.Read_Attributes>
2021-03-31 09:28:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:28:07 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=69 command_id=Command.Report_Attributes>
2021-03-31 09:28:07 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=230>)]]
2021-03-31 09:28:07 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] Attribute report received: current_level=230
2021-03-31 09:28:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=235 command_id=Command.Report_Attributes>
2021-03-31 09:28:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32558>)]]
2021-03-31 09:28:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32558
2021-03-31 09:28:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=10 command_id=Command.Report_Attributes>
2021-03-31 09:28:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32531>)]]
2021-03-31 09:28:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32531
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xa7 request
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xa8 request
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=167 command_id=Command.Default_Response>
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=168 command_id=Command.Default_Response>
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=70 command_id=Command.Report_Attributes>
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:28:46 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xa9 request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xaa request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=169 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xab request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=171 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xac request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=170 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xad request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=71 command_id=Command.Report_Attributes>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=172 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=173 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xae request
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=174 command_id=Command.Default_Response>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=15 command_id=Command.Report_Attributes>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=161>)]]
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] Attribute report received: measured_value=161
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=16 command_id=Command.Report_Attributes>
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=bitmap8, value=bitmap8.1>)]]
2021-03-31 09:29:01 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] Attribute report received: occupancy=1
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xaf request
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xb0 request
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=175 command_id=Command.Default_Response>
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=176 command_id=Command.Default_Response>
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=72 command_id=Command.Report_Attributes>
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:29:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:29:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=213 command_id=Command.Read_Attributes>
2021-03-31 09:29:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:29:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=41 command_id=Command.Report_Attributes>
2021-03-31 09:29:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32756>)]]
2021-03-31 09:29:08 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32756
2021-03-31 09:29:19 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=True disable_default_response=True> manufacturer=4447 tsn=226 command_id=Command.Report_Attributes>
2021-03-31 09:29:19 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x0000] ZCL request 0x000a: [[Attribute(attrid=65281, value=<TypeValue type=CharacterString, value=(! >)]]
2021-03-31 09:29:19 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x0000] Attribute report received: 65281=(!
2021-03-31 09:29:32 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=105 command_id=Command.Report_Attributes>
2021-03-31 09:29:32 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:29:32 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:29:33 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=73 command_id=Command.Report_Attributes>
2021-03-31 09:29:33 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] ZCL request 0x000a: [[Attribute(attrid=1024, value=<TypeValue type=int24s, value=0>)]]
2021-03-31 09:29:33 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0702] Attribute report received: instantaneous_demand=0
2021-03-31 09:29:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=72 command_id=Command.Report_Attributes>
2021-03-31 09:29:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32772>)]]
2021-03-31 09:29:38 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32772
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xddf0] Extending timeout for 0xb1 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xadc7] Extending timeout for 0xb2 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xe256] Extending timeout for 0xb3 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=177 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xddf0] Extending timeout for 0xb4 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=178 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xadc7] Extending timeout for 0xb5 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=180 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xddf0] Extending timeout for 0xb6 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=181 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xadc7] Extending timeout for 0xb7 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=179 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xe256] Extending timeout for 0xb8 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=183 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=182 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=184 command_id=Command.Default_Response>
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.device] [0xe256] Extending timeout for 0xb9 request
2021-03-31 09:29:48 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=185 command_id=Command.Default_Response>
2021-03-31 09:29:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=74 command_id=Command.Report_Attributes>
2021-03-31 09:29:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL request 0x000a: [[Attribute(attrid=7, value=<TypeValue type=uint16_t, value=370>)]]
2021-03-31 09:29:49 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] Attribute report received: color_temperature=370
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=40 command_id=Command.Report_Attributes>
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=251>)]]
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] Attribute report received: current_level=251
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=87 command_id=Command.Report_Attributes>
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=251>)]]
2021-03-31 09:29:54 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] Attribute report received: current_level=251
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=41 command_id=Command.Report_Attributes>
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=252>)]]
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xadc7:1:0x0008] Attribute report received: current_level=252
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=88 command_id=Command.Report_Attributes>
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=252>)]]
2021-03-31 09:29:59 DEBUG (MainThread) [zigpy.zcl] [0xe256:1:0x0008] Attribute report received: current_level=252
2021-03-31 09:30:01 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xba request
2021-03-31 09:30:01 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xbb request
2021-03-31 09:30:01 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=186 command_id=Command.Default_Response>
2021-03-31 09:30:01 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=187 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xbc request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xbd request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=188 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xbe request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=189 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xbf request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=190 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xd357] Extending timeout for 0xc0 request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xd357:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=192 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=191 command_id=Command.Default_Response>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.device] [0xaa58] Extending timeout for 0xc1 request
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=75 command_id=Command.Report_Attributes>
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0006] Attribute report received: on_off=1
2021-03-31 09:30:06 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=193 command_id=Command.Default_Response>
2021-03-31 09:30:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=19 command_id=Command.Read_Attributes>
2021-03-31 09:30:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:30:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=103 command_id=Command.Report_Attributes>
2021-03-31 09:30:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32777>)]]
2021-03-31 09:30:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32777
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=17 command_id=Command.Report_Attributes>
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=162>)]]
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0400] Attribute report received: measured_value=162
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=18 command_id=Command.Report_Attributes>
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=bitmap8, value=bitmap8.1>)]]
2021-03-31 09:30:16 DEBUG (MainThread) [zigpy.zcl] [0xd083:1:0x0406] Attribute report received: occupancy=1
2021-03-31 09:30:27 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=76 command_id=Command.Report_Attributes>
2021-03-31 09:30:27 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=178>)]]
2021-03-31 09:30:27 DEBUG (MainThread) [zigpy.zcl] [0xaa58:1:0x0008] Attribute report received: current_level=178
2021-03-31 09:30:37 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=134 command_id=Command.Report_Attributes>
2021-03-31 09:30:37 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32781>)]]
2021-03-31 09:30:37 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32781
2021-03-31 09:30:53 DEBUG (MainThread) [zigpy.zcl] [0x091a:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=53 command_id=Command.Report_Attributes>
2021-03-31 09:30:53 DEBUG (MainThread) [zigpy.zcl] [0x091a:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.false>)]]
2021-03-31 09:30:53 DEBUG (MainThread) [zigpy.zcl] [0x091a:1:0x0006] Attribute report received: on_off=0
2021-03-31 09:30:55 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0019] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=100 command_id=1>
2021-03-31 09:30:55 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0019] ZCL request 0x0001: [0, 4448, 1, 46, None]
2021-03-31 09:30:55 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0019] OTA query_next_image handler for 'sengled Z01-A19NAE26': field_control=0, manufacture_id=4448, image_type=1, current_file_version=46, hardware_version=None
2021-03-31 09:30:55 DEBUG (MainThread) [zigpy.zcl] [0xddf0:1:0x0019] No OTA image is available
2021-03-31 09:31:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=80 command_id=Command.Read_Attributes>
2021-03-31 09:31:07 DEBUG (MainThread) [zigpy.zcl] [0x475e:1:0x000a] ZCL request 0x0000: [[0]]
2021-03-31 09:31:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=165 command_id=Command.Report_Attributes>
2021-03-31 09:31:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint16_t, value=32786>)]]
2021-03-31 09:31:07 DEBUG (MainThread) [zigpy.zcl] [0x45d7:1:0x0400] Attribute report received: measured_value=32786

Edit: never mind. Happened to me again today.

So I had this happen to me for the first time today. I have been using this integration for a long while but decided to start fresh and setup a new HA instance. Now I have not read all the posts in here but my first reaction was to check my groups.

So my scenario is from the living room. I have AL on the light group for all my living room lights (not on the lights themselves) and I do have a group that just contains the lights I want to turn off when the tv is on. So when light.livingroom is still technically on even when light.tv is off so I think it applied the transition to the turned off tv lights as AL was set to use the light.livingroom and that’s why the tv lights turns on even when they should not.

I tested it out and put the light.livingroom to my tv automation instead of just turning off them tv lights and the problem was gone. Not sure if it’s related but that’s my finding.

I use deconz with ikea bulbs and ikea 5 way buttons. a few seconds after I turn off a group of lights using the ikea button, and one or two random lights will turn back on. Is this there any solution for this yet?

@sevorl The problem is not Adaptive Lighting! It ONLY controls lights that show as ON in Home Assistant.

Home Assistant is still showing the light as ON when it is physically off. Disable AL, sit in front of HA and observe the state of the lights as you turn them off with your buttons. I have, and I've seen it with my two groups of Sengled Zigbee bulbs. Another anomaly I've seen is using a transition with a group can also cause HA to get out of sync. It depends on a lot of factors one of which may be that while transitioning to off, the light(s) report an intermediate brightness state causing HA to toggle its state back to on, then the light reaches off and that message gets lost somewhere...

I've had lights randomly go on in the middle of the night, with nothing to trigger them. Not saying it's AL, but I never had this happen until I started using AL.

When I turn lights off with the switch, they will show as off in ha immediately. Also, this did not happen before I started using AL. I will test further though to see if I can reproduce this when AL is off, or if it would disappear without transitioning time.

@broyuken I feel like this might be a different problem. Can you create a dedicated ticket for this - this way it won't get lost. :)

basnijholt / adaptive-lighting

Lights randomly come back on after shut off #10