search

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
70.11k stars 29.16k forks source link

The Tradfri integration stops working every few days. #42563

Closed rubenbe closed 2 years ago

rubenbe commented 3 years ago

The problem

The Tradfri integration stops working every few days. A restart of the integration (or hass entirely) is required to revive it. No need to restart the ikea tradfri hub.

Environment

Problem-relevant configuration.yaml

Configured via flow

Traceback/Error logs

2020-10-28 17:05:08 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall light.turn_on (c:081e8aff193811ebac0de104ad2b18e1): entity_id=['light.tradfri_bulb_e27_ws_opal_980lm'], params=brightness=175, color_temp=370>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1351, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1370, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 470, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 655, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 507, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 249, in async_handle_light_on_service
    await light.async_turn_on(**params)
  File "/usr/src/homeassistant/homeassistant/components/tradfri/light.py", line 262, in async_turn_on
    await self._api(command)
  File "/usr/src/homeassistant/homeassistant/components/tradfri/base_class.py", line 22, in wrapper
    await func(command)
  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 164, in request
    result = await self._execute(api_commands)
  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 148, in _execute
    _, res = await self._get_response(msg)
  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 96, in _get_response
    r = await pr.response
  File "/usr/local/lib/python3.8/site-packages/aiocoap/protocol.py", line 731, in _run_outer
    await cls._run(app_request, response, weak_observation, protocol, log)
  File "/usr/local/lib/python3.8/site-packages/aiocoap/protocol.py", line 783, in _run
    blockresponse = await blockrequest.response
  File "/usr/local/lib/python3.8/site-packages/aiocoap/protocol.py", line 313, in send
    request_interface.request(plumbing_request)
  File "/usr/local/lib/python3.8/site-packages/aiocoap/tokenmanager.py", line 243, in request
    self.outgoing_requests[key] = request
TypeError: 'NoneType' object does not support item assignment
2020-10-28 17:05:08 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'3311': [{'5711': 370}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65544'))
2020-10-28 17:05:08 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'3311': [{'5851': 175}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65544'))
2020-10-28 17:05:08 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65538]: {'3311': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65538'))
2020-10-28 17:13:12 ERROR (MainThread) [coap] Connection loss was not expected.

Additional information

Originally discussed here: https://community.home-assistant.io/t/tradfri-integration-stops-working-approx-once-twice-a-week/238429/4 I'll see if the issue keeps appearing on the 0.117.x

JayOne73 commented 3 years ago

I can confirm this behaviour, after reloading the integration everything works for some time. I noticed this also for the 0.115 release.

Running: Home Assistant on RPI 3

probot-home-assistant[bot] commented 3 years ago

Hey there @ggravlingen, mind taking a look at this issue as its been labeled with an integration (tradfri) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

ggravlingen commented 3 years ago

Have a look in the new version of HA if it works better, a fix was recently added to the code base.

rubenbe commented 3 years ago

The problem persists on 117 too unfortunately. With a different error this time though

2020-10-30 06:25:52 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.3 <Command get ['15011', '15012']>  (Repeated 245 times)
2020-10-30 06:25:52 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.3 <Command put ['15001', 65538]: {'3311': [{'5850': 1}]}>
2020-10-30 06:25:52 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.3 <Command get ['15011', '15012']>  (Repeated 49 times)
2020-10-30 06:25:52 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'3311': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65544'))
2020-10-30 06:25:52 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65538]: {'3311': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65538'))
2020-10-30 06:25:52 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'3311': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65544'))
/usr/local/lib/python3.8/site-packages/afsapi/__init__.py:71: RuntimeWarning: coroutine 'noop2' was never awaited
  self.__session._connector.close()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
doubleopinter commented 3 years ago

Hey hey, I have the exact same issue, every few days have the reload the integration. Is there a way to auto reload that I could use for now?

thecobra666 commented 3 years ago

Also broken here, 0.166.4. Worked perfectly on 0.155.x. What changed? I see 0 respons from the developer, hope they pick this up fast.

rubenbe commented 3 years ago

@thecobra666 I suspect an update of the underlying "pytradfri" caused some regressions: https://github.com/home-assistant/core/commits/dev/homeassistant/components/tradfri/manifest.json If you see the issue, it can be very useful to check the logging. They might contain extra info for the developers.

ggravlingen commented 3 years ago

In what environment are you guys running this? Raspberry Pi with hassos? Also, are you sending many commands to the gateway due to some plug-in in HA?

rubenbe commented 3 years ago

I'm running the official docker on a amd64 server, without any plugins. Currently I only have 4 automated triggers, so the connection/setup is idle most of the time. The connection to the tradfri gateway is wired ethernet (2 hops away)

ggravlingen commented 3 years ago

Can you please try this? https://github.com/home-assistant/core/issues/40612#issuecomment-703581004

ggravlingen commented 3 years ago

@frenck: this is a duplicate of #40612.

rubenbe commented 3 years ago

I've installed the trigger mention in the comment. Let's wait and see if it fixes the issue.

doubleopinter commented 3 years ago

I’m running this in a VM on a QNAP NAS

ggravlingen commented 3 years ago

Yeah, a lot of people have reported issues running in a VM. It’s unrelated to the integration with the gateway and related to your local environment I’m afraid.

rubenbe commented 3 years ago

@ggravlingen Unfortunately the issue appeared again, even with the workaround in place. When reloading, I get the credentials error again

2020-11-02 06:44:30 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.3 <Command get ['15011', '15012']>
2020-11-02 06:44:30 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65538]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.3:5684/15001/65538'))
doubleopinter commented 3 years ago

Yeah, a lot of people have reported issues running in a VM. It’s unrelated to the integration with the gateway and related to your local environment I’m afraid.

Should I switch over to an rpi or something? I wonder what it could be with the vm.

doubleopinter commented 3 years ago

I'm not entirely sure but it seems like HA might be crashing the gateway. I updated to the latest version of HA and the gateway keeps hanging now, this is completely new. I used to have to reload the integration and things would work, now I have to restart the whole gateway. I just powered off HA to see if the gateway stays up.

doubleopinter commented 3 years ago

OK HA is not the cause. I'm gonna get a zigbee dongle and control all my lights that way instead of this gateway.

rubenbe commented 3 years ago

I had some major instabilities today too. Even had to reset the gateway. @doubleopinter what version of the gateway SW are you running? (mine is 1.11.51) @ggravlingen can I gather/add extra logging to provide more info on this issue (worst case by adding prints in the python sources)?

ggravlingen commented 3 years ago

Sorry, not much I can do here. Please try running HA without a VM and see if that helps.

doubleopinter commented 3 years ago

My ikea hub has taken a dump and is locking up constantly now so I’m just going to move away from it. Sorry I can’t help any more

rubenbe commented 3 years ago

@ggravlingen My setup does not involve a VM (that was @doubleopinter). it's running the official docker container without modifications / plugins. And the networking is set to "host networking", so there is no extra networking magic happening. The setup was running (largely) rock-solid for multiple years. And now it isn't anymore, so I suspect that somewhere there is a nasty regression. I'll try to remove the extra switch to verify if that could be a cause (trying to eliminate all external factors).

im85288 commented 3 years ago

I am also experiencing this consistently, reloading the integration resolves it until the next time I interact with it. Has there been any progress on this!

rubenbe commented 3 years ago

I've started digging further into this extremely annoying issue (what's home automation worth if stops working randomly?) Moving the tradfri gateway closer on the network to my hass machine did not solve the issue.

