home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
69.87k stars 28.97k forks source link

Tradfri light, various frequent errors: KeyError: '3311', NoneType' object does not support item assignment #85254

Open Mariusthvdb opened 1 year ago

Mariusthvdb commented 1 year ago

The problem

as logged in the beta a couple of times, below error(s) is (are) in the logs.

Update: Not sure if it is actually causing functionality issues, but is is so frequent, something really is not ok.

time has shown this is causing frequent (multiple times daily) connection issues, and Tradfri not responding/communicating to the Gateway any longer. The Gateway btw being fully functional standalone communicating correctly with the Ikea app.

What version of Home Assistant Core has the issue?

2023.1

What was the last working version of Home Assistant Core?

2022.12

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Tradfri

Link to integration documentation on our website

https://www.home-assistant.io/integrations/tradfri/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: homeassistant
Source: components/tradfri/light.py:93 
First occurred: 18:11:09 (5256 occurrences) 
Last logged: 22:02:15

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 168, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update
    self._refresh()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh
    self._device_data = self.coordinator.data.light_control.lights[0]
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 84, in light_control
    return LightControl(self)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 40, in __init__
    if ATTR_LIGHT_DIMMER in self.raw[0]:
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 71, in raw
    return self._device.raw[ATTR_LIGHT_CONTROL]
KeyError: '3311'

and 

Logger: homeassistant.util.logging
Source: util/logging.py:156 
First occurred: 18:11:53 (451 occurrences) 
Last logged: 22:01:55

