Pytradfri or Home assistant issue: unresponsive after a few hours of start up

Configuration
1

I am new to HA, and have recently set it up via HASS.io in docker on a local ubuntu server. My only ‘smart devices’ are a set of tradfri lights, which are configured via the discovery configurator.

In the last 3-4 days I note that the lights become “unresponsive” to HA after HA has been running for about a few hours. I use the quotes because if I issue a switch off command, it does occur (lights go off, switch in UI toggled to off position) but then the switch in the UI toggles back on. Vice versa for a switch on command. After this since the switch is in the wrong position (with respect to the light), I cannot issue the correct command to the lights. During this time the lights are still working fine via HomeKit. Other objects in HA work fine as well (dark sky sensor, device_tracker).

Below is the log output when this occurs. 192.168.0.12 is the IP for the gateway. Light.TV was the bulb in that instance.

2018-02-02 21:27:19 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139668076590472: Received {'type': 'call_service', 'domain': 'homeassistant', 'service': 'turn_on', 'service_data': {'entity_id': 'light.tv'}, 'id': 11}
2018-02-02 21:27:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.tv, service_call_id=139668149929352-29>
2018-02-02 21:27:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.tv'], service_call_id=139668149929352-30>
2018-02-02 21:27:19 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.12 put ['15001', 65548]: {'3311': [{'5850': 1}]}
2018-02-02 21:27:19 DEBUG (MainThread) [coap] Sending message <aiocoap.Message at 0x7f0702691080: Type.CON PUT (ID 14590, token b'\x00\x00|7') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7f07024fd588>, 3 option(s), 23 byte(s) payload>
2018-02-02 21:27:19 DEBUG (MainThread) [coap] Exchange added, message ID: 14590.
2018-02-02 21:27:19 DEBUG (MainThread) [coap.requester] Timeout is 93.0
2018-02-02 21:27:19 DEBUG (MainThread) [coap.requester] Sending request - Token: 00007c37, Remote: <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7f07024fd588>
2018-02-02 21:27:19 DEBUG (MainThread) [coap] Incoming message <aiocoap.Message at 0x7f0702882fd0: Type.ACK 2.04 Changed (ID 14590, token b'\x00\x00|7') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7f07024fd588>>
2018-02-02 21:27:19 DEBUG (MainThread) [coap] New unique message received
2018-02-02 21:27:19 DEBUG (MainThread) [coap] Exchange removed, message ID: 14590.
2018-02-02 21:27:19 DEBUG (MainThread) [coap] Received Response: <aiocoap.Message at 0x7f0702882fd0: Type.ACK 2.04 Changed (ID 14590, token b'\x00\x00|7') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7f07024fd588>>
2018-02-02 21:27:19 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2018-02-02 21:27:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139668149929352-30>
2018-02-02 21:27:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139668149929352-29>
2018-02-02 21:27:19 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 139668076590472: Sending {'id': 11, 'type': 'result', 'success': True, 'result': None}
2018-02-02 21:27:24 INFO (MainThread) [homeassistant.components.http] Serving /api/error/all to 192.168.0.1 (auth: True)

I wonder if anyone knows the cause of this?

The issue is completely resolved by restarting HA, and recurs after a few hours of this.

Home Assistant v0.62.1
Ubuntu Server 7.10
Docker 17.12.0-ce
Gateway 1.3.14

2

This is the log when HA is working (i.e. after a restart):

