Startup Delay / Error #5

mekenthompson · 2022-01-13T08:29:49Z

After restart sometimes there's a delay until light entites are available even though it looks like the integration has discovered them successfully.

Logger: homeassistant
Source: custom_components/lifx/light.py:774
Integration: LIFX (documentation, issues)
First occurred: 19:12:15 (3 occurrences)
Last logged: 19:12:15

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 382, in async_add_entities
    await asyncio.gather(*tasks)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 613, in _async_add_entity
    await entity.add_to_platform_finish()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 748, in add_to_platform_finish
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 505, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 540, in _async_write_ha_state
    attr.update(self.state_attributes or {})
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 882, in state_attributes
    color_mode = self._light_internal_color_mode
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 723, in _light_internal_color_mode
    if COLOR_MODE_HS in supported and self.hs_color is not None:
  File "/config/custom_components/lifx/light.py", line 774, in hs_color
    hue, sat, _
[hass_lifx_beta_error_logs.log](https://github.com/Djelibeybi/ha-lifx-beta/files/7861134/hass_lifx_beta_error_logs.log)
, _ = self.bulb.color
TypeError: cannot unpack non-iterable NoneType object

Full log attached
hass_lifx_beta_error_logs.log

The text was updated successfully, but these errors were encountered:

Djelibeybi · 2022-01-13T09:11:08Z

What kind of bulbs do you have?

mekenthompson · 2022-01-13T10:06:01Z

I've got a mix of: - Downlight Colour - Z-Strip - Beam - Mini Colour Get Outlook for Android<https://aka.ms/AAb9ysg>

…

________________________________ From: Avi Miller ***@***.***> Sent: Thursday, January 13, 2022 8:11:19 PM To: Djelibeybi/ha-lifx-beta ***@***.***> Cc: Ken Thompson ***@***.***>; Author ***@***.***> Subject: Re: [Djelibeybi/ha-lifx-beta] Startup Delay / Error (Issue #5) What kind of bulbs do you have? — Reply to this email directly, view it on GitHub<https://apac01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FDjelibeybi%2Fha-lifx-beta%2Fissues%2F5%23issuecomment-1011938709&data=04%7C01%7C%7C7747edb6958748aaaf8908d9d674ca05%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637776619394541151%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=74qXrgRn4IKhXg19auyzV%2BIwtE1NzqxMjzL0f06ccYw%3D&reserved=0>, or unsubscribe<https://apac01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FACECWCK73ZFYBSTIIGJ5L6TUV2JLPANCNFSM5L3E6HCA&data=04%7C01%7C%7C7747edb6958748aaaf8908d9d674ca05%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C637776619394541151%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=%2Fyr39NKMJ6ZbbqogK7WQKcF%2F%2FoqgdZqLsc40Cenu9Wg%3D&reserved=0>. You are receiving this because you authored the thread.Message ID: ***@***.***>

Djelibeybi · 2022-01-13T10:28:10Z

Can you bump the message reply timeout to 1 second? You can edit this by hitting the Configure button in the UI. I can't reproduce the issue (and I have almost the identical setup, with a similar network config and collection of bulbs).

mekenthompson · 2022-01-13T11:05:31Z

Updated, now getting more errors at restart...

Log Details (ERROR)
This error originated from a custom integration.
Logger: custom_components.lifx
Source: custom_components/lifx/light.py:440
Integration: LIFX (documentation, issues)
First occurred: 21:59:42 (32 occurrences)
Last logged: 21:59:45

(Discovery) action=restart, ip_addr=192.168.2.107.
(Discovery) action=restart, ip_addr=192.168.2.122.
(Discovery) action=restart, ip_addr=192.168.2.104.
(Discovery) action=restart, ip_addr=192.168.2.131.
(Discovery) action=restart, ip_addr=192.168.2.38.

Here's some around activity around 192.168.2.107 which had some issues:

022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Discovery) action=received_response, serial=d073d52ecc20, ip_addr=192.168.2.107
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=1, ack=0, resp=1, dest=192.168.2.107
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Discovery) action=received_response, serial=d073d56333c6, ip_addr=192.168.3.156
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=1, ack=0, resp=1, dest=192.168.3.156
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Discovery) action=received_response, serial=d073d52ece1b, ip_addr=192.168.2.38
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Discovery) action=received_response, serial=d073d52ec889, ip_addr=192.168.2.122
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=1, ack=0, resp=1, dest=192.168.2.38
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=1, ack=0, resp=1, dest=192.168.2.122
2022-01-13 21:59:39 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, MultiZoneStateMultiZone, pkt=506, seq=5, ack=0, resp=1, src=192.168.2.132
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Discovery) countdown=55, step=5
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.3.247
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.106
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.114
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.105
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.104
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.131
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.120
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.121
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.134
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.118
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.107
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.3.156
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.38
2022-01-13 21:59:40 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, LightGet, pkt=101, seq=2, ack=0, resp=1, dest=192.168.2.122
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.114
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.114
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.105
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.105
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.106
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.106
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.131
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.121
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.120
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.131
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.121
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.120
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.107
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.107
2022-01-13 21:59:41 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Roomba' for roomba integration not ready yet; Retrying in background
2022-01-13 21:59:41 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.114
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.121
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.134
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.134
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.120
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.107
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.3.247.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.106.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.114.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.105.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.104.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.131.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.120.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.121.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.134.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.118.
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.106
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.106
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.114
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.114
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.105
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.105
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.120
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.120
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.121
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.121
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.134
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.134
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.107.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.3.156.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.38.
2022-01-13 21:59:42 ERROR (MainThread) [custom_components.lifx] (Discovery) action=restart, ip_addr=192.168.2.122.
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.118
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=3, ack=0, resp=1, dest=192.168.2.118
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=received, StateVersion, pkt=33, seq=1, ack=0, resp=1, src=192.168.2.107
2022-01-13 21:59:42 DEBUG (MainThread) [custom_components.lifx] (Get State) action=send, GetVersion, pkt=32, seq=4, ack=0, resp=1, dest=192.168.2.107

