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
73.44k stars 30.68k forks source link

Homekit Controller - Netatmo Relay - Error doing job: Task exception was never retrieved #52642

Closed Scialla closed 3 years ago

Scialla commented 3 years ago

The problem

After upgrading to 2021.7.0 having this error in some integration. The main is homekit controller, this error is filling my log.

What is version of Home Assistant Core has the issue?

core-2021.7.0

What was the last working version of Home Assistant Core?

core-2021.6.6

What type of installation are you running?

Home Assistant Core

Integration causing the issue

Homekit Controller

Link to integration documentation on our website

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

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Jul  7 18:26:02 raspberrypi hass[23810]: 2021-07-07 18:26:02 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Jul  7 18:26:02 raspberrypi hass[23810]: Traceback (most recent call last):
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 424, in async_update
Jul  7 18:26:02 raspberrypi hass[23810]:     new_values_dict = await self.get_characteristics(
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 464, in get_characteristics
Jul  7 18:26:02 raspberrypi hass[23810]:     return await self.pairing.get_characteristics(*args, **kwargs)
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/pairing.py", line 243, in get_characteristics
Jul  7 18:26:02 raspberrypi hass[23810]:     response = await self.connection.get_json(url)
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 318, in get_json
Jul  7 18:26:02 raspberrypi hass[23810]:     return json.loads(body)
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
Jul  7 18:26:02 raspberrypi hass[23810]:     return _default_decoder.decode(s)
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
Jul  7 18:26:02 raspberrypi hass[23810]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jul  7 18:26:02 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
Jul  7 18:26:02 raspberrypi hass[23810]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Jul  7 18:26:02 raspberrypi hass[23810]: json.decoder.JSONDecodeError: Expecting value: line 1 column 872 (char 871)
Jul  7 18:27:01 raspberrypi hass[23810]: 2021-07-07 18:27:01 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Jul  7 18:27:01 raspberrypi hass[23810]: Traceback (most recent call last):
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 424, in async_update
Jul  7 18:27:01 raspberrypi hass[23810]:     new_values_dict = await self.get_characteristics(
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 464, in get_characteristics
Jul  7 18:27:01 raspberrypi hass[23810]:     return await self.pairing.get_characteristics(*args, **kwargs)
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/pairing.py", line 243, in get_characteristics
Jul  7 18:27:01 raspberrypi hass[23810]:     response = await self.connection.get_json(url)
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 318, in get_json
Jul  7 18:27:01 raspberrypi hass[23810]:     return json.loads(body)
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
Jul  7 18:27:01 raspberrypi hass[23810]:     return _default_decoder.decode(s)
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
Jul  7 18:27:01 raspberrypi hass[23810]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jul  7 18:27:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
Jul  7 18:27:01 raspberrypi hass[23810]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Jul  7 18:27:01 raspberrypi hass[23810]: json.decoder.JSONDecodeError: Expecting value: line 1 column 872 (char 871)
Jul  7 18:27:23 raspberrypi hass[23810]: 2021-07-07 18:27:23 INFO (MainThread) [homeassistant.components.generic_thermostat.climate] Turning off heater switch.fan_shim
Jul  7 18:28:01 raspberrypi hass[23810]: 2021-07-07 18:28:01 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Jul  7 18:28:01 raspberrypi hass[23810]: Traceback (most recent call last):
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 424, in async_update
Jul  7 18:28:01 raspberrypi hass[23810]:     new_values_dict = await self.get_characteristics(
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 464, in get_characteristics
Jul  7 18:28:01 raspberrypi hass[23810]:     return await self.pairing.get_characteristics(*args, **kwargs)
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/pairing.py", line 243, in get_characteristics
Jul  7 18:28:01 raspberrypi hass[23810]:     response = await self.connection.get_json(url)
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 318, in get_json
Jul  7 18:28:01 raspberrypi hass[23810]:     return json.loads(body)
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
Jul  7 18:28:01 raspberrypi hass[23810]:     return _default_decoder.decode(s)
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
Jul  7 18:28:01 raspberrypi hass[23810]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jul  7 18:28:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
Jul  7 18:28:01 raspberrypi hass[23810]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Jul  7 18:28:01 raspberrypi hass[23810]: json.decoder.JSONDecodeError: Expecting value: line 1 column 872 (char 871)
Jul  7 18:28:48 raspberrypi hass[23810]: 2021-07-07 18:28:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.netatmo
Jul  7 18:29:01 raspberrypi hass[23810]: 2021-07-07 18:29:01 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Jul  7 18:29:01 raspberrypi hass[23810]: Traceback (most recent call last):
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 424, in async_update
Jul  7 18:29:01 raspberrypi hass[23810]:     new_values_dict = await self.get_characteristics(
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 464, in get_characteristics
Jul  7 18:29:01 raspberrypi hass[23810]:     return await self.pairing.get_characteristics(*args, **kwargs)
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/pairing.py", line 243, in get_characteristics
Jul  7 18:29:01 raspberrypi hass[23810]:     response = await self.connection.get_json(url)
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 318, in get_json
Jul  7 18:29:01 raspberrypi hass[23810]:     return json.loads(body)
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
Jul  7 18:29:01 raspberrypi hass[23810]:     return _default_decoder.decode(s)
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
Jul  7 18:29:01 raspberrypi hass[23810]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jul  7 18:29:01 raspberrypi hass[23810]:   File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
Jul  7 18:29:01 raspberrypi hass[23810]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Jul  7 18:29:01 raspberrypi hass[23810]: json.decoder.JSONDecodeError: Expecting value: line 1 column 872 (char 871)


### Additional information

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

homekit_controller documentation homekit_controller source (message by IssueLinks)

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

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

Jc2k commented 3 years ago

What device is this you are connected to?

Can you check your .storage/core.config_entries for this device. Is the ip right? If you take the ip and port and do curl http://ip:port what do you get?

Jc2k commented 3 years ago

Working fine here with the 2021.7.0 image and a Phillips Hue bridge (+ lots of accessories), Eve range extender (+ accessories), Eufy (+ 3 cameras). I have a UniFi based network, and HA is currently on its own subnet so can only see zerconf via the unifi mdns reflection.

So looks like there is a vendor specific or network specific factor to this.

Scialla commented 3 years ago

I have Netatmo Relay (192.168.1.124:5001) with Thermostat and 6 valve, one Koogeek lamp bulb (192.168.101:80) and one air quality sensor with old ravencore FW (192.168.1.135:5556).

With 2021.6.6 all work fine. from .storage/core.config_entries device IP are correct for all device, i can ping they

curl http://192.168.1.124:5001 report nothing curl http://192.168.1.101:80 report File / not_found curl http://192.168.1.135:5556 report:

{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","hidden":false,"primary":false,"characteristics":[{"aid":1,"iid":2,"type":"23","perms":["pr"],"description":"Name","format":"string","value":"Air Quality Sensor-3C26CF"},{"aid":1,"iid":3,"type":"20","perms":["pr"],"description":"Manufacturer","format":"string","value":"lizzus"},{"aid":1,"iid":4,"type":"30","perms":["pr"],"description":"Serial Number","format":"string","value":"CC50E33C26CF"},{"aid":1,"iid":5,"type":"21","perms":["pr"],"description":"Model","format":"string","value":"NODE MCU"},{"aid":1,"iid":6,"type":"52","perms":["pr"],"description":"Firmware Revision","format":"string","value":"1.4.8"},{"aid":1,"iid":7,"type":"14","perms":["pw"],"description":"Identify","format":"bool"}]},{"iid":8,"type":"8D","hidden":false,"primary":true,"characteristics":[{"aid":1,"iid":9,"type":"23","perms":["pr"],"description":"Name","format":"string","value":"Air Quality Sensor"},{"aid":1,"iid":10,"type":"95","perms":["pr","ev"],"ev":false,"description":"Air Quality","format":"uint8","minValue":0,"maxValue":5,"minStep":1,"valid-values":[0,1,2,3,4,5],"value":2},{"aid":1,"iid":11,"type":"90","perms":["pr","ev"],"ev":false,"description":"Carbon Monoxide Level","format":"float","minValue":0,"maxValue":100,"value":5},{"aid":1,"iid":12,"type":"93","perms":["pr","ev"],"ev":false,"description":"Carbon Dioxide Level","format":"float","minValue":0,"maxValue":100000,"value":1169},{"aid":1,"iid":13,"type":"F0000108-03a1-4971-92bf-af2b7d833922","perms":["pr","ev"],"ev":false,"description":"Ethanol Level","format":"float","minValue":0,"maxValue":100,"value":80},{"aid":1,"iid":14,"type":"F0000109-03a1-4971-92bf-af2b7d833922","perms":["pr","ev"],"ev":false,"description":"Ammonium Level","format":"float","minValue":0,"maxValue":100,"value":39},{"aid":1,"iid":15,"type":"F0000110-03a1-4971-92bf-af2b7d833922","perms":["pr","ev"],"ev":false,"description":"Toluene Level","format":"float","minValue":0,"maxValue":100,"value":0},{"aid":1,"iid":16,"type":"F0000111-03a1-4971-92bf-af2b7d833922","perms":["pr","ev"],"ev":false,"description":"Acetone Level","format":"float","minValue":0,"maxValue":100,"value":61},{"aid":1,"iid":17,"type":"F0000106-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"Show Setup","format":"bool","value":true}]},{"iid":18,"type":"8A","hidden":false,"primary":false,"characteristics":[{"aid":1,"iid":19,"type":"23","perms":["pr"],"description":"Name","format":"string","value":"Temperature Sensor"},{"aid":1,"iid":20,"type":"11","perms":["pr","ev"],"ev":false,"description":"Current Temperature","format":"float","unit":"celsius","minValue":0,"maxValue":100,"minStep":0.100000001490116,"value":27.6000003814697}]},{"iid":21,"type":"82","hidden":false,"primary":false,"characteristics":[{"aid":1,"iid":22,"type":"23","perms":["pr"],"description":"Name","format":"string","value":"Humidity Sensor"},{"aid":1,"iid":23,"type":"10","perms":["pr","ev"],"ev":false,"description":"Current Relative Humidity","format":"float","unit":"percentage","minValue":0,"maxValue":100,"minStep":1,"value":60.7999992370605}]},{"iid":24,"type":"F00000FF-03a1-4971-92bf-af2b7d833922","hidden":false,"primary":false,"characteristics":[{"aid":1,"iid":25,"type":"23","perms":["pr"],"description":"Name","format":"string","value":"Setup"},{"aid":1,"iid":107,"type":"F0000107-03a1-4971-92bf-af2b7d833922","perms":["pr"],"description":"1) Actual Dev Type","format":"string","value":"Air Quality Sensor"},{"aid":1,"iid":113,"type":"F0000113-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"3) Offset HUM","format":"float","unit":"percentage","minValue":-15,"maxValue":15,"minStep":1,"value":0},{"aid":1,"iid":112,"type":"F0000112-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"2) Offset TEMP","format":"float","unit":"celsius","minValue":-15,"maxValue":15,"minStep":0.100000001490116,"value":0},{"aid":1,"iid":114,"type":"F0000114-03a1-4971-92bf-af2b7d833922","perms":["pr"],"description":"4) Wifi IP Addr","format":"string","value":"192.168.1.135"},{"aid":1,"iid":115,"type":"F0000115-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"5) Wifi Reset","format":"bool","value":false},{"aid":1,"iid":116,"type":"F0000116-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"6) Reboot","format":"bool","value":false},{"aid":1,"iid":117,"type":"F0000117-03a1-4971-92bf-af2b7d833922","perms":["pr","pw","ev"],"ev":false,"description":"7) Firmware Update","format":"bool","value":false}]}]}]}