2018-02-03 06:45:47 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140568504237472: Received {'type': 'call_service', 'domain': 'homeassistant', 'service': 'turn_off', 'service_data': {'entity_id': 'light.tv'}, 'id': 13}
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.tv, service_call_id=140568646567304-27>
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.tv'], service_call_id=140568646567304-28>
2018-02-03 06:45:47 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Executing 192.168.0.12 put ['15001', 65548]: {'3311': [{'5850': 0}]}
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Sending message <aiocoap.Message at 0x7fd8abea96a0: Type.CON PUT (ID 17835, token b'\x00\x00\x8d\xfc') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>, 3 option(s), 23 byte(s) payload>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Exchange added, message ID: 17835.
2018-02-03 06:45:47 DEBUG (MainThread) [coap.requester] Timeout is 93.0
2018-02-03 06:45:47 DEBUG (MainThread) [coap.requester] Sending request - Token: 00008dfc, Remote: <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Incoming message <aiocoap.Message at 0x7fd8ac45e240: Type.ACK 2.04 Changed (ID 17835, token b'\x00\x00\x8d\xfc') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] New unique message received
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Exchange removed, message ID: 17835.
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Received Response: <aiocoap.Message at 0x7fd8ac45e240: Type.ACK 2.04 Changed (ID 17835, token b'\x00\x00\x8d\xfc') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Incoming message <aiocoap.Message at 0x7fd8abc20f28: Type.CON 2.05 Content (ID 49177, token b'\x00\x00\x8d\xe6') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>, 3 option(s), 216 byte(s) payload>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] New unique message received
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Received Response: <aiocoap.Message at 0x7fd8abc20f28: Type.CON 2.05 Content (ID 49177, token b'\x00\x00\x8d\xe6') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>, 3 option(s), 216 byte(s) payload>
2018-02-03 06:45:47 DEBUG (MainThread) [coap] Sending message <aiocoap.Message at 0x7fd8ac2eeb00: Type.ACK EMPTY (ID 49177, token b'') remote <aiocoap.transports.tinydtls.DTLSClientConnection object at 0x7fd8a7c71cc0>>
2018-02-03 06:45:47 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.04 Changed, Received: 
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140568646567304-28>
2018-02-03 06:45:47 DEBUG (MainThread) [coap.blockwise-requester] Notification received
2018-02-03 06:45:47 DEBUG (MainThread) [coap.blockwise-requester] Reporting completed notification
2018-02-03 06:45:47 DEBUG (MainThread) [pytradfri.api.aiocoap_api] Status: 2.05 Content, Received: {"9001":"TV","3":{"0":"IKEA of Sweden","1":"TRADFRI bulb E27 opal 1000lm","2":"","3":"1.2.214","6":1},"9002":1517070354,"9020":1517592693,"9003":65548,"9054":0,"5750":2,"3311":[{"5850":0,"5851":1,"9003":0}],"9019":1}
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tv, old_state=<state light.tv=on; brightness=1, color_temp=370, rgb_color=[16, 11, 3], friendly_name=TV, supported_features=33 @ 2018-02-03T06:44:56.513126+00:00>, new_state=<state light.tv=off; friendly_name=TV, supported_features=33 @ 2018-02-03T06:45:47.676744+00:00>>
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.living_room, old_state=<state group.living_room=on; entity_id=('light.hallway', 'light.main', 'light.tv'), order=2, friendly_name=Living Room, assumed_state=False @ 2018-02-03T06:44:56.514195+00:00>, new_state=<state group.living_room=off; entity_id=('light.hallway', 'light.main', 'light.tv'), order=2, friendly_name=Living Room, assumed_state=False @ 2018-02-03T06:45:47.678021+00:00>>
2018-02-03 06:45:47 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140568504237472: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'light.tv', 'old_state': <state light.tv=on; brightness=1, color_temp=370, rgb_color=[16, 11, 3], friendly_name=TV, supported_features=33 @ 2018-02-03T06:44:56.513126+00:00>, 'new_state': <state light.tv=off; friendly_name=TV, supported_features=33 @ 2018-02-03T06:45:47.676744+00:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 2, 3, 6, 45, 47, 676767, tzinfo=<UTC>)}}
2018-02-03 06:45:47 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=140568646567304-27>
2018-02-03 06:45:47 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140568504237472: Sending {'id': 2, 'type': 'event', 'event': {'event_type': 'state_changed', 'data': {'entity_id': 'group.living_room', 'old_state': <state group.living_room=on; entity_id=('light.hallway', 'light.main', 'light.tv'), order=2, friendly_name=Living Room, assumed_state=False @ 2018-02-03T06:44:56.514195+00:00>, 'new_state': <state group.living_room=off; entity_id=('light.hallway', 'light.main', 'light.tv'), order=2, friendly_name=Living Room, assumed_state=False @ 2018-02-03T06:45:47.678021+00:00>}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 2, 3, 6, 45, 47, 678044, tzinfo=<UTC>)}}
2018-02-03 06:45:47 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 140568504237472: Sending {'id': 13, 'type': 'result', 'success': True, 'result': None}
3

I’ve not had any luck in finding a solution. I’ve reset the gateway, and tried a clean install of HASS without any luck.

For what it’s worth, I’ve set up a script with toggle a light every so often and resets HA if the toggle fails.

4

I get the same issue, but after 2 days of running, anyone knows anything about this?

5

I’ve only managed to find another report of this:

Max-te’s solution in the thread to alter the observe duration seems to have stopped the problem. I was going from being unresponsive every few hours to not at all anymore. I’m also noticing that my CPU / RAM usage is increasing steadily. Although a reset solves that issue.

1 Like
6

Thanks for the info, for me its not a solution to have to restart to stop the increasing of the CPU/RAM, then I can restart to solve the Trader issue instead. No ide to fix a problem with a problem