Djelibeybi · 2022-01-13T20:20:42Z

Those aren't actual errors, I'm just using the wrong log levels. But it does indicate that your network is very busy, I think. Can you bump the message reply timeout again to 3 seconds? Most of your bulbs are replying, but not within the timeout.

Djelibeybi · 2022-01-13T20:21:06Z

You'll need to adjust discovery interval as well. I'd put that up at 300 or so.

mekenthompson · 2022-01-14T01:21:51Z

I've done that, so now it's waiting until 300 secs after HASS bootup before they're available and HASS flags it's "fully started".

I can see the lights registering multiple times before discovery ends though. Do they not register as available entities until that Discovery time has fully completed though?

Djelibeybi · 2022-01-14T01:45:54Z

That's really weird. I'll have to try and work out what's going on over the weekend.

Djelibeybi · 2022-01-14T01:55:19Z

I've just double-checked my test/dev instance and all 59 of my bulbs are discovered and active before the timer for the next discovery starts. It also completes the initial discovery in ~4 seconds. That's with a 300 second discovery interval and a 1 second message response timeout.

Djelibeybi · 2022-01-14T01:58:01Z

For reference, here are the settings I'm using for test purposes.

Djelibeybi · 2022-04-23T01:25:43Z

This should be resolved by home-assistant/core#70458 when it is merged to the core.

Djelibeybi closed this as completed Apr 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Startup Delay / Error #5

Startup Delay / Error #5

mekenthompson commented Jan 13, 2022 •

edited

Loading

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 13, 2022 via email

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 13, 2022

Djelibeybi commented Jan 13, 2022

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Apr 23, 2022

Startup Delay / Error #5

Startup Delay / Error #5

Comments

mekenthompson commented Jan 13, 2022 • edited Loading

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 13, 2022 via email

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 13, 2022

Djelibeybi commented Jan 13, 2022

Djelibeybi commented Jan 13, 2022

mekenthompson commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Jan 14, 2022

Djelibeybi commented Apr 23, 2022

mekenthompson commented Jan 13, 2022 •

edited

Loading