All 3 device are working but log is full of error

i've same error, but only at HA start, with UPNP.

Homekit Controller error are continuously.

Thanks

Jc2k commented 3 years ago

Can you turn on debug logs for aiohomekit and homeassistant.components.homekit_controller:

logger:
  logs:
    aiohomekit: debug
    homeassistant.components.homekit_controller: debug

This will be even more verbose, but we should see what requests are sent and what the device is returning.

Scialla commented 3 years ago 
Jul  7 20:22:05 raspberrypi hass[29863]: 2021-07-07 20:22:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to 192.168.1.135:5556
Jul  7 20:22:05 raspberrypi hass[29863]: 2021-07-07 20:22:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to 192.168.1.101:80
Jul  7 20:22:05 raspberrypi hass[29863]: 2021-07-07 20:22:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to 192.168.1.124:5001
Jul  7 20:22:08 raspberrypi hass[29863]: 2021-07-07 20:22:08 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to 192.168.1.135:5556
Jul  7 20:22:08 raspberrypi hass[29863]: 2021-07-07 20:22:08 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to 192.168.1.101:80
Jul  7 20:22:08 raspberrypi hass[29863]: 2021-07-07 20:22:08 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to 192.168.1.124:5001
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:14 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x01
Jul  7 20:22:14 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytes'>) b'\x9a\x1fW\xb7\xea\xaa{\xdaf\x8f{co+\x9f\xb6\x98\xa8\xf4X\xba\xac\x9e\xd2\x81q|\x9e\x88\x7f{*'
Jul  7 20:22:14 raspberrypi hass[29863]: ]
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.101\r\nContent-Length: 37\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x01\x03 \x9a\x1fW\xb7\xea\xaa{\xdaf\x8f{co+\x9f\xb6\x98\xa8\xf4X\xba\xac\x9e\xd2\x81q|\x9e\x88\x7f{*'
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:14 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x01
Jul  7 20:22:14 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytes'>) b'k\xcf\xdf\xb5\x08\x7f\xe1\xf7\xa12\x05h\xc0-\x9fg\xeaJ\x8cbTH\x84)\xb7\x03\xd0\x1f\x11\x8f\xb7u'
Jul  7 20:22:14 raspberrypi hass[29863]: ]
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.135\r\nContent-Length: 37\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x01\x03 k\xcf\xdf\xb5\x08\x7f\xe1\xf7\xa12\x05h\xc0-\x9fg\xeaJ\x8cbTH\x84)\xb7\x03\xd0\x1f\x11\x8f\xb7u'
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:14 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x01
Jul  7 20:22:14 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytes'>) b'\t\x96\x02\x80\xc2\xf3s>c\xc6pYW\xee\xa9\xc7a\xc6p\xff7\x96\x17S\x82\x0f\xea\rm\xe6K#'
Jul  7 20:22:14 raspberrypi hass[29863]: ]
Jul  7 20:22:14 raspberrypi hass[29863]: 2021-07-07 20:22:14 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 37\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x01\x03 \t\x96\x02\x80\xc2\xf3s>c\xc6pYW\xee\xa9\xc7a\xc6p\xff7\x96\x17S\x82\x0f\xea\rm\xe6K#'
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw response: bytearray(b'\x06\x01\x02\x03 `\xa8}\x1a\x81I\xe3\xe9\xd0f\x9c\xdb\x97\x1d\xaa\x7fV\xdd\x1f\xfc\xfd\xcfw\xfa\xc7\xa65\x83\xa0\x03\xd4s\x05e\xe5m7\xed&\xe5\xea\xa0\x01C\xfa\xb7u\xcd\x0b0\xd0\x0c1\xb5&\xe7\x17>.\xe9\x9d\x1f\xbfpQ\xd1\x00ln\xe3Dj{\xe9%3\x97`\xb5\x15\xb9VZ\xa3\x0e\x96\xd4\x98\xa5\xf1^cd\xf3A\xb6M,\xe2\t>\xd7\x84\xbe.\x90\xa3+\xab\x04\xb1\xec\xdf\xee\xc4\xcbi\xbd\xfc`\x1c\xb69~4\xee\xe2;I\xac\xaf\x84\x00\xcd\xbc')
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:17 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x02
Jul  7 20:22:17 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytearray'>) 0x60a87d1a8149e3e9d0669cdb971daa7f56dd1ffcfdcf77fac7a63583a003d473
Jul  7 20:22:17 raspberrypi hass[29863]:   5: (101 bytes/<class 'bytearray'>) 0xe56d37ed26e5eaa00143fab775cd0b30d00c31b526e7173e2ee99d1fbf7051d1006c6ee3446a7be925339760b515b9565aa30e96d498a5f15e6364f341b64d2ce2093ed784be2e90a32bab04b1ecdfeec4cb69bdfc601cb6397e34eee23b49acaf8400cdbc
Jul  7 20:22:17 raspberrypi hass[29863]: ]
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:17 raspberrypi hass[29863]:   1: (17 bytes/<class 'bytearray'>) 0x41363a38423a43303a35333a38443a3246
Jul  7 20:22:17 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytearray'>) 0xb4ce1e4f09c4b544a6bc3d4d98f50989a29b7918dadd6f8450077b6e17e5ca2bd0d5a68c5ccc018f40602227627991adf3799afa768ba8fba395f6c83c23e407
Jul  7 20:22:17 raspberrypi hass[29863]: ]
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:17 raspberrypi hass[29863]:   1: (36 bytes/<class 'bytes'>) b'6da12d26-3dcf-4133-9db5-6dd0c9b3b55d'
Jul  7 20:22:17 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytes'>) b'7\xe8 \x08\xe4]\xe50-\xcc5B\xeb<q1@\xa9\x1a\xae\xf0w\x93\x8d:\xeaY\xa0\xaa\xd0`\x00\xf3\\\xb9\x11\x16u)\xc5f\x9aX\xe619\xc9n\xbb5\xc6\x1f~\x9e\x02!\x04?\x82n5\xc5\x9f\t'
Jul  7 20:22:17 raspberrypi hass[29863]: ]
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:17 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x03
Jul  7 20:22:17 raspberrypi hass[29863]:   5: (120 bytes/<class 'bytes'>) b"Dg\x05\xddb\x9b\x84d\xcd~\x12cbyD\xda\x14\nt\x11\xf7%IE\x86\xa0@\xa2~\x88\xa0\xa4\xff4@s\xc5SU\xcb'\xba\xf7\xc1i=8\xe3\xde\xc9s\x11\xd8\x7f\xac\x1d\x85\x89\xcb\x8a\xeeI:wu\x14\xe2J\x07r\x9f\x82\x95\x88\xe1^F\xd6\x7f\x9a\xcd\xf37\xe0\x94@C\xc3\xab\x83.\x80e\xab\x91ej\xa9Q\x0fS\x07U\xcc\xd2E\xfc6\xa5v\x82}\xc1i\xbb\xa5\xdb\xfb\x98\x94"
Jul  7 20:22:17 raspberrypi hass[29863]: ]
Jul  7 20:22:17 raspberrypi hass[29863]: 2021-07-07 20:22:17 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw request: b"POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.101\r\nContent-Length: 125\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x03\x05xDg\x05\xddb\x9b\x84d\xcd~\x12cbyD\xda\x14\nt\x11\xf7%IE\x86\xa0@\xa2~\x88\xa0\xa4\xff4@s\xc5SU\xcb'\xba\xf7\xc1i=8\xe3\xde\xc9s\x11\xd8\x7f\xac\x1d\x85\x89\xcb\x8a\xeeI:wu\x14\xe2J\x07r\x9f\x82\x95\x88\xe1^F\xd6\x7f\x9a\xcd\xf37\xe0\x94@C\xc3\xab\x83.\x80e\xab\x91ej\xa9Q\x0fS\x07U\xcc\xd2E\xfc6\xa5v\x82}\xc1i\xbb\xa5\xdb\xfb\x98\x94"
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:18 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x02
Jul  7 20:22:18 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytearray'>) 0xa064a88dbf4b11855bb5ea8bdbe849d874d90b22e3bf111ea0831fab8593a56c
Jul  7 20:22:18 raspberrypi hass[29863]:   5: (101 bytes/<class 'bytearray'>) 0x108f490c5880a28ca3b6d8b190c83412b0cbef75eeb79ef499860bdd6b9179da2fcc33f8ee1a62a894ff7bd6ec56274a4bd8e2d6d1c03c5f0298f298b4c1bd4247adebcc3face484a912fcbb52cf7537b45d6ff94299655f36e901d74012fc41085e807ee3
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:18 raspberrypi hass[29863]:   1: (17 bytes/<class 'bytearray'>) 0x39303a45323a38373a37423a35343a3246
Jul  7 20:22:18 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytearray'>) 0x63e2c566ccd80ef9e9f7d580daa5736be3c6601c5537ae284ca1f2cd55a677372d53246f402ddaa1af56652c5fe5cca303ff810b67c2413616b093259148aa0d
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:18 raspberrypi hass[29863]:   1: (36 bytes/<class 'bytes'>) b'a023c4c2-eee7-44dd-bf96-584d20eed32a'
Jul  7 20:22:18 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytes'>) b'\x0c\xe7*$\x0e\xe9D\xf9]\xdd\xb6a\x07\x07\x90\n:\x94=\x99==\xd6\xe6\xed\x1bX\xd8\xfa\xc2\xa1V\x08\x90kbo%P3\xb4=\x13\xe8x\xad(4\xdf\x18\xf7U\xee\x17\xff\xfa~\xe2\x00\n\x19\x0b\xc2\x02'
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:18 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x03
Jul  7 20:22:18 raspberrypi hass[29863]:   5: (120 bytes/<class 'bytes'>) b'\x8d\xc7\xfa\xd9\x81\x13Jp\xc5\xd0\x02\xe3\x7f\xed\xce\t\x84\x1cV\x05\x8f\x88\x91F;j/\x11qaV9\xb6d\xa1\xa0x\x7f\xfa\xd8\xabq\xfeI\x9e\xd6\xa8%\xa4Z\x08\x0ep\xf2\xeb\xe0\xe80\xecI\xff0\x07\x8bD\xfa\xcd\x0f\x90\x1carJ\x0e\xc9\x8c"Z\t\x80\x820\x93oI_\x89\x9e7\xba\xd3\xe9\x98m\xf9\xa6`\xa6\x07\xa2>\xb7E\x880\xf5\x8b\x8e\n\x1a\x08\x96\xb9\x11\xd6\x8f@\'\xb0\xeb'
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.135\r\nContent-Length: 125\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x03\x05x\x8d\xc7\xfa\xd9\x81\x13Jp\xc5\xd0\x02\xe3\x7f\xed\xce\t\x84\x1cV\x05\x8f\x88\x91F;j/\x11qaV9\xb6d\xa1\xa0x\x7f\xfa\xd8\xabq\xfeI\x9e\xd6\xa8%\xa4Z\x08\x0ep\xf2\xeb\xe0\xe80\xecI\xff0\x07\x8bD\xfa\xcd\x0f\x90\x1carJ\x0e\xc9\x8c"Z\t\x80\x820\x93oI_\x89\x9e7\xba\xd3\xe9\x98m\xf9\xa6`\xa6\x07\xa2>\xb7E\x880\xf5\x8b\x8e\n\x1a\x08\x96\xb9\x11\xd6\x8f@\'\xb0\xeb'
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'\x06\x01\x02\x03 \x17\xa6\rH\xa3\x92l.|>\xc3q4f\xb6\x7f\x04<\x95Z\xf2"K\x0b\x03\xbc\xd5\x88S\x0e\xbeh\x05e"\x0fK\xaa\xff\xff\xf8B\x9d\x0c\xb9m\xb6\xa3\xd4\xebb\x90\xe1o\x9d\xc5%\xcd\'_6\xdb\x97\x1b\xeb\x8e\x93\x16\xdfH\x1b\xa9\x0c\xbd?\xaf&\xd1\x9c\xb4\xfb\x05\x8e7\x8f{\xcc\xbe\x9b\xc3HG>n=\x13\xb2\xd1q\x96\x81\xc1^\xee@\xdb\xc0[Z\x8b\xdfLYn\xee\xa2\xbeSJhsP\xb3\xa10x\x93\xee\xf6\xf1\xf5\xbc]\xe2\xe2')
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:18 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x02
Jul  7 20:22:18 raspberrypi hass[29863]:   3: (32 bytes/<class 'bytearray'>) 0x17a60d48a3926c2e7c3ec3713466b67f043c955af2224b0b03bcd588530ebe68
Jul  7 20:22:18 raspberrypi hass[29863]:   5: (101 bytes/<class 'bytearray'>) 0x220f4baafffff8429d0cb96db6a3d4eb6290e16f9dc525cd275f36db971beb8e9316df481ba90cbd3faf26d19cb4fb058e378f7bccbe9bc348473e6e3d13b2d1719681c15eee40dbc05b5a8bdf4c596eeea2be534a687350b3a1307893eef6f1f5bc5de2e2
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:18 raspberrypi hass[29863]:   1: (17 bytes/<class 'bytearray'>) 0x37353a30443a42463a46463a44413a4635
Jul  7 20:22:18 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytearray'>) 0x969fef8edf8b21ee142ff52d6b52dcde443c02b553091c4dc98a24fd9df198cba39597273034ad7c7438216747a04a0a9ecd240c5c81d8c80afd1eb2f490a800
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:18 raspberrypi hass[29863]:   1: (36 bytes/<class 'bytes'>) b'7fbbf667-5c24-4b82-a586-4f0c595a760b'
Jul  7 20:22:18 raspberrypi hass[29863]:   10: (64 bytes/<class 'bytes'>) b'\x0c^\x16;\xb4dM\xa3@]0*\xc0`\xb2H\xcct\x01"4\xca\x7f\xb93\x1d\x1e]\x80\xb3\xf6\x02 \xebb\x92\xee:\xe5\xd4\xb51\xc3jG\x80\x07\xcc\xce\x99\xf2e\x94\x057%]\xd4eB<C\xda\x0e'
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
Jul  7 20:22:18 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x03
Jul  7 20:22:18 raspberrypi hass[29863]:   5: (120 bytes/<class 'bytes'>) b'\xf0\n40\x89\xbc?\x99\x18D\xf7*\x12\x82\xebZa\xe5\x19\xd7\xe7/\x91\t\xc5\x81\xbb\xa9\xd9D\xfd\x08\xbcM\xd6\x18<\xedD\xafu:\xff\x05h\xe5-\xe6M\x98\xa8jX\xb9.\x95\xf5E\xed\x9e|\xf4L1-\x13\xa8\xc9\xf1\xaa\x1b\x10n\xfc+\xdd\xd7Z<\x068\xd0\x12\xcf\xb83\xcf]H\xf7\xa7ln\x87\xaf\x8e>Y>\x85C\xeb\xed\xa2\xac\xadPY\xd9\xef\x0c\x19JX\x03\xa7.\x92u\xf5'
Jul  7 20:22:18 raspberrypi hass[29863]: ]
Jul  7 20:22:18 raspberrypi hass[29863]: 2021-07-07 20:22:18 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 125\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x03\x05x\xf0\n40\x89\xbc?\x99\x18D\xf7*\x12\x82\xebZa\xe5\x19\xd7\xe7/\x91\t\xc5\x81\xbb\xa9\xd9D\xfd\x08\xbcM\xd6\x18<\xedD\xafu:\xff\x05h\xe5-\xe6M\x98\xa8jX\xb9.\x95\xf5E\xed\x9e|\xf4L1-\x13\xa8\xc9\xf1\xaa\x1b\x10n\xfc+\xdd\xd7Z<\x068\xd0\x12\xcf\xb83\xcf]H\xf7\xa7ln\x87\xaf\x8e>Y>\x85C\xeb\xed\xa2\xac\xadPY\xd9\xef\x0c\x19JX\x03\xa7.\x92u\xf5'
Jul  7 20:22:19 raspberrypi hass[29863]: 2021-07-07 20:22:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw response: bytearray(b'\x06\x01\x04')
Jul  7 20:22:19 raspberrypi hass[29863]: 2021-07-07 20:22:19 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:19 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x04
Jul  7 20:22:19 raspberrypi hass[29863]: ]
Jul  7 20:22:19 raspberrypi hass[29863]: 2021-07-07 20:22:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.101:80 established
Jul  7 20:22:19 raspberrypi hass[29863]: 2021-07-07 20:22:19 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for A6:8B:C0:53:8D:2F
Jul  7 20:22:20 raspberrypi hass[29863]: 2021-07-07 20:22:20 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw response: bytearray(b'\x06\x01\x04')
Jul  7 20:22:20 raspberrypi hass[29863]: 2021-07-07 20:22:20 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:20 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x04
Jul  7 20:22:20 raspberrypi hass[29863]: ]
Jul  7 20:22:20 raspberrypi hass[29863]: 2021-07-07 20:22:20 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.135:5556 established
Jul  7 20:22:20 raspberrypi hass[29863]: 2021-07-07 20:22:20 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 90:E2:87:7B:54:2F
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.101\r\nContent-Length: 135\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":1,"iid":11,"ev":true},{"aid":1,"iid":8,"ev":true},{"aid":1,"iid":10,"ev":true},{"aid":1,"iid":9,"ev":true}]}'
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Starting HomeKit controller update: A6:8B:C0:53:8D:2F
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'\x06\x01\x04')
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
Jul  7 20:22:21 raspberrypi hass[29863]:   6: (1 bytes/<class 'bytearray'>) 0x04
Jul  7 20:22:21 raspberrypi hass[29863]: ]
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.124:5001 established
Jul  7 20:22:21 raspberrypi hass[29863]: 2021-07-07 20:22:21 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 75:0D:BF:FF:DA:F5
Jul  7 20:22:22 raspberrypi hass[29863]: 2021-07-07 20:22:22 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.135\r\nContent-Length: 108\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":1,"iid":20,"ev":true},{"aid":1,"iid":23,"ev":true},{"aid":1,"iid":10,"ev":true}]}'
Jul  7 20:22:23 raspberrypi hass[29863]: 2021-07-07 20:22:23 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 50\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":7,"iid":10,"ev":true}]}'
Jul  7 20:22:23 raspberrypi hass[29863]: 2021-07-07 20:22:23 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw response: bytearray(b'')
Jul  7 20:22:23 raspberrypi hass[29863]: 2021-07-07 20:22:23 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw request: b'GET /characteristics?id=1.8,1.9,1.10,1.11 HTTP/1.1\r\nHost: 192.168.1.101\r\n\r\n'
Jul  7 20:22:23 raspberrypi hass[29863]: 2021-07-07 20:22:23 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw response: bytearray(b'')
Jul  7 20:22:25 raspberrypi hass[29863]: 2021-07-07 20:22:25 DEBUG (MainThread) [aiohomekit.controller.ip.pairing] Attempted to subscribe to characteristics but could not connect to accessory
Jul  7 20:22:25 raspberrypi hass[29863]: 2021-07-07 20:22:25 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Starting HomeKit controller update: 90:E2:87:7B:54:2F
Jul  7 20:22:25 raspberrypi hass[29863]: 2021-07-07 20:22:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'')
Jul  7 20:22:25 raspberrypi hass[29863]: 2021-07-07 20:22:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 50\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":6,"iid":11,"ev":true}]}'
Jul  7 20:22:26 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.101: raw response: bytearray(b'{"characteristics":[{"aid":1,"iid":8,"value":false},{"aid":1,"iid":9,"value":30.00000},{"aid":1,"iid":10,"value":0.00000},{"aid":1,"iid":11,"value":100}]}')
Jul  7 20:22:26 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for A6:8B:C0:53:8D:2F
Jul  7 20:22:26 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Finished HomeKit controller update: A6:8B:C0:53:8D:2F
Jul  7 20:22:26 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw request: b'GET /characteristics?id=1.20,1.23,1.20,1.10 HTTP/1.1\r\nHost: 192.168.1.135\r\n\r\n'
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'')
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 51\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":10,"iid":10,"ev":true}]}'
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:27 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 90:E2:87:7B:54:2F
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:27 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.135: raw response: bytearray(b'{"characteristics":[{"aid":1,"iid":20,"value":27.6000003814697},{"aid":1,"iid":23,"value":60.2000007629395},{"aid":1,"iid":20,"value":27.6000003814697},{"aid":1,"iid":10,"value":2}]}')
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:27 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 90:E2:87:7B:54:2F
Jul  7 20:22:27 raspberrypi hass[29863]: 2021-07-07 20:22:27 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Finished HomeKit controller update: 90:E2:87:7B:54:2F
Jul  7 20:22:28 raspberrypi hass[29863]: 2021-07-07 20:22:28 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 90:E2:87:7B:54:2F
Jul  7 20:22:32 raspberrypi hass[29863]: 2021-07-07 20:22:32 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'')
Jul  7 20:22:32 raspberrypi hass[29863]: 2021-07-07 20:22:32 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 50\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":4,"iid":11,"ev":true}]}'
Jul  7 20:22:32 raspberrypi hass[29863]: 2021-07-07 20:22:32 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'')
Jul  7 20:22:32 raspberrypi hass[29863]: 2021-07-07 20:22:32 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 50\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":2,"iid":11,"ev":true}]}'
Jul  7 20:22:33 raspberrypi hass[29863]: 2021-07-07 20:22:32 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 90:E2:87:7B:54:2F
Jul  7 20:22:33 raspberrypi hass[29863]: 2021-07-07 20:22:33 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'')
Jul  7 20:22:33 raspberrypi hass[29863]: 2021-07-07 20:22:33 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.1.124\r\nContent-Length: 50\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":7,"iid":12,"ev":true}]}'