So I added two simple prints before the CredentialsMissingError exception is thrown on https://github.com/chrysn/aiocoap/blob/master/aiocoap/credentials.py#L291

                print(uri)
                print(self.items())
                raise CredentialsMissingError("No suitable credentials for %s" % uri)

Their output seems to indicate that the aiocoap library forgets its credentials for some (currently unknown) reason.

dict_items([])
coaps://192.168.1.3:5684/15001/65538

The hunt for the root cause of this problem can now start.

im85288 commented 3 years ago

Great stuff, let's hope this leads to a solution. I reload the integration after it's done any activity (in my case opening/closing the blinds). Be nice not to have to remember to do that each time.

kim1138 commented 3 years ago

Get this every Friday around noon! Reload of integration makes everything work OK again. Lucky one works from home these days so all things automated can get a extra hand when not working as automed things should :D

2020-11-20 10:31:54 INFO (MainThread) [coap] Exchange timed out 2020-11-20 10:31:57 INFO (MainThread) [coap] Retransmission, Message ID: 56312.

rubenbe commented 3 years ago

@kim1138 The problem is that at this moment, I don't have the issue. What you could do is enable logging for the tradfri component: https://www.home-assistant.io/integrations/logger/

    homeassistant.components.tradfri: debug

I suspect that it's some race condition, so maybe you might no longer see the problem even with the debug output enabled. It would be very interesting to see next friday what the output is (or if the issue has disappeared)

im85288 commented 3 years ago

@rubenbe I have this occurring daily, hopefully the below is useful:

020-11-20 15:50:20 WARNING (zeroconf-Engine-282) [zeroconf] Choked at offset 294 while unpacking b'\x00\x00\x84\x00\x00\x00\x00\x05\x00\x00\x00\x00\x0fTRADFRI gateway\x04_hap\x04_tcp\x05local\x00\x00!\x80\x01\x00\x00\x00x\x00\x08\x00\x00\x00\x00\x00P\x00\x00\x00\x00\x00\x01\x80\x01\x00\x00\x00x\x00\x04\xc0\xa8\x01\x86\x00\x00\x00\x1c\x80\x01\x00\x00\x00\x00\x00\x10\x00\xf0>\xb0z\x80\x12\xeaz\x80\x12\xeaz\x80\x12\xea\x04_hap\x04_tcp\x05local\x00\x00\x0c\x00\x01\x00\x00\x11\x94\x00!\x0fTRADFRI gateway\x04_hap\x04_tcp\x05local\x00\x0fTRADFRI gateway\x04_hap\x04_tcp\x05local\x00\x00\x10\x80\x01\x00\x00\x11\x94\x00T\x04c#=1\x04ff=1\x14id=F8:FF:92:CD:B2:D3\x12md=TRADFRI gateway\x06pv=1.1\x04s#=1\x04sf=1\x04ci=2\x0bsh=1OInkg==' Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 741, in __init__ self.read_others() File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 812, in read_others domain = self.read_name() File "/usr/local/lib/python3.8/site-packages/zeroconf/__init__.py", line 873, in read_name length = self.data[off] IndexError: index out of range