Exception in set_hub_available when dispatching 'tradfri.gw_status': (True,)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 47, in set_hub_available
    await self.async_request_refresh()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 175, in async_request_refresh
    await self._debounced_refresh.async_call()
  File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 82, in async_call
    await task
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 201, in async_refresh
    await self._async_refresh(log_failures=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update
    self._refresh()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh
    self._device_data = self.coordinator.data.light_control.lights[0]
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 84, in light_control
    return LightControl(self)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 40, in __init__
    if ATTR_LIGHT_DIMMER in self.raw[0]:
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 71, in raw
    return self._device.raw[ATTR_LIGHT_CONTROL]
KeyError: '3311'

Logger: homeassistant.components.tradfri
Source: helpers/update_coordinator.py:201 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 18:11:02 (2 occurrences) 
Last logged: 18:11:04

Error fetching Update coordinator for <65583 - Parking light (TRADFRI bulb E27 W opal 1000lm)> data: Error communicating with API: Gateway payload: {"r":"02"}. Error code: 4.00 Bad Request..
Error fetching Update coordinator for <65714 - Mademoiselle Filou (TRADFRI bulb E14 W op/ch 400lm)> data: Error communicating with API: Gateway payload: {"r":"02"}. Error code: 4.00 Bad Request..

Logger: homeassistant.components.tradfri
Source: components/tradfri/light.py:93 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 18:11:09 (2 occurrences) 
Last logged: 18:12:48

Unexpected error fetching Update coordinator for <65714 - Mademoiselle Filou (TRADFRI bulb E14 W op/ch 400lm)> data: '3311'
Unexpected error fetching Update coordinator for <65583 - Parking light (TRADFRI bulb E27 W opal 1000lm)> data: '3311'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 225, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 88, in _async_update_data
    await self.api(cmd)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 199, in request
    result = await self._execute(api_commands, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 137, in _execute
    await self._observe(api_command, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 220, in _observe
    api_command.result = _process_output(pr_rsp)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/command.py", line 91, in result
    self._result = self._process_result(value)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/resource.py", line 62, in observe_callback
    callback(self)
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 52, in _observe_update
    self.async_set_updated_data(data=device)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 346, in async_set_updated_data
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update
    self._refresh()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh
    self._device_data = self.coordinator.data.light_control.lights[0]
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 84, in light_control
    return LightControl(self)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 40, in __init__
    if ATTR_LIGHT_DIMMER in self.raw[0]:
  File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 71, in raw
    return self._device.raw[ATTR_LIGHT_CONTROL]
KeyError: '3311'

Logger: homeassistant.components.tradfri
Source: components/tradfri/coordinator.py:77 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 18:14:03 (50 occurrences) 
Last logged: 18:14:03

Unexpected error fetching Update coordinator for <65641 - Master bed outlet (TRADFRI control outlet)> data: Retransmissions exceeded
Unexpected error fetching Update coordinator for <65741 - Ster rechts (TRADFRI bulb E14 WS 470lm)> data: Retransmissions exceeded
Unexpected error fetching Update coordinator for <65719 - Bureau left (TRADFRI bulb E14 WS opal 400lm)> data: Retransmissions exceeded
Unexpected error fetching Update coordinator for <65740 - Ster links (TRADFRI bulb E14 WS 470lm)> data: Retransmissions exceeded
Unexpected error fetching Update coordinator for <65701 - Guest room afstandsbediening (TRADFRI remote control)> data: Retransmissions exceeded
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 225, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 77, in _async_update_data
    raise exc
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 107, in _get_response
    pr_resp = await asyncio.wait_for(pr_req.response, timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 408, in wait_for
    return await fut
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 612, in _run_outer
    await cls._run(app_request, response, weak_observation, protocol, log)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 671, in _run
    blockresponse = await blockrequest.response
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 897, in __del__
    self._future.result()
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 897, in __del__
    self._future.result()
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 897, in __del__
    self._future.result()
  [Previous line repeated 1 more time]
aiocoap.error.ConRetransmitsExceeded: Retransmissions exceeded

Additional information

Aware several other new Tradfri issues have been logged, I decided to create this separate, because the logging is different.

https://github.com/home-assistant/core/issues/85105 https://github.com/home-assistant/core/issues/84624

home-assistant[bot] commented 1 year ago

tradfri documentation tradfri source

Mariusthvdb commented 1 year ago

some extra and ridiculously frequent logging:

Logger: root
Source: /usr/src/homeassistant/homeassistant/bootstrap.py:383 
First occurred: 03:17:26 (343646 occurrences) 
Last logged: 12:58:14

Uncaught exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aiocoap/transports/tinydtls.py", line 174, in wrapper
    return getattr(self, __method)(*args)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/transports/tinydtls.py", line 284, in _read
    self.coaptransport.ctx.dispatch_message(message)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/messagemanager.py", line 115, in dispatch_message
    success = self._process_response(message)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/messagemanager.py", line 341, in _process_response
    return self.token_manager.process_response(response)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/tokenmanager.py", line 171, in process_response
    if key not in self.outgoing_requests:
TypeError: argument of type 'NoneType' is not iterable

and

Logger: homeassistant.components.tradfri
Source: components/tradfri/coordinator.py:88 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 03:15:54 (345599 occurrences) 
Last logged: 12:58:14

Unexpected error fetching Update coordinator for <65606 - Hallway dresser bewegingssensor (TRADFRI motion sensor)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65709 - Corridor pool (TRADFRIbulbT120E27WSopal470lm)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65583 - Parking light (TRADFRI bulb E27 W opal 1000lm)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65670 - Garage afstandsbediening (TRADFRI remote control)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65716 - Symfonisk afstandsbediening (SYMFONISK Sound Controller)> data: 'NoneType' object does not support item assignment
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 225, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 88, in _async_update_data
    await self.api(cmd)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 199, in request
    result = await self._execute(api_commands, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 137, in _execute
    await self._observe(api_command, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 218, in _observe
    pr_req, pr_rsp = await self._get_response(msg, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 107, in _get_response
    pr_resp = await asyncio.wait_for(pr_req.response, timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 408, in wait_for
    return await fut
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 612, in _run_outer
    await cls._run(app_request, response, weak_observation, protocol, log)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 671, in _run
    blockresponse = await blockrequest.response
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 355, in send
    request_interface.request(pipe)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/tokenmanager.py", line 256, in request
    self.outgoing_requests[key] = request
TypeError: 'NoneType' object does not support item assignment
Mariusthvdb commented 1 year ago
Logger: homeassistant.util.logging
Source: util/logging.py:156 
First occurred: 7 januari 2023 om 19:32:55 (1166 occurrences) 
Last logged: 00:28:58

Exception in set_hub_available when dispatching 'tradfri.gw_status': (True,) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 47, in set_hub_available await self.async_request_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 175, in async_request_refresh await self._debounced_refresh.async_call() File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 82, in async_call await task File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 201, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update self._refresh() File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh self._device_data = self.coordinator.data.light_control.lights[0] File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 84, in light_control return LightControl(self) File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 40, in __init__ if ATTR_LIGHT_DIMMER in self.raw[0]: File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 71, in raw return self._device.raw[ATTR_LIGHT_CONTROL] KeyError: '3311'
Exception in set_hub_available when dispatching 'tradfri.gw_status': (True,) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 47, in set_hub_available await self.async_request_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 175, in async_request_refresh await self._debounced_refresh.async_call() File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 82, in async_call await task File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 201, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update self._refresh() File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh self._device_data = self.coordinator.data.light_control.lights[0] File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 84, in light_control return LightControl(self) File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 40, in __init__ if ATTR_LIGHT_DIMMER in self.raw[0]: File "/usr/local/lib/python3.10/site-packages/pytradfri/device/light_control.py", line 71, in raw return self._device.raw[ATTR_LIGHT_CONTROL] TypeError: 'NoneType' object is not subscriptable
Exception in set_hub_available when dispatching 'tradfri.gw_status': (True,) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 47, in set_hub_available await self.async_request_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 175, in async_request_refresh await self._debounced_refresh.async_call() File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 82, in async_call await task File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 201, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update self._refresh() File "/usr/src/homeassistant/homeassistant/components/tradfri/sensor.py", line 212, in _refresh self._attr_native_value = self.entity_description.value(self.coordinator.data) File "/usr/src/homeassistant/homeassistant/components/tradfri/sensor.py", line 83, in <lambda> value=lambda device: cast(int, device.device_info.battery_level), File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 195, in battery_level if ATTR_DEVICE_BATTERY not in self.raw: File "/usr/local/lib/python3.10/site-packages/pytradfri/device/__init__.py", line 203, in raw return cast(TypeDeviceInfo, self._device.raw[ATTR_DEVICE_INFO]) TypeError: 'NoneType' object is not subscriptable
Mariusthvdb commented 1 year ago

and counting the endless errors.. currently on 2023.2.5

Scherm­afbeelding 2023-01-20 om 13 04 30

also:

Logger: homeassistant.components.tradfri
Source: components/tradfri/base_class.py:32 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 16:06:59 (6 occurrences) 
Last logged: 16:07:28

Unable to execute command <Command put ['15001', 65695]: {'3311': [{'5850': 1}]}>: Gateway payload: {"r":"02"}. Error code: 4.00 Bad Request.
Unable to execute command <Command put ['15001', 65730]: {'3311': [{'5850': 1}]}>: Gateway payload: {"r":"02"}. Error code: 4.00 Bad Request.
Mariusthvdb commented 1 year ago

This might be the most frequent logger, every 5 seconds:

2023-01-22 00:14:40.494 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 168, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 316, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 121, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 71, in _handle_coordinator_update
    self._refresh()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/fan.py", line 77, in _refresh
    self._device_data = self.coordinator.data.air_purifier_control.air_purifiers[0]
AttributeError: 'NoneType' object has no attribute 'air_purifiers'
Mariusthvdb commented 1 year ago

Martin confirmed that nothing significant has changed in PyTradfri library, so what else would it be?

Mariusthvdb commented 1 year ago

noticed pytrafdri was just updated with a huge amount of new stuff. maybe that helps to fix this.. https://github.com/home-assistant-libs/pytradfri/releases/tag/12.0.0

MartinHjelmare commented 1 year ago

Note that I said that nothing significant has changed in the integration in recent releases:

https://github.com/home-assistant-libs/pytradfri/issues/617#issuecomment-1399367301

h4rm commented 1 year ago

Have the same error, started at the same time you saw it.

Mariusthvdb commented 1 year ago

Nick is on to something, please see https://github.com/home-assistant/core/issues/86083#issuecomment-1416402508

Mariusthvdb commented 1 year ago

Note that I said that nothing significant has changed in the integration in recent releases:

home-assistant-libs/pytradfri#617 (comment)

sure Martin, that was noted. However, as it seems things might have changed on the Tradfri side of things? It has become a steady issue, and am surprised so few people respond here. The logs are littered with many thousands of lines, and only a HA restart stops it from happening. Until it all starts over

MartinHjelmare commented 1 year ago

Most of the problems historically have been caused by the gateway and problems in the gateway firmware.

For me it's been working fine for months now.

Mariusthvdb commented 1 year ago

Maybe it depends on the (number of) devices one has included on the gateway ?

This issue has been around 2 HA cycles now.

Only thing locally changed was the addition of 2 lights and a remote for that , which now have been deleted again.

Maybe they were the overload of allowed number of devices so I took them out to be sure

Yet, the issue persists.... heavily

h4rm commented 1 year ago

I oddly fixed it by extending the DHCP release time from 24 hours to days. I had the hub configured with a fixed IP for obvious reasons and somehow the DHCP scrambled the connection for the integration. Maybe that helps someone here. In the meantime I bought the new IKEA Dirigera hub which comes with its own challenges :-)

Mariusthvdb commented 1 year ago

I do have it set to a fixed Ip on my Unifi Udm pro, but have not lease time configured. Or so I think...

Mariusthvdb commented 1 year ago

Just an update , and do note the occurrences count...

Logger: homeassistant.components.tradfri
Source: components/tradfri/coordinator.py:88 
Integration: IKEA TRÅDFRI (documentation, issues) 
First occurred: 16:47:41 (97205 occurrences) 
Last logged: 19:52:15

Unexpected error fetching Update coordinator for <65705 - Antiek afstandsbediening (TRADFRI on/off switch)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65683 - Library bewegingssensor (TRADFRI motion sensor)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65680 - Antiek (TRADFRI bulb E27 WW clear 250lm)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65719 - Bureau left (TRADFRI bulb E14 WS opal 400lm)> data: 'NoneType' object does not support item assignment
Unexpected error fetching Update coordinator for <65678 - Bedside guest room left (TRADFRI bulb E27 CWS opal 600lm)> data: 'NoneType' object does not support item assignment
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 239, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 88, in _async_update_data
    await self.api(cmd)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 199, in request
    result = await self._execute(api_commands, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 137, in _execute
    await self._observe(api_command, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 218, in _observe
    pr_req, pr_rsp = await self._get_response(msg, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 107, in _get_response
    pr_resp = await asyncio.wait_for(pr_req.response, timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 408, in wait_for
    return await fut
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 612, in _run_outer
    await cls._run(app_request, response, weak_observation, protocol, log)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 671, in _run
    blockresponse = await blockrequest.response
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 355, in send
    request_interface.request(pipe)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/tokenmanager.py", line 256, in request
    self.outgoing_requests[key] = request
TypeError: 'NoneType' object does not support item assignment
ggravlingen commented 1 year ago

Looking at the stack trace above, it looks like the library that talks to the gateway is throwing an error. My guess is that the gateway is the root cause, and that there is very little that can be done by anyone developing the Home Assistant system.

I ran the very first version of the gateway (bought it on the day it was released) for years without any issues. The only time I did experience issues what when I flooded the gateway with requests, which caused it to hang.

Mariusthvdb commented 1 year ago

HI thanks for chiming in!

the gateway has only seen updates by Ikea, and besides that HA has had 2 monthly updates,.

I have not added devices, nor am I flooding the gateway with requests. (btw, could the HA frontend be doing that too? Ive always only checked backend, but maybe the dashboard talks to the Gateway also..?)

What I did notice is that the fans are always listed dominantly. Not sure if anything has changed there in core since 2023? If not the integration, maybe the underlying libraries?

btw, an integration reload mostly fixes it, so, currently, we're back to that point in time where the Integration reload is automated based on 'Keep alive failed'.

and, as stated above, the gateway itself does not hang at all, and I can control all devices nicely with the app.

Mariusthvdb commented 1 year ago

Even reloading has its issues:

Logger: homeassistant.config_entries
Source: components/tradfri/__init__.py:149 
First occurred: 19:23:34 (1 occurrences) 
Last logged: 19:23:34

Error unloading entry Ikea Trådfri for tradfri
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 533, in async_unload
    result = await component.async_unload_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/tradfri/__init__.py", line 149, in async_unload_entry
    await factory.shutdown()
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 99, in shutdown
    await self._reset_protocol(exc)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 87, in _reset_protocol
    await protocol.shutdown()
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 332, in shutdown
    await item
  File "/usr/local/lib/python3.10/site-packages/aiocoap/tokenmanager.py", line 65, in shutdown
    await self.token_interface.shutdown()
  File "/usr/local/lib/python3.10/site-packages/aiocoap/messagemanager.py", line 71, in shutdown
    for messageerror_monitor, cancellable in self._active_exchanges.values():
AttributeError: 'NoneType' object has no attribute 'values'
ggravlingen commented 1 year ago

The last track trace you posted indicates there is something going on in aiocoap, which is the library used by the pytradfri integration to talk to the gateway. It was updated to version 0.4.5 in January this year, and the update came into effect in version 2023.2. So to conclude, as Martin said above, nothing significant has been updated as of recently.

Unfortunately, I have no further advice to give other than maybe trying some other equipment like Home Assistant's SkyConnect.

Mariusthvdb commented 1 year ago

thanks for your analysis. it at least points to versions in underlying libraries we can track (not always obvious when only checking the integration). And no, 2023.3 didnt fix it, so something still is off.

Ofc I already took Martins remark for true, no question there.

But, it might well be the cause for the issue. If Tradfri made updates to their Gateway, and HA (or the underlying libraries) didnt followup there, it might result in what I see?

Anyways, I notice the team updating Tradfri libraries actively, maybe it will get sorted in the end.

Strangest thing is I cant imagine being the only Tradfri/HA user suffering this. As it is a truly breaking issue, there should be more people complaining.....

note this just happened on HA restart, which I didnt notice before. an integration reload fixed it, but its really getting serious

Logger: homeassistant.config_entries
Source: components/tradfri/__init__.py:81 
First occurred: 17:31:32 (1 occurrences) 
Last logged: 17:31:32

Error setting up entry Ikea Trådfri for tradfri
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 107, in _get_response
    pr_resp = await asyncio.wait_for(pr_req.response, timeout)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 382, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/tradfri/__init__.py", line 81, in async_setup_entry
    devices: list[Device] = await api(devices_commands, timeout=TIMEOUT_API)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 204, in request
    command_results = await asyncio.gather(*commands)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 167, in _execute
    _, res = await self._get_response(msg, timeout)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 116, in _get_response
    await self._reset_protocol(exc)
  File "/usr/local/lib/python3.10/site-packages/pytradfri/api/aiocoap_api.py", line 87, in _reset_protocol
    await protocol.shutdown()
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 332, in shutdown
    await item
  File "/usr/local/lib/python3.10/site-packages/aiocoap/tokenmanager.py", line 62, in shutdown
    request.add_exception(error.LibraryShutdown())
  File "/usr/local/lib/python3.10/site-packages/aiocoap/pipe.py", line 179, in add_exception
    self._add_event(self.Event(None, exception, True))
  File "/usr/local/lib/python3.10/site-packages/aiocoap/pipe.py", line 164, in _add_event
    keep_calling = cb(event)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 450, in process
    self._runner.send(event)
  File "/usr/local/lib/python3.10/site-packages/aiocoap/protocol.py", line 493, in _run
    self.response.set_exception(first_event.exception)
asyncio.exceptions.InvalidStateError: invalid state
Mariusthvdb commented 1 year ago

just another way of visualizing the impact of the issue:

Mar-03-2023 17-21-34

lenne0815 commented 1 year ago

Nothing to add unfortunately beside having the same issue, reloading tradfri integration solves the problem for a bit until it turns up again.

Mariusthvdb commented 1 year ago

yes, Ive just corrected an reinstated the automation to take care of it, an d trigger on the keep-alive malfunctioning:

  - alias: Reload Tradfri integration
    id: reload_tradfri_integration
    mode: restart
    trigger:
      - platform: event
        event_type: system_log_event
        event_data:
          level: WARNING
        id: observation
      - platform: event
        event_type: system_log_event
        event_data:
          level: ERROR
        id: failed
    condition:
#       or:
#         - >
#           {{trigger.event.data.name == 'tradfri.base_class' and 'Observation failed for'
#             in trigger.event.data.message[0]}}
      - >
        {{trigger.event.data.name == 'homeassistant.components.tradfri' and
          'Keep-alive failed' in trigger.event.data.message[0]}}
#         - >
#           {{trigger.event.data.name == 'coap' and
#               'Error received in UDP connection under DTLS' in trigger.event.data.message[0]}}
    action:
      - service: system_log.write
        data:
          message: >
            Ikea Tradfri '{{trigger.id}}' on {{trigger.event.data.name}} issue logged, reloading integration
          level: warning
          logger: homeassistant.components.tradfri
      - service: script.reload_tradfri_integration
      - service: system_log.write
        data:
          message: >
            Ikea Tradfri integration was reloaded because of {{trigger.id}}
          level: warning
          logger: homeassistant.components.tradfri
      - service: persistent_notification.create
        data:
          title: >
            {{trigger.event.data.level}}: Tradfri reloaded
          message: >
            {{now().timestamp()|timestamp_custom('%X')}}: Ikea Tradfri integration was
              reloaded because of {{trigger.id}}:
              Message: {{trigger.event.data.message[0]}},
              Logger: {{trigger.event.data.name}},
              Source: {{trigger.event.data.source}},
              Level: {{trigger.event.data.level}}

              Full data: {{trigger.event}}

I did comment the other triggers I had before, as they have changed to the ones we have in this issue now.

Keep-alive seems to be the ultimate state into which the system gets after all of the other listed errors, and should be the final moment to have to restart the integration.

this is the result, so you know something happened:

Scherm­afbeelding 2023-03-14 om 07 35 56
Mariusthvdb commented 1 year ago

just a bit safer, to prevent concurrent firing of this automation (I noticed the Keep-alive messages were repeated quickly in the log), I added an extra condition, and changed to mode single:

  - alias: Reload Tradfri integration
    id: reload_tradfri_integration
    mode: single
    trigger:
      - platform: event
        event_type: system_log_event
        event_data:
          level: WARNING
        id: observation
      - platform: event
        event_type: system_log_event
        event_data:
          level: ERROR
        id: failed
    condition:
#prevent frequent firing
      - >
        {{now() - this.attributes.last_triggered > timedelta(minutes=5) if
          this.attributes.last_triggered is not none else true}}
      - >
        {{trigger.event.data.name == 'homeassistant.components.tradfri' and
          'Keep-alive failed' in trigger.event.data.message[0]}}
    action:
      - service: system_log.write
        data:
          message: >
            Ikea Tradfri: '{{trigger.id}}' on {{trigger.event.data.name}} issue logged:
            {{trigger.event.data.message[0]}}.
            Reloading integration
          level: critical
          logger: homeassistant.components.tradfri
      - service: script.reload_tradfri_integration
      - service: system_log.write
        data:
          message: >
            Ikea Tradfri integration was reloaded because of {{trigger.id}}
          level: critical
          logger: homeassistant.components.tradfri
      - service: persistent_notification.create
        data:
          title: >
            {{trigger.event.data.timestamp|timestamp_custom('%X')}}: Tradfri reloaded
          message: >
            {{now().timestamp()|timestamp_custom('%X')}}: Ikea Tradfri integration was
              reloaded because of {{trigger.id}}:
              Message: {{trigger.event.data.message[0]}},
              Logger: {{trigger.event.data.name}},
              Source: {{trigger.event.data.source}},
              Level: {{trigger.event.data.level}}

              Full data:
              {{trigger.event}}

Note I also added the timestamp from the data itself, in the title. It actually proves to be the same as the now() in the message, but this is a nice way to check those timings logged in the system.

Mariusthvdb commented 1 year ago

and logging history on this to see the impact more clearly: triggered by keep-alive failed

Scherm­afbeelding 2023-03-22 om 08 02 00

faintly feared it had to do with some actions I fire manually (scenes, triggering automations touching Tradfri lights) but this clearly proves that is not the case, as it was happening twice this night while firmly asleep....

Mariusthvdb commented 1 year ago

The last track trace you posted indicates there is something going on in aiocoap, which is the library used by the pytradfri integration to talk to the gateway. It was updated to version 0.4.5 in January this year, and the update came into effect in version 2023.2.

Getting back to this, I honestly dont understand why devs say this didnt change anything in HA, as it clearly did..? How come you conclude this aiocoap update to 0.4.5 can not be the reason?

Mariusthvdb commented 1 year ago

given the frequency of the issue, now checking whether this has to do with the transition: used on the Tradfri lights in my scripts/scenes.

which would also relate to other logged and yet unsolved issues in core: https://github.com/home-assistant/core/issues/85535 in Frontend https://github.com/home-assistant/core/issues/80696

so I now commented all transitions on Tradfri lights, and will keep HA on for a day, let's see what gives .....

Mariusthvdb commented 1 year ago

well, that didnt help. Have lived without transitions on Tradfri lights for the week now, but still seeing the regular Tradfri reload being triggered by the Keep-alive failed logging

Scherm­afbeelding 2023-03-30 om 12 43 56

seems to be twice a day, but that is about the only thing to notice.. no connection to other events found yet

Mariusthvdb commented 1 year ago

keeping it alive

Scherm­afbeelding 2023-04-13 om 15 33 09
Mariusthvdb commented 1 year ago

give the fact from 2023.6 we have a different python version, errors have changed a bit too. wondering if it is useful to post those, and see if it holds new info. for startes this seems an important one as it's the 3311 error I started this issue with. Martin please let me know if I should recap in Python 3.11?:

Logger: homeassistant.util.logging
Source: util/logging.py:156 
First occurred: 6 juni 2023 om 23:14:54 (10 occurrences) 
Last logged: 09:35:57

Exception in set_hub_available when dispatching 'tradfri.gw_status': (True,) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/tradfri/coordinator.py", line 47, in set_hub_available await self.async_request_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 236, in async_request_refresh await self._debounced_refresh.async_call() File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 95, in async_call await task File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 262, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 374, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 164, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 70, in _handle_coordinator_update self._refresh() File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 93, in _refresh self._device_data = self.coordinator.data.light_control.lights[0] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/pytradfri/device/__init__.py", line 84, in light_control return LightControl(self) ^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/pytradfri/device/light_control.py", line 40, in __init__ if ATTR_LIGHT_DIMMER in self.raw[0]: ^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/pytradfri/device/light_control.py", line 71, in raw return self._device.raw[ATTR_LIGHT_CONTROL] ~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^ KeyError: '3311'
MartinHjelmare commented 1 year ago

Have you tried going back to core-2022.12.x to see if that is working without issue still?

bramdd commented 11 months ago

Also not adding anything useful, but having the same issue. Worked for more than a year, and now having exactly the same issue as you. Also have a unifi setup. Have set the IP fixed for the hub, see if that helps.

lenne0815 commented 11 months ago

Now this is pretty far-fetched, but can you guys check if you got everything sorted in "Groups" in the Ikea app ?

bramdd commented 11 months ago

Now this is pretty far-fetched, but can you guys check if you got everything sorted in "Groups" in the Ikea app ?

Pretty sure I haven't. However: after posting this, I fixed the IP address of the Ikea Hub, which seems to have solved the issue (for now). I could say this is something obvious, but it hasn't been necessary in the passed year (or so).

Mariusthvdb commented 11 months ago

Having had a fixed IP address since forever I can attest this does not fix anything at all...

The group question: what exactly do you mean by that?

I have no groups enabled in HA for Tradfri

Fwiw auto integration reload logged:

image

lenne0815 commented 11 months ago

Like This: IMG_2051

Mariusthvdb commented 11 months ago

yes, but what exactly are you asking? if we have all devices in a group and no loose devices, or empty groups?

Mariusthvdb commented 11 months ago

Have you tried going back to core-2022.12.x to see if that is working without issue still?

Martin, I am sorry I missed your ask, but no, I have not. My setup changes drastically since that last 8 months and it wont be easy to go back even for a few days, as this is the production system I am running the integration on..

lenne0815 commented 11 months ago

yes, but what exactly are you asking? if we have all devices in a group and no loose devices, or empty groups?

All devices in groups, no “loose” devices. I changed that and it hasn’t crashed since, even though it makes zero sense.

Mariusthvdb commented 11 months ago

ok thanks, I see. well, tbh, I don't have any loose devices, nor did I ever have.

Testing several 'solutions' I did endup with an empty group I can not delete just now.... This is not the cause of the issue however (since that exists for a long time), but it is awkward...

there is really nothing I can link this to. Only scenario I remotely imagined being related is light commands to the Gateway. I did notice some connection loss on switching scenes, and, when not actually dong that myself, some automated commands to the night lights.

However, I did test that extensively, even rewrote all of my logic eg to not use transition times, but it never helped....

I cant believe we are the only few people using the Tradfri integration being plagued by this.

All the rewrites of the library or updated to the Gateway from Tradfri havent changed this issue either. Really wish the HA codeowners could contact Ikea team own this matter, its the most frequent offender in the system.

Only real contribution I could make currently, is repost the set of errors/warnings we get, since they did change in the last half year or so.

lenne0815 commented 11 months ago

I did carefully recheck again today and since I created the groups and put all the devices in, the error is gone. It's just for ~3 Days now, so nothing definitive. Ill report back if the error rears its head again.

lenne0815 commented 10 months ago

So just to update you guys, grouping in the app wasnt the culprit unfortunately, error came back a few days later. Dont fully understand why it did work for a period of time though :/

dehigama commented 10 months ago

Same issue as reported Home Assistant 2023.8.4 Supervisor 2023.08.1 Operating System 10.5 Frontend 20230802.1 - latest

Definitely tradfri gateway related as my tradfri devices (bulbs)on ZHA are running fine

After a HA restart all works fine for several hours before breaking again.

dehigama commented 10 months ago

Not sure if this helps but I rolled back to HA 2023.3 and so far so good Home Assistant 2023.3.3 Supervisor 2023.08.1 Operating System 10.5 Frontend 20230309.0 - latest

Mariusthvdb commented 10 months ago

If you're prepared to do so (I can't because of other functionality) : I think you should be good at least to 2022.12 or maybe even 2023.1.

It was around that threshold when these issues started.

O wait , I didn't read closely enough. 2023.3? No way here, it was breaking constantly already at that time

dehigama commented 10 months ago

Thanks I’ll continue to observe for any issues after the roll back. So far no more errors on the logs for me on HA 2023.03.

aetha commented 8 months ago

FWIW I was getting this problem on 2022.08 too. I stopped updating and was using that version for over a year, until recently. I assumed it was caused by high system load (due to SD iowait on my RPi 3), but I've moved over to a HA Green on 2023.11 and Tradfri is still having the same problem.

Mariusthvdb commented 8 months ago

yep, still going strong here too.... ive cleaned up the gateway so it has less devices, but the reloads still are required to have the integration function properly after connection loss. to give you an idea of the number and frequency :

Scherm­afbeelding 2023-11-09 om 07 41 48

and compare with august: https://github.com/home-assistant/core/issues/85254#issuecomment-1669839170

no improvement at all. And yet, the standalone app is solid as ever, so must be the interface to HA itself

Mariusthvdb commented 7 months ago

new development:

since beta 2023.12.0b the issue seems to have worsened.

The auomatic reload of the integration does seem to work initially and entities are shown as if they are available. However, controlling them is impossible and errors out with

Logger: root
Source: /usr/src/homeassistant/homeassistant/bootstrap.py:402
First occurred: 10:21:50 (76 occurrences)
Last logged: 11:30:16

Uncaught exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiocoap/transports/tinydtls.py", line 170, in wrapper
    return getattr(self, __method)(*args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiocoap/transports/tinydtls.py", line 280, in _read
    self.coaptransport.ctx.dispatch_message(message)
  File "/usr/local/lib/python3.11/site-packages/aiocoap/messagemanager.py", line 109, in dispatch_message
    success = self._process_response(message)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiocoap/messagemanager.py", line 335, in _process_response
    return self.token_manager.process_response(response)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiocoap/tokenmanager.py", line 167, in process_response
    if key not in self.outgoing_requests:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: argument of type 'NoneType' is not iterable

a subsequent manual reload of the integration now also errors with:

Logger: homeassistant.config_entries
Source: config_entries.py:557
First occurred: 11:30:46 (1 occurrences)
Last logged: 11:30:46

Error unloading entry Ikea Trådfri for tradfri
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 557, in async_unload
    result = await component.async_unload_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/tradfri/__init__.py", line 149, in async_unload_entry
    await factory.shutdown()
  File "/usr/local/lib/python3.11/site-packages/pytradfri/api/aiocoap_api.py", line 99, in shutdown
    await self._reset_protocol(exc)
  File "/usr/local/lib/python3.11/site-packages/pytradfri/api/aiocoap_api.py", line 87, in _reset_protocol
    await protocol.shutdown()
  File "/usr/local/lib/python3.11/site-packages/aiocoap/protocol.py", line 326, in shutdown
    await item
  File "/usr/local/lib/python3.11/site-packages/aiocoap/tokenmanager.py", line 61, in shutdown
    await self.token_interface.shutdown()
  File "/usr/local/lib/python3.11/site-packages/aiocoap/messagemanager.py", line 65, in shutdown
    for messageerror_monitor, cancellable in self._active_exchanges.values():
                                             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'values'

followed up with:

2023-12-04 20:38:13.545 WARNING (MainThread) [py.warnings] /usr/local/lib/python3.11/site-packages/aiocoap/transports/tinydtls.py:166: UserWarning: DTLS module did not shut down the DTLSSocket perfectly; it still tried to call _write in vain
  warnings.warn("DTLS module did not shut down the DTLSSocket "

and:

Scherm­afbeelding 2023-12-04 om 11 34 50

so the only thing we can do is restart HA....

meanwhile the gateway and dedicated app works as before: just fine

NOTE this is from before the dec 4th Ikea firmware update ruling that out as a new source of trouble.