This is the first part, error still continues..

i repeat that devices work well

Scialla commented 3 years ago

it seems every time aiohomekit is connecting with netatmo relay (192.168.1.124) i've error in log:

Jul  7 21:19:53 raspberrypi hass[29863]: 2021-07-07 21:19:53 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Starting HomeKit controller update: 75:0D:BF:FF:DA:F5
Jul  7 21:19:53 raspberrypi hass[29863]: 2021-07-07 21:19:53 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw request: b'GET /characteristics?id=2.10,2.11,2.12,2.13,3.10,3.11,3.12,3.13,4.10,4.11,4.12,4.13,6.10,6.11,6.12,6.13,7.10,7.11,7.12,7.13,8.10,8.11,8.12,8.13,10.10,10.11,10.12,10.13,2.12,3.12,4.12,6.12,7.12,8.12,10.12 HTTP/1.1\r\nHost: 192.168.1.124\r\n\r\n'
Jul  7 21:19:54 raspberrypi hass[29863]: 2021-07-07 21:19:54 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'{"characteristics":[{"aid":2,"iid":10,"value":0},{"aid":2,"iid":11,"value":1},{"aid":2,"iid":12,"value":27.0},{"aid":2,"iid":13,"value":20.0},{"aid":3,"iid":10,"value":0},{"aid":3,"iid":11,"value":1},{"aid":3,"iid":12,"value":26.5},{"aid":3,"iid":13,"value":20.5},{"aid":4,"iid":10,"value":0},{"aid":4,"iid":11,"value":1},{"aid":4,"iid":12,"value":27.5},{"aid":4,"iid":13,"value":20.5},{"aid":6,"iid":10,"value":0},{"aid":6,"iid":11,"value":1},{"aid":6,"iid":12,"value":26.0},{"aid":6,"iid":13,"value":20.0},{"aid":7,"iid":10,"value":0},{"aid":7,"iid":11,"value":1},{"aid":7,"iid":12,"value":26.5},{"aid":7,"iid":13,"value":20.5},{"aid":8,"iid":10,"value":0},{"aid":8,"iid":11,"value":1},{"aid":8,"iid":12,"value":26.5},{"aid":8,"iid":13,"value":20.5},{"aid":10,"iid":10,"value":0},{"aid":10,"iid":11,"value":1},{"aid":10,"iid":12,"value":27.0},{"aid":10,"iid":13,"value":20.5},]}')
Jul  7 21:19:54 raspberrypi hass[29863]: 2021-07-07 21:19:54 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Jul  7 21:19:54 raspberrypi hass[29863]: Traceback (most recent call last):
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 424, in async_update
Jul  7 21:19:54 raspberrypi hass[29863]:     new_values_dict = await self.get_characteristics(
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/srv/homeassistant/lib/python3.8/site-packages/homeassistant/components/homekit_controller/connection.py", line 464, in get_characteristics
Jul  7 21:19:54 raspberrypi hass[29863]:     return await self.pairing.get_characteristics(*args, **kwargs)
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/pairing.py", line 243, in get_characteristics
Jul  7 21:19:54 raspberrypi hass[29863]:     response = await self.connection.get_json(url)
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/srv/homeassistant/lib/python3.8/site-packages/aiohomekit/controller/ip/connection.py", line 318, in get_json
Jul  7 21:19:54 raspberrypi hass[29863]:     return json.loads(body)
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
Jul  7 21:19:54 raspberrypi hass[29863]:     return _default_decoder.decode(s)
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
Jul  7 21:19:54 raspberrypi hass[29863]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jul  7 21:19:54 raspberrypi hass[29863]:   File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
Jul  7 21:19:54 raspberrypi hass[29863]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Jul  7 21:19:54 raspberrypi hass[29863]: json.decoder.JSONDecodeError: Expecting value: line 1 column 879 (char 878)
bdraco commented 3 years ago
Screen Shot 2021-07-07 at 2 41 24 PM

The device is producing invalid json

Scialla commented 3 years ago

Sorry, but if you have check json for device 192.168.1.135 (that i've posted) json linter returned this: Schermata 2021-07-07 alle 21 50 06

if not, i don't understand....

error seems appears when connecting to netatmo relay (192.168.1.124) with 2021.6.6 no errors in log

thanks for your patience

bdraco commented 3 years ago

Jul 7 21:19:54 raspberrypi hass[29863]: 2021-07-07 21:19:54 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.124: raw response: bytearray(b'{"characteristics":[{"aid":2,"iid":10,"value":0},{"aid":2,"iid":11,"value":1},{"aid":2,"iid":12,"value":27.0},{"aid":2,"iid":13,"value":20.0},{"aid":3,"iid":10,"value":0},{"aid":3,"iid":11,"value":1},{"aid":3,"iid":12,"value":26.5},{"aid":3,"iid":13,"value":20.5},{"aid":4,"iid":10,"value":0},{"aid":4,"iid":11,"value":1},{"aid":4,"iid":12,"value":27.5},{"aid":4,"iid":13,"value":20.5},{"aid":6,"iid":10,"value":0},{"aid":6,"iid":11,"value":1},{"aid":6,"iid":12,"value":26.0},{"aid":6,"iid":13,"value":20.0},{"aid":7,"iid":10,"value":0},{"aid":7,"iid":11,"value":1},{"aid":7,"iid":12,"value":26.5},{"aid":7,"iid":13,"value":20.5},{"aid":8,"iid":10,"value":0},{"aid":8,"iid":11,"value":1},{"aid":8,"iid":12,"value":26.5},{"aid":8,"iid":13,"value":20.5},{"aid":10,"iid":10,"value":0},{"aid":10,"iid":11,"value":1},{"aid":10,"iid":12,"value":27.0},{"aid":10,"iid":13,"value":20.5},]}')

There is a trailing , in the json you posted above.

Scialla commented 3 years ago

this means that the problem is with netatmo relay (192.168.1.124) and his json exposed, integrated with homekit controller.... right?

what's changed in 2021.7.0 for integrate Netatmo? with 2021.6.6 i don't have this errors...

what i can do to resolve? i think nothing.. right?

Thanks again

Jc2k commented 3 years ago

This isn't something that has changed in HA in the latest release. It's either a Netamo firmware update or the errors were happening but not noticed. Perhaps there was a logging improvement? Perhaps homekit_controller is trying to recover from the failure more often than before, creating more errors.

Scialla commented 3 years ago

if i do a rollback to 2021.6.6 errors disappears. Non firmware upgrade for netatmo. the only changes i've see are new entity temperature sensor, for every valve or thermostat, in 2021.7.0, with homekit controller. yes, is probably is trying to recover with more errors... anything device works fine

Jc2k commented 3 years ago

Looking at your logs again I don't think it is trying more often. Once a minute is the normal rate.

It is impossible that this code ever worked for your device, as it is not returning valid JSON. And if its not had a firmware update then your device has always returned invalid JSON, and never worked. It might appear to work, but trust me, polling just won't work with the corrupt data your device is returning. We don't have and have never had code that can recover from invalid JSON like this.

So I can only assume the errors were just not getting logged before, and now that is fixed you can see how broken it was all along.

Ideally the vendor would fix this and return valid JSON. Historically they have been reluctant to fix stuff for us, especially for uncertified implementations (do you know if Netamo Relay is certified)?

Scialla commented 3 years ago

For sure, if i change settings on lovelace, the devices (and Netatmo App) changes their settings. I've tried again in this moment and work. For sure, if i changes settings on devices or from app, in lovelace settings changes. i tried again now and work. i've errors in log BUT work.

if you don't believe me i can make a video and post it here, with lovelace, netatmo app and terminal open together

Scialla commented 3 years ago

in core.config_entries this is config for netatmo relay:

            {
                "entry_id": "d47bc66bd96b16a7e70157e151295bbc",
                "version": 1,
                "domain": "homekit_controller",
                "title": "Netatmo Relay",
                "data": {
                    "AccessoryPairingID": "75:0D:BF:FF:DA:F5",
                    "AccessoryLTPK": "fe0729f3f6904a60367835d71c17ef0620778c445e6dcf5492eac3799a26daff",
                    "iOSPairingId": "7fbbf667-5c24-4b82-a586-4f0c595a760b",
                    "iOSDeviceLTSK": "a76bb0f95e228992a109d73251ab273d2bba2e4f1eb93ec8d7f10cba3bc0676c",
                    "iOSDeviceLTPK": "9a796e436958b9f09d9942dc43ccf4c5748e1dcd6ad17de953108e3a0f0eba76",
                    "AccessoryIP": "192.168.1.124",
                    "AccessoryPort": 5001,
                    "Connection": "IP"
                },
                "options": {},
                "pref_disable_new_entities": false,
                "pref_disable_polling": false,
                "source": "zeroconf",
                "unique_id": "75:0d:bf:ff:da:f5",
                "disabled_by": null
            },
Jc2k commented 3 years ago

The code that is erroring is polling, the 2 actions that work for you are making changes and receiving events. So it seems to work, but is in fact broken.

When events work properly they could mask the fact that polling is broken, but there will be subtle edge cases. Off the top of my head:

We use json.loads from the python standard library to parse JSON and e.g. if i parse the broken data from your device into a python3 terminal:

% python3
Python 3.9.5 (default, May  4 2021, 03:33:11) 
[Clang 12.0.0 (clang-1200.0.32.29)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import json
>>> json.loads('{"characteristics":[{"aid":2,"iid":10,"value":0},{"aid":2,"iid":11,"value":1},{"aid":2,"iid":12,"value":27.0},{"aid":2,"iid":13,"value":20.0},{"aid":3,"iid":10,"value":0},{"aid":3,"iid":11,"value":1},{"aid":3,"iid":12,"value":26.5},{"aid":3,"iid":13,"value":20.5},{"aid":4,"iid":10,"value":0},{"aid":4,"iid":11,"value":1},{"aid":4,"iid":12,"value":27.5},{"aid":4,"iid":13,"value":20.5},{"aid":6,"iid":10,"value":0},{"aid":6,"iid":11,"value":1},{"aid":6,"iid":12,"value":26.0},{"aid":6,"iid":13,"value":20.0},{"aid":7,"iid":10,"value":0},{"aid":7,"iid":11,"value":1},{"aid":7,"iid":12,"value":26.5},{"aid":7,"iid":13,"value":20.5},{"aid":8,"iid":10,"value":0},{"aid":8,"iid":11,"value":1},{"aid":8,"iid":12,"value":26.5},{"aid":8,"iid":13,"value":20.5},{"aid":10,"iid":10,"value":0},{"aid":10,"iid":11,"value":1},{"aid":10,"iid":12,"value":27.0},{"aid":10,"iid":13,"value":20.5},]}')
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/Cellar/python@3.9/3.9.5/Frameworks/Python.framework/Versions/3.9/lib/python3.9/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/Cellar/python@3.9/3.9.5/Frameworks/Python.framework/Versions/3.9/lib/python3.9/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/Cellar/python@3.9/3.9.5/Frameworks/Python.framework/Versions/3.9/lib/python3.9/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 879 (char 878)

As you can see there is no home assistant code, no homekit code. So even if it seeems to work for you, it is (and always has) returned data that we just can't parse. And have been failing to parse all along.

So the assessment is the same. It worked enough for you not to notice, but has been subtly broken all along, and now the errors that were happening all along are in your log.

Your device is and has always been returning JSON that is invalid. Ideally the vendor would fix it to return JSON like the spec says.

Do you know if the Netamo is a ceritified implementation?

Scialla commented 3 years ago

Jc2k, thank you very much for the explanation.

i don't know if is a certified implementation but i suppose yes

Netatmo have his official integration for HA but have a big lag because it goes through Netatmo Cloud; with homekit controller have only a little lag, i've ever used it in this mode

i will remove it from homekit controller and will use official integration.

Thanks again for your support

Jc2k commented 3 years ago

The reason I ask if its certified is, if Apple is tolerating mistakes like this then normally we would try to as well. I'd much rather you didn't have to go through the cloud. But this is such a doozy that I think i'd only consider it for a certified device, and i certainly wouldn't for a custom firmware (which doesn't seem to be the case here).

Have you ever used it with iOS? It would show a warning with iOS if it was uncertified. Thats the only way to be sure.

Even if it is certified and I do want to fix this, there might not be a good way to do it at the present time as we'd need a custom JSON parser that could tolerate trailing commas. I know they exist in the javascript world, but I don't know if there is a good one for python.

I'd also be very influenced by @bdraco's thoughts here.

bdraco commented 3 years ago

It looks like the device is probably certified based on the vendors website.

https://github.com/vaidik/commentjson might be a reasonable solution

Scialla commented 3 years ago

Yes, i've used it directly with homekit and iOS and no warning appear, it is certified.

Now, i've removed Netatmo Relay from homekit controller and resolved errors in log.

Jc2k commented 3 years ago

It looks like the device is probably certified based on the vendors website.

https://github.com/vaidik/commentjson might be a reasonable solution

The code looks like they've taken time to think about some Unicode edge cases and it is a proper parser rather than gaffa taping pre cleaning so might be worth a look. It is a shame to pull in 2+ extra libraries here, but I don't have any better ideas.

Jc2k commented 3 years ago

https://github.com/Jc2k/aiohomekit/pull/46 adapts our test harness to generate equally broken device JSON, then fixes it by switching to the package @bdraco suggested. Looks to work.

Scialla commented 3 years ago

thanks for your work

Jc2k commented 3 years ago

PR for HA here: https://github.com/home-assistant/core/pull/52759

Jc2k commented 3 years ago

For anyone tracking this issue but not the PR, unfortunately we've had to back this out of the next release for now. It looks like it's quite a bit slower.