`2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65555]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65547]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65553]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65542]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65554]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65539]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:55:59 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65550]: {'15015': [{'5536': 100}]}>: {"r":"02"} 2020-11-20 15:56:00 ERROR (Recorder) [homeassistant.components.recorder] Error executing query: (sqlite3.DatabaseError) database disk image is malformed [SQL: INSERT INTO events (event_type, event_data, origin, time_fired, created, context_id, context_user_id, context_parent_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?)] [parameters: ('homekit_state_change', '{"entity_id": "cover.tradfri_blind_8", "display_name": "TRADFRI blind 8", "service": "set_cover_position", "value": 0}', 'LOCAL', '2020-11-20 15:55:59.621486', '2020-11-20 15:55:59.621486', '6f06dc1e63cb95ce176b039fe576a9db', None, None)] (Background on this error at: http://sqlalche.me/e/13/4xp6) 2020-11-20 15:56:00 ERROR (Recorder) [homeassistant.components.recorder] Error saving events: (sqlite3.DatabaseError) database disk image is malformed [SQL: INSERT INTO events (event_type, event_data, origin, time_fired, created, context_id, context_user_id, context_parent_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?)] [parameters: ('homekit_state_change', '{"entity_id": "cover.tradfri_blind_8", "display_name": "TRADFRI blind 8", "service": "set_cover_position", "value": 0}', 'LOCAL', '2020-11-20 15:55:59.621486', '2020-11-20 15:55:59.621486', '6f06dc1e63cb95ce176b039fe576a9db', None, None)] (Background on this error at: http://sqlalche.me/e/13/4xp6) Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context self.dialect.do_execute( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute cursor.execute(statement, parameters) sqlite3.DatabaseError: database disk image is malformed

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

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/recorder/init.py", line 454, in _commit_event_session_or_retry self._commit_event_session() File "/usr/src/homeassistant/homeassistant/components/recorder/init.py", line 516, in _commit_event_session self.event_session.commit() File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 1042, in commit self.transaction.commit() File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 504, in commit self._prepare_impl() File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 483, in _prepare_impl self.session.flush() File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2536, in flush self._flush(objects) File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2678, in _flush transaction.rollback(_captureexception=True) File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 68, in exit compat.raise( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 2638, in _flush flush_context.execute() File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute rec.execute(self) File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/unitofwork.py", line 586, in execute persistence.save_obj( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 239, in save_obj _emit_insert_statements( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1135, in _emit_insert_statements result = cached_connections[connection].execute( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1011, in execute return meth(self, multiparams, params) File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection return connection._execute_clauseelement(self, multiparams, params) File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement ret = self._execute_context( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context self._handle_dbapi_exception( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1510, in _handle_dbapiexception util.raise( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context self.dialect.do_execute( File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute cursor.execute(statement, parameters) sqlalchemy.exc.DatabaseError: (sqlite3.DatabaseError) database disk image is malformed [SQL: INSERT INTO events (event_type, event_data, origin, time_fired, created, context_id, context_user_id, context_parent_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?)] [parameters: ('homekit_state_change', '{"entity_id": "cover.tradfri_blind_8", "display_name": "TRADFRI blind 8", "service": "set_cover_position", "value": 0}', 'LOCAL', '2020-11-20 15:55:59.621486', '2020-11-20 15:55:59.621486', '6f06dc1e63cb95ce176b039fe576a9db', None, None)] (Background on this error at: http://sqlalche.me/e/13/4xp6)`

rubenbe commented 3 years ago

@im85288 Could you also enable the debug logging? It seems that you have another (unrelated) problem with your setup: your database is corrupted https://www.home-assistant.io/integrations/recorder/ Removing the home-assistant_v2.db file should be sufficient. If you would need more help, please ask on the forum. As such we can keep this discussion related to the tradri issue.

im85288 commented 3 years ago

@rubenbe thanks I thought I had enabled debug but it must have not been picked up correctly. I will give it another try and report back.

kim1138 commented 3 years ago

My logger now looks like below, not getting anything from homeassistant.components.tradfri only pytradfri.api.aiocoap_api. Maybe homeassistant.components.tradfri doesn't log that much?!

logger: default: info logs: homeassistant.components.tradfri: debug pytradfri.api.aiocoap_api: debug

rubenbe commented 3 years ago

@kim1138 indeed, you're right, that's the config we need (I assume you have the correct indentation) I double checked in the code and the pytradfri.api.aiocoap_api show the details that might be interesting.

kim1138 commented 3 years ago

Indentation is correct, copy/paste issues! :D

manuelbernhardt commented 3 years ago

I have the same issue (I think) but it happens much more frequently - every 6 hours or so. My setup is a Raspberry PI 3B+. I also have a python script that runs every 5 minutes and "pings" the lights (i.e. tries to set their brightness to their current brightness) to forcefully detect when a light has been turned completely off (i.e. via the light switch, no more power).

I've now setup debug logging and will report if that reveals anything.

im85288 commented 3 years ago

@rubenbe This is a link to my log from this morning. It starts off with me reloading the ikea integration as it had got out of sync and by the end it is again out of sync (as I had closed three of the blinds using Alexa). I cannot really see many errors rather it seems to be not receiving any content on the get request. Log

manuelbernhardt commented 3 years ago

@rubenbe I have some logs as well. Today I restarted HA at about 7AM and things worked until about 12:45. Here's the output of one of the "synchronize tradfri light state" script execution results (that pings all the lights) when things work:

2020-11-22 12:45:00 INFO (SyncWorker_3) [homeassistant.components.python_script] Executing update_tradfri.py: {}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65572]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65565]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 2","9003":65572,"9002":1602693726,"9020":1606043131,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65567]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 2","9003":65565,"9002":1601281393,"9020":1606043571,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65564]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65568]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 4","9003":65567,"9002":1601281482,"9020":1606043557,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65566]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65576]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65571]: {'3311': [{'5851': 204}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 1","9003":65564,"9002":1601281358,"9020":1606043542,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65573]: {'3311': [{'5851': 13}]}>
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 5","9003":65568,"9002":1601281536,"9020":1606043578,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 3","9003":65566,"9002":1601281438,"9020":1606043553,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Toilet Spot","9003":65576,"9002":1605717190,"9020":1606042913,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 1","9003":65571,"9002":1602693681,"9020":1606043239,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:45:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 3","9003":65573,"9002":1602693772,"9020":1606043121,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":13,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:45:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:45:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9023":"0.tradfri.pool.ntp.org","9106":0,"9118":0,"9072":3,"9059":1606049150,"9060":"2020-11-22T12:45:50.008392Z","9054":0,"9073":28,"9082":false,"9075":0,"9062":0,"9061":0,"9029":"1.11.51","9202":1585406627,"9081":"7e39155204400098","9083":"N/A","9200":"737ddfd7-2590-43fd-be50-9ac7d55b15a3","9093":0,"9055":0,"9066":5,"9069":1603215347,"9074":1,"9071":1,"9076":10,"9077":31,"9078":1,"9079":0,"9080":60,"9092":1,"9103":"a1nvlh0fc0asuq.iot.eu-central-1.amazonaws.com","9105":0,"9107":1,"9201":1}
2020-11-22 12:46:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:46:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9023":"0.tradfri.pool.ntp.org","9106":0,"9118":0,"9072":3,"9059":1606049210,"9060":"2020-11-22T12:46:50.004392Z","9054":0,"9073":28,"9082":false,"9075":0,"9062":0,"9061":0,"9029":"1.11.51","9202":1585406627,"9081":"7e39155204400098","9083":"N/A","9200":"737ddfd7-2590-43fd-be50-9ac7d55b15a3","9093":0,"9055":0,"9066":5,"9069":1603215347,"9074":1,"9071":1,"9076":10,"9077":31,"9078":1,"9079":0,"9080":60,"9092":1,"9103":"a1nvlh0fc0asuq.iot.eu-central-1.amazonaws.com","9105":0,"9107":1,"9201":1}
2020-11-22 12:47:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:47:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9023":"0.tradfri.pool.ntp.org","9106":0,"9118":0,"9072":3,"9059":1606049270,"9060":"2020-11-22T12:47:50.005392Z","9054":0,"9073":28,"9082":false,"9075":0,"9062":0,"9061":0,"9029":"1.11.51","9202":1585406627,"9081":"7e39155204400098","9083":"N/A","9200":"737ddfd7-2590-43fd-be50-9ac7d55b15a3","9093":0,"9055":0,"9066":5,"9069":1603215347,"9074":1,"9071":1,"9076":10,"9077":31,"9078":1,"9079":0,"9080":60,"9092":1,"9103":"a1nvlh0fc0asuq.iot.eu-central-1.amazonaws.com","9105":0,"9107":1,"9201":1}
2020-11-22 12:48:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:48:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9023":"0.tradfri.pool.ntp.org","9106":0,"9118":0,"9072":3,"9059":1606049330,"9060":"2020-11-22T12:48:50.011392Z","9054":0,"9073":28,"9082":false,"9075":0,"9062":0,"9061":0,"9029":"1.11.51","9202":1585406627,"9081":"7e39155204400098","9083":"N/A","9200":"737ddfd7-2590-43fd-be50-9ac7d55b15a3","9093":0,"9055":0,"9066":5,"9069":1603215347,"9074":1,"9071":1,"9076":10,"9077":31,"9078":1,"9079":0,"9080":60,"9092":1,"9103":"a1nvlh0fc0asuq.iot.eu-central-1.amazonaws.com","9105":0,"9107":1,"9201":1}
2020-11-22 12:49:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:49:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9023":"0.tradfri.pool.ntp.org","9106":0,"9118":0,"9072":3,"9059":1606049390,"9060":"2020-11-22T12:49:50.004392Z","9054":0,"9073":28,"9082":false,"9075":0,"9062":0,"9061":0,"9029":"1.11.51","9202":1585406627,"9081":"7e39155204400098","9083":"N/A","9200":"737ddfd7-2590-43fd-be50-9ac7d55b15a3","9093":0,"9055":0,"9066":5,"9069":1603215347,"9074":1,"9071":1,"9076":10,"9077":31,"9078":1,"9079":0,"9080":60,"9092":1,"9103":"a1nvlh0fc0asuq.iot.eu-central-1.amazonaws.com","9105":0,"9107":1,"9201":1}

Here's the same 10 minutes later at which point things start not to look too good. I haven't checked in between but right now the integration is no longer responsive (reloading would fix it):

2020-11-22 12:55:00 INFO (MainThread) [homeassistant.components.automation.sync_tradfri_state] Sync tradfri state: Running automation actions
2020-11-22 12:55:00 INFO (MainThread) [homeassistant.components.automation.sync_tradfri_state] Sync tradfri state: Executing step call service
2020-11-22 12:55:00 INFO (SyncWorker_1) [homeassistant.components.python_script] Executing update_tradfri.py: {}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65572]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65565]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 2","9003":65572,"9002":1602693726,"9020":1606043131,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65567]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 2","9003":65565,"9002":1601281393,"9020":1606043571,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65564]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 4","9003":65567,"9002":1601281482,"9020":1606043557,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65568]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 1","9003":65564,"9002":1601281358,"9020":1606043542,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65566]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 5","9003":65568,"9002":1601281536,"9020":1606043578,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65576]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65571]: {'3311': [{'5851': 204}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Bathroom Spot 3","9003":65566,"9002":1601281438,"9020":1606043553,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":32886,"5710":27217,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65573]: {'3311': [{'5851': 13}]}>
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Toilet Spot","9003":65576,"9002":1605717190,"9020":1606042913,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 1","9003":65571,"9002":1602693681,"9020":1606043239,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":204,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:55:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Kitchen Spot 3","9003":65573,"9002":1602693772,"9020":1606043121,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 WS 400lm","6":1,"2":"","3":"2.0.029"},"5750":2,"3311":[{"5850":1,"5851":13,"5717":0,"5711":350,"5709":30015,"5710":26870,"5706":"0","9003":0}]}
2020-11-22 12:55:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:55:55 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:55:59 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:08 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:27 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:57:03 INFO (MainThread) [coap] Exchange timed out
2020-11-22 12:57:06 INFO (MainThread) [coap] Retransmission, Message ID: 36410.
2020-11-22 12:57:11 INFO (MainThread) [coap] Retransmission, Message ID: 36410.
2020-11-22 12:57:21 INFO (MainThread) [coap] Retransmission, Message ID: 36410.
2020-11-22 12:57:41 INFO (MainThread) [coap] Retransmission, Message ID: 36410.
2020-11-22 12:57:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:58:22 INFO (MainThread) [coap] Exchange timed out
2020-11-22 12:58:25 INFO (MainThread) [coap] Retransmission, Message ID: 36411.
2020-11-22 12:58:30 INFO (MainThread) [coap] Retransmission, Message ID: 36411.
2020-11-22 12:58:42 INFO (MainThread) [coap] Retransmission, Message ID: 36411.
2020-11-22 12:58:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:59:04 INFO (MainThread) [coap] Retransmission, Message ID: 36411.
2020-11-22 12:59:50 INFO (MainThread) [coap] Exchange timed out
2020-11-22 12:59:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:59:53 INFO (MainThread) [coap] Retransmission, Message ID: 36412.
2020-11-22 12:59:59 INFO (MainThread) [coap] Retransmission, Message ID: 36412.
2020-11-22 13:00:00 INFO (MainThread) [homeassistant.components.automation.sync_tradfri_state] Sync tradfri state: Running automation actions
2020-11-22 13:00:00 INFO (MainThread) [homeassistant.components.automation.sync_tradfri_state] Sync tradfri state: Executing step call service
2020-11-22 13:00:00 INFO (SyncWorker_4) [homeassistant.components.python_script] Executing update_tradfri.py: {}
2020-11-22 13:00:00 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command put ['15001', 65572]: {'3311': [{'5851': 204}]}>
2020-11-22 13:00:10 INFO (MainThread) [coap] Retransmission, Message ID: 36412.
2020-11-22 13:00:33 INFO (MainThread) [coap] Retransmission, Message ID: 36412.
2020-11-22 13:00:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 13:01:18 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ceiling Kids Playroom","9003":65575,"9002":1604043583,"9020":1606042627,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 WW 806lm","6":1,"2":"","3":"2.3.050"},"5750":2,"3311":[{"5850":1,"5851":204,"9003":0}]}
2020-11-22 13:01:18 INFO (MainThread) [homeassistant.components.automation.kid_playroom_morning] Kid Playroom Morning: Running automation actions
2020-11-22 13:01:18 INFO (MainThread) [homeassistant.components.automation.kid_playroom_morning] Kid Playroom Morning: Executing step call service
2020-11-22 13:01:19 INFO (MainThread) [coap] Exchange timed out
2020-11-22 13:01:20 INFO (MainThread) [coap] Duplicate CON received, sending old response again
2020-11-22 13:01:20 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ceiling Kids Playroom","9003":65575,"9002":1604043583,"9020":1606042627,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 WW 806lm","6":1,"2":"","3":"2.3.050"},"5750":2,"3311":[{"5850":1,"5851":13,"9003":0}]}
2020-11-22 13:01:22 INFO (MainThread) [coap] Retransmission, Message ID: 36413.
2020-11-22 13:01:23 INFO (MainThread) [coap] Duplicate CON received, sending old response again
2020-11-22 13:01:24 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ceiling Kids Playroom","9003":65575,"9002":1604043583,"9020":1606050081,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 WW 806lm","6":1,"2":"","3":"2.3.050"},"5750":2,"3311":[{"5850":1,"5851":13,"9003":0}]}
2020-11-22 13:01:26 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ceiling Kids Playroom","9003":65575,"9002":1604043583,"9020":1606050081,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 WW 806lm","6":1,"2":"","3":"2.3.050"},"5750":2,"3311":[{"5850":1,"5851":13,"9003":0}]}
2020-11-22 13:01:26 INFO (MainThread) [coap] Retransmission, Message ID: 36413.
2020-11-22 13:01:27 INFO (MainThread) [coap] Duplicate CON received, sending old response again
2020-11-22 13:01:27 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ceiling Kids Playroom","9003":65575,"9002":1604043583,"9020":1606050085,"9054":0,"9019":1,"3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 WW 806lm","6":1,"2":"","3":"2.3.050"},"5750":2,"3311":[{"5850":1,"5851":13,"9003":0}]}
2020-11-22 13:01:28 INFO (MainThread) [homeassistant.components.automation.kid_playroom_morning] Kid Playroom Morning: Executing step delay 0:00:02
2020-11-22 13:01:28 INFO (MainThread) [coap] Duplicate CON received, sending old response again
2020-11-22 13:01:30 INFO (MainThread) [homeassistant.components.automation.kid_playroom_morning] Kid Playroom Morning: Executing step call service
2020-11-22 13:01:34 INFO (MainThread) [coap] Retransmission, Message ID: 36413.
2020-11-22 13:01:51 INFO (MainThread) [coap] Retransmission, Message ID: 36413.
2020-11-22 13:01:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 13:02:24 INFO (MainThread) [coap] Exchange timed out
2020-11-22 13:02:27 INFO (MainThread) [coap] Retransmission, Message ID: 36414.
2020-11-22 13:02:31 INFO (MainThread) [coap] Retransmission, Message ID: 36414.
2020-11-22 13:02:41 INFO (MainThread) [coap] Retransmission, Message ID: 36414.

As far as I can tell, there's a retry mechanism in place that fails, eventually leading to timeouts:

2020-11-22 12:55:55 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:55:59 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:08 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:27 INFO (MainThread) [coap] Retransmission, Message ID: 36409.
2020-11-22 12:56:53 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.124 <Command get ['15011', '15012']>
2020-11-22 12:57:03 INFO (MainThread) [coap] Exchange timed out

Another message which I think is symptomatic of this is

2020-11-22 13:01:28 INFO (MainThread) [coap] Duplicate CON received, sending old response again

I'm not entirely sure what coap is.

The full log is here: https://gist.github.com/manuelbernhardt/32221c58817de559db84a9d35a94412c

rubenbe commented 3 years ago

@manuelbernhardt coap is the protocol that's used to communicate with the tradfri hub (Constrained Application Protocol) From your log (and @im85288) it seems that the gateway indeed starts refusing to answer (retransmissions + timeout). Another possibility is a flaky (wireless?) network connection which causes the packets to get lost and the retransmissions to appear.

doubleopinter commented 3 years ago

My hub completely started freezing. In all honesty I don't trust the hub at all anymore, even if some issues with the integration are resolved you may find the hub stop working. I bought a conbee II and have imported my ikea bulbs that way. Another option is to get a Hue hub. The conbee thing hasn't been smooth at first but it seems stable now so I need to give it time but I will not use the Ikea hub ever again. In fact any new bulbs I buy will be something else as well. I've lost all trust in Ikea firmware. Consider doing the same.

onkelbeh commented 3 years ago

Same here, already filed an issue at https://github.com/home-assistant-libs/pytradfri/issues/297 some days ago, but closed it, because after re-adding the component in HA 0.118.2 it gain seemed OK to me. Somehow the gateway behaves strange after a couple of hours working. It still responds to ICMP, but it reacts to commands very slowly, if you turn on a bulb, after a minute or so, it turns it on. The shutters also work, but with a delay of some minutes. Cannot tell if the gateway updated, there is no log. It's on 1.9.27 now. Logs look like https://github.com/home-assistant/core/issues/42563#issuecomment-731772772, lots of 

INFO (MainThread) [coap] Retransmission, Message ID: 7030.

I have aiocoap-0.4b3 installed.

maweki commented 3 years ago

I believe I have the same issue. It randomly stops so that I can't control a light. I believe it still works using the tradfri app. Restarting HA solves the issue. Custom installation (pip in venv) on a RPi3, completely wired. No wi-fi involved in any related part. The issue crops up about weekly, but I regularly restart Home Assistant, so it might be after a few days.

Sadly, I restarted before I could capture logs. Will do so now.

litinoveweedle commented 3 years ago

I can confirm similar observations - after max few days Tradfri stops to work. In my case it seems as well that COAP forgot credentials - as described earlier.

2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.3.55 <Command get ['15011', '15012']>
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65564]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65564'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65565]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65565'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65559]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65559'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65574]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65574'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65575]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65575'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65563]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65563'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65564]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65564'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65565]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65565'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65574]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65574'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65575]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65575'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65559]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65559'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65574]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65574'))
2020-11-24 22:16:12 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65559]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.3.55:5684/15001/65559'))
kim1138 commented 3 years ago

Hi!

Got the issue today again, below are parts of log.

I dont know how to format it as nice as in the post above :(

2020-11-25 20:27:29 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [140676245139264] Connection closed by client 2020-11-25 20:27:35 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:27:35 INFO (MainThread) [coap] Exchange timed out 2020-11-25 20:27:38 INFO (MainThread) [coap] Retransmission, Message ID: 26843. 2020-11-25 20:27:44 INFO (MainThread) [coap] Retransmission, Message ID: 26843. 2020-11-25 20:27:55 INFO (MainThread) [coap] Retransmission, Message ID: 26843. 2020-11-25 20:28:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Running automation actions 2020-11-25 20:28:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Executing step call service 2020-11-25 20:28:17 INFO (MainThread) [volvooncall.volvooncall] Updating 2020-11-25 20:28:18 INFO (MainThread) [coap] Retransmission, Message ID: 26843. 2020-11-25 20:28:35 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:29:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Running automation actions 2020-11-25 20:29:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Executing step call service 2020-11-25 20:29:04 INFO (MainThread) [coap] Exchange timed out 2020-11-25 20:29:07 INFO (MainThread) [coap] Retransmission, Message ID: 26844. 2020-11-25 20:29:13 INFO (MainThread) [coap] Retransmission, Message ID: 26844. 2020-11-25 20:29:18 INFO (MainThread) [volvooncall.volvooncall] Updating 2020-11-25 20:29:24 INFO (MainThread) [coap] Retransmission, Message ID: 26844. 2020-11-25 20:29:35 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:29:48 INFO (MainThread) [coap] Retransmission, Message ID: 26844. 2020-11-25 20:30:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Running automation actions 2020-11-25 20:30:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Executing step call service 2020-11-25 20:30:18 INFO (MainThread) [volvooncall.volvooncall] Updating 2020-11-25 20:30:33 INFO (MainThread) [homeassistant.components.discovery] Ignoring service: samsung_printer {'host': '192.168.1.76', 'port': 5200, 'ssdp_description': 'http://192.168.1.76:5200/Printer.xml', 'name': 'Samsung C410 Series (192.168.1.76)', 'model_name': 'Samsung C410', 'model_number': '1.0', 'serial': 'ZET5B8GF9E00LGH', 'manufacturer': 'Samsung Electronics', 'udn': 'uuid:16a65700-007c-1000-bb49-30cda739d64e', 'upnp_device_type': 'urn:schemas-upnp-org:device:Printer:1'} 2020-11-25 20:30:35 INFO (MainThread) [coap] Exchange timed out 2020-11-25 20:30:35 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:30:37 INFO (MainThread) [coap] Retransmission, Message ID: 26845. 2020-11-25 20:30:42 INFO (MainThread) [coap] Retransmission, Message ID: 26845. 2020-11-25 20:30:51 INFO (MainThread) [coap] Retransmission, Message ID: 26845. 2020-11-25 20:31:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Running automation actions 2020-11-25 20:31:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Executing step call service 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Resetting protocol 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, stopping observation 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> . . . . 2020-11-25 20:31:09 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65562]: {'3312': [{'5850': 0}]}> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']> 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65562]: {'3312': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65562')) 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65562]: {'3312': [{'5850': 1}]}> 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65562]: {'3312': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65562')) 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65562]: {'3312': [{'5850': 1}]}> 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:09 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65562]: {'3312': [{'5850': 1}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65562')) 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65562]: {'3312': [{'5850': 0}]}> . . . . 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Matbordshörna","9003":65569,"9002":1545239209,"9020":1606295179,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E27 W opal 1000lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":158,"9003":0}]} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Hammockhörna","9003":65568,"9002":1543741376,"9020":1606295181,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E14 W op/ch 400lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":145,"9003":0}]} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Draklampa","9003":65567,"9002":1543740843,"9020":1606295181,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E14 W op/ch 400lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":254,"9003":0}]} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"TV rum","9003":65558,"9002":1515604908,"9020":1606295181,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E27 opal 1000lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":254,"9003":0}]} 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Vänster högtalare","9003":65561,"9002":1519573137,"9020":1606295181,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E27 W opal 1000lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":63,"9003":0}]} 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Fönsterlampa","9003":65542,"9002":1513770771,"9020":1606295185,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb E14 W op/ch 400lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":165,"9003":0}]} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Willes taklampa","9003":65553,"9002":1513772166,"9020":1606295181,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 W 400lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":119,"9003":0}]} 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Ledstrip","3312":[{"5850":1,"5851":44,"9003":0}],"9003":65563,"9002":1539012474,"9020":1606295180,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI control outlet","2":"","3":"2.0.024"},"5750":3} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"Willes taklampa","9003":65554,"9002":1513772372,"9020":1606295180,"9054":0,"9019":1,"3":{"6":1,"0":"IKEA of Sweden","1":"TRADFRI bulb GU10 W 400lm","2":"","3":"1.2.214"},"5750":2,"3311":[{"5850":1,"5851":119,"9003":0}]} 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}> 2020-11-25 20:31:10 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://192.168.1.231:5684/15001/65545')) 2020-11-25 20:31:10 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command put ['15001', 65545]: {'3311': [{'5850': 0}]}>

samuelbenzaquen commented 3 years ago

Same issues here. practically every morning I wake up to the Integration being broken. Any way to automate the reload of the integration?

onkelbeh commented 3 years ago

I am afraid this won't help (sometimes) here at my site, currently on 0.118.3, the gateway is on 1.9.27. While the gateway still is controllable via the IKEA app, but it cannot be controlled from Haome Assistant:

After reloading the component:

about 900 times:
2020-11-28 10:30:39 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 172.16.4.90 <Command get ['15011', '15012']>
2020-11-28 10:30:39 WARNING (MainThread) [pytradfri.api.aiocoap_api] Protocol is shutdown, cancelling command: 172.16.4.90 <Command get ['15011', '15012']>

and then:
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5536': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65543'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'15015': [{'5536': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65544'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65540]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65540'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65543'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65544'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65540]: {'15015': [{'5536': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65540'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5536': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65543'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'15015': [{'5536': 0}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65544'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65540]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65540'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65543'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'15015': [{'5536': 100}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65544'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65540]: {'15015': [{'5523': True}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65540'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65543]: {'15015': [{'5523': True}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65543'))
2020-11-28 10:30:40 ERROR (MainThread) [homeassistant.components.tradfri.base_class] Unable to execute command <Command put ['15001', 65544]: {'15015': [{'5523': True}]}>: ('There was an error with the request.', CredentialsMissingError('No suitable credentials for coaps://172.16.4.90:5684/15001/65544'))
2020-11-28 10:30:42 INFO (MainThread) [coap] Retransmission, Message ID: 42240.
2020-11-28 10:30:46 INFO (MainThread) [coap] Retransmission, Message ID: 42240.
2020-11-28 10:30:55 INFO (MainThread) [coap] Retransmission, Message ID: 42240.
2020-11-28 10:31:12 INFO (MainThread) [coap] Retransmission, Message ID: 42240.

After that, the Gateway is dead. It is no more controllable via the IKEA app. Although, sometimes a command make it's way through, could be that a shutter suddenly performes a command 15 minutes after it was sent.

when I then reboot the gateway:

2020-11-28 10:44:48 INFO (MainThread) [coap] Exchange timed out
2020-11-28 10:45:26 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: tradfri

2020-11-28 10:47:26 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: tradfri
2020-11-28 10:47:42 WARNING (MainThread) [coap] Received Type.ACK from <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7f85b499a430>, but could not match it to a running exchange.
2020-11-28 10:47:42 INFO (MainThread) [coap] Duplicate NON, ACK or RST received
2020-11-28 10:47:42 INFO (MainThread) [coap] Duplicate NON, ACK or RST received
2020-11-28 10:47:42 INFO (MainThread) [coap] Duplicate NON, ACK or RST received
2020-11-28 10:47:42 INFO (MainThread) [coap] Duplicate NON, ACK or RST received
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.components.cover] Setting up cover.tradfri
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.components.light] Setting up light.tradfri
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.tradfri
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.components.switch] Setting up switch.tradfri
/usr/lib/python3.8/site-packages/homeassistant/core.py:469: RuntimeWarning: coroutine 'get_service' was never awaited
  self._pending_tasks.clear()
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 257.13s
2020-11-28 10:47:42 INFO (MainThread) [homeassistant.core] Starting Home Assistant

I will now try to update the gateway. It is now on 1.12.31 after the Update. Let's see if this changes something.

litinoveweedle commented 3 years ago

Same issues here. practically every morning I wake up to the Integration being broken. Any way to automate the reload of the integration?

My problems are less often although it is real annoying as well. I have outage every few days. In my case I have Tradfri gateway connected to wired Ethernet network, but I doubt it has anything to do with connection. Even with flaky connection Integration shall recover from whatever state it goes to. And as we all proved, there is nothing wrong with gateway itself - as IKEA app keeps working even when HA stops.

As this integration is supported by HA core team, I would expect maintainer should be assigned to this case. Especially when IKEA logo is proudly displayed on HA front page as supported integration. So far this is just pool of frustrated users. So could the maintainer step in please so we can move forward? I bet that we are ready to provide further logs and help with testing.

ggravlingen commented 3 years ago

I’m reading the thread but I’m afraid I don’t have any answers as to why this is not working in your environments.

The good thing is that this is open source so it’s open for everyone to fork the code, try their ideas and submit a pull request with proposed changes that solves the issue. Please feel free to!

One thing that stuck me when I read the logs above: does the IKEA gateway switch IPs in your network, ie have you set it to fixed IP? If you switch the IP, I believe HA will lose the credentials so I would set it to using a fixed IP.

litinoveweedle commented 3 years ago

oh sorry, I based my assumption on that there is no Assignee for this issue. I understand concept of FOSS, but with HA I am personally on the level of script kiddie. ;-) Also observing HA conditions for PR acceptance I doubt it would pass anyway. So I am afraid this will has to go for HA core team.

Regarding your question - I have permanent DHCP IP lease set for Tradfri GW. So it has all the time the same IP. Also pinging to GW from HA do not indicate any network issues. Please note, that HA restarts helps, so IMHO this is probably something unrelated to the network connection. If there is anything I can test please let me know.

P.S.: My issue started around the time when Tradfri integration went from my configuration.yaml into the new GUI style (I guess there was a lot of changes at that time), although it could be pure coincidence.

ggravlingen commented 3 years ago

What's happened recently (a few months ago) is that the upstream library aiocoap was updated. We also updated pytradfri, which is being used by Home Assistant to communicate with the gateway. The reason for the update of pytradfri in Home Assistant, I believe, was to support multiple gateways.

Looking at the logs above I note that what's raised is a CredentialsMissingError which, according to the documentation is "Raised when no suiting credentials can be found for a message, or credentials are found but inapplicable to a transport's security mechanisms."

Investigating further into the code, in the place where I believe the error is raised, it seems the author of aiocoap has realised there are some limitations to the implementation: "Matching is currently based on wildcards, but not yet very well thought out."

While I still don't understand why your setups are throwing so many errors (mine has run like a Swiss watch for many years), I believe it would be a good idea to investigate further if that part of aiocoap could be rewritten.

litinoveweedle commented 3 years ago

Probably best log trace was provided here: https://github.com/home-assistant/core/issues/42563#issuecomment-735208731

As you can see problems starts with:

Protocol is shutdown, cancelling command: 172.16.4.90 <Command get ['15011', '15012']>

I would not be surprised if following missing credentials errors are more likely result and not the cause - of the protocol going into shutdown state.

from pytradfri

       except LibraryShutdown:
            _LOGGER.warning(
                "Protocol is shutdown, cancelling command: %s %s",
                self._host,
                api_command,
            )
            return None

which seems to be imported from aiocoap:

from aiocoap.error import (
    RequestTimedOut,
    Error,
    ConstructionRenderableError,
    LibraryShutdown,
)

from aiocoap/error.py:

class LibraryShutdown(Error):
    """The library or a transport registered with it was requested to shut
    down; this error is raised in all outstanding requests."""

from aiocoap/tokenmanager.py:

    async def shutdown(self):
        while self.outgoing_requests:
            key = next(iter(self.outgoing_requests.keys()))
            request = self.outgoing_requests.pop(key)
            request.add_exception(error.LibraryShutdown())
        self.outgoing_requests = None

So maybe it would be nice to find out why "The library or a transport registered with it was requested to shut down"

In this log trace https://github.com/home-assistant/core/issues/42563#issuecomment-733931863 we can find even preceeding error:

2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Resetting protocol

is is mentioned after coap timeouts and retransmisions:

2020-11-25 20:30:35 INFO (MainThread) [coap] Exchange timed out
2020-11-25 20:30:35 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.1.231 <Command get ['15011', '15012']>
2020-11-25 20:30:37 INFO (MainThread) [coap] Retransmission, Message ID: 26845.
2020-11-25 20:30:42 INFO (MainThread) [coap] Retransmission, Message ID: 26845.
2020-11-25 20:30:51 INFO (MainThread) [coap] Retransmission, Message ID: 26845.
2020-11-25 20:31:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Running automation actions
2020-11-25 20:31:00 INFO (MainThread) [homeassistant.components.automation.tradfri_keep_alive] tradfri_keep_alive: Executing step call service
2020-11-25 20:31:09 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Resetting protocol

This seems to be corresponding to code in the pytradfri/api/aiocoap_api.py:

    async def _reset_protocol(self, exc=None):
        """Reset the protocol if an error occurs."""
        skip = self._reset_lock.locked()
        async with self._reset_lock:
            if self._shutdown:
                return
            if skip:
                # The lock was already acquired, so another task was already
                # in the process of resetting the protocol, so we don't need
                # to do it again.
                #
                # This is only here for performance reasons.  It should be
                # safe if the protocol is reset multiple times.
                _LOGGER.debug("Skipping reset: protocol was already being reset")
                return

            _LOGGER.debug("Resetting protocol")

            # Be responsible and clean up.
            protocol = await self._get_protocol()
            await protocol.shutdown()
            self._protocol = None

            # The error callbacks are called when shutting down the protocol.
            # Clear the saved callbacks
            self._observations_err_callbacks.clear()

It seems that await protocol.shutdown() is actually calling aiocoap/tokenmanager.py shutdon method.

Until there it seems to be kind of logical, except one thing. If you call coap protocol shutdown is pytradfri able properly reinit and create new coap session?

I would bet my 5cents that pytradfri is failing to reinit properly after some network timeout problem. This would also explain why some people have no issue - as it seems it could be triggered by external factors.

litinoveweedle commented 3 years ago

To continue in my paper analysis. :-) Maybe there is some kind of race condition in the _reset_protocol?

please could anyone with often issues add some logging into pytradfri/api/aiocoap_api.py:

    async def _reset_protocol(self, exc=None):
        """Reset the protocol if an error occurs."""
        skip = self._reset_lock.locked()
        async with self._reset_lock:
            if self._shutdown:
                return
            if skip:
                # The lock was already acquired, so another task was already
                # in the process of resetting the protocol, so we don't need
                # to do it again.
                #
                # This is only here for performance reasons.  It should be
                # safe if the protocol is reset multiple times.
                _LOGGER.debug("Skipping reset: protocol was already being reset")
                return

            _LOGGER.debug("Resetting protocol 1")

            # Be responsible and clean up.
            protocol = await self._get_protocol()
            _LOGGER.debug("Resetting protocol 2")
            await protocol.shutdown()
            _LOGGER.debug("Resetting protocol 3")
            self._protocol = None

            # The error callbacks are called when shutting down the protocol.
            # Clear the saved callbacks
            self._observations_err_callbacks.clear()
            _LOGGER.debug("Resetting protocol 4")