Core: HomeKit Controller Issue 0.107.0

[geekofweek]

The problem

HomeKit Controller devices, specifically a Garage Door Opener no longer function with the changes in 0.107.0

At first was troubleshooting by un-pairing the device, but was unable to pair it again until I rolled back to 0.106.6. After pairing the device and upgrading back to 0.107.0 it no longer functions and shows the in-correct state (Open instead of Closed). I've since rolled back to the previous version and everything works as it did before.

Environment

• Home Assistant release with the issue: 0.107.0
• Last working Home Assistant release (if known): 0.106.6
• Operating environment (Hass.io/Docker/Windows/etc.): Docker
• Integration causing this issue: HomeKit Controller
• Link to integration documentation on our website:
  https://www.home-assistant.io/integrations/homekit_controller/
  

  Problem-relevant configuration.yaml

Traceback/Error logs

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 826, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 83, in data_received
    data = self.current_response.parse(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 101, in parse
    if self.is_read_completely():
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 127, in is_read_completely
    raise HttpException("Could not determine if HTTP data was read completely")
aiohomekit.exceptions.HttpException: Could not determine if HTTP data was read completely

Additional information

[probot-home-assistant[bot]]

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

[Jc2k]

What make of door opener is it?

[garyak]

I'm getting these errors also. I'm using HomeKit Controller to control two Lennox S30 thermostats.

2020-03-19 05:00:11 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error: protocol.data_received() call failed.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 826, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 184, in data_received
    super().data_received(decrypted)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 83, in data_received
    data = self.current_response.parse(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 101, in parse
    if self.is_read_completely():
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 127, in is_read_completely
    raise HttpException("Could not determine if HTTP data was read completely")
aiohomekit.exceptions.HttpException: Could not determine if HTTP data was read completely

This error is new for 107.0 and remains on 107.1

[Jc2k]

Sorry for the regression everyone. This is because of a switch to a purely async homekit library. It enables push state changes and to avoid the synch thread pool in home assistant. It has been working well for everyone who tested the beta, so sad that your devices work differently enough for it to fail. I'd like to get this sorted quickly and take steps to stop it happening again. With your help I'd like to try and capture enough information here to add a regression test for this case. Now that the change is in place we should need any more "big bang" disruptive changes either - we are on a good stable long term footing now.

So it's working for a bunch of other accessories - despite success being under-reported i still know of more devices where its working than devices where it isnt. So there must be a difference in how HTTP is sending data to us on these devices. Previously the HTTP parsing only had to contend with simple RPC style stuff (send HTTP request, parse HTTP result) and in 0.107.0 it has to contend with spontaneous unexpected push events from the device (which are tagged 'EVENT/1.0' instead of 'HTTP/1.1'), which makes it harder to reuse existing HTTP libraries. My guess is your devices are doing something ever so slightly different at this layer and its throwing the code out of whack.

Looking at the code my fear is if its that your device is not sending a content-length. The other option is that its sending the response over multiple packets and we are not quite handling that properly.

I'd like one of you to instrument the parsing if possible. Replace your /usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py with this. If its easier to modify it in place, the most important lines are 2, 7 and 29. You'll need to turn on debug logging for aiohomekit too:

logger:
  default: info
  logs:
    aiohomekit: debug

If you can't edit it in place (I think HA OS makes it harder to edit stuff) then we'll have to install homekit_controller as a custom component and modify it there, but thats a mini essay to explain.

[garyak]

I'm willing to give it a shot. NUC/Ubuntu/Docker CE/Portainer. I saved your revised response.py in the /config directory using samba. I have a terminal window open as root in Portainer. Just need instruction on how to save the original and move the new file into place.

[Jc2k]

@garyak it looks like you are on discord - might be a bit chatty so shall we continue there? I am Jc2k#6068 there.

[geekofweek]

@Jc2k It's an Insignia NS-CH1XGO8. Works pretty well with HA HomeKit being all local, I'm actually replacing it soon with a ESPHome setup.

Willing to try out the modified response.py file, will just need to find some time today.

[geekofweek]

What specifically are you looking for in testing the response.py file? Just catching the error log output or if it resolves it?

[Jc2k]

@geekofweek it adds extra logging so that i can see the state of a parser state machine as bytes arrive on the network. if its the same as @garyak we were seeing some HTTP auth errors. There are 2 files to test:

• https://gist.github.com/Jc2k/c89e30fdc112b2329b12609bff8a9e07/f996483fa184787c47e277e48ad5b72c08177f45 - this will let us verify if you are seeing the 470 error as well. please start with this. if you see:

HTTP/1.1 470 Connection Authorization Required\r\n\r\n

then we are likely talking about the same bug.

• https://gist.github.com/Jc2k/c89e30fdc112b2329b12609bff8a9e07/6f71e39b10588e559fb4d8f2447efaab2ea8ad6f - this fixes the parsing error but doesn't fix the underlying cause of the 470. try this 2nd and look for any errors in your log. Does everything work as expected?

I am still chasing the state it gets in to trigger a 470...

[geekofweek]

First test, I seem to get a 404 and not noticing a 407:

2020-03-19 09:53:54 DEBUG (MainThread) [aiohomekit.http.response] parse: b'HTTP/1.1 404 Not Found\r\nContent-Type: text/html\r\n\r\n<!doctype html>\n<html><head><title>404 - Page not found</title></head><body>\n<h1>Page not found.</h1>\n<p><a href="/">Return to home page</a></p>\n</body>\n</html>\n'
2020-03-19 09:53:54 DEBUG (MainThread) [aiohomekit.http.response] parse: headers: [('Content-Type', 'text/html')]
2020-03-19 09:53:54 DEBUG (MainThread) [aiohomekit.http.response] parse: body: bytearray(b'')
2020-03-19 09:53:54 DEBUG (MainThread) [aiohomekit.http.response] parse: left: bytearray(b'<!doctype html>\n<html><head><title>404 - Page not found</title></head><body>\n<h1>Page not found.</h1>\n<p><a href="/">Return to home page</a></p>\n</body>\n</html>\n')
2020-03-19 09:53:54 DEBUG (MainThread) [aiohomekit.http.response] is_read_completely: False 404 -1 2
2020-03-19 09:53:54 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error: protocol.data_received() call failed.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 826, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 83, in data_received
    data = self.current_response.parse(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 93, in parse
    if self.is_read_completely():
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 120, in is_read_completely
    raise HttpException("Could not determine if HTTP data was read completely")

Second test, still seems to be a 404 error:

2020-03-19 09:59:35 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to 192.168.101.78:80
2020-03-19 09:59:35 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x01
  3: (32 bytes/<class 'bytes'>) b'\xd1\x83!\x88\xde\xa4\xc5\xc4\xa8\xedC\x07\x95g7PQ\n\x11%\xba\x8a8\xc8\x1d\xda7\x17\xdb\xad\x8fB'
]

2020-03-19 09:59:35 DEBUG (MainThread) [aiohomekit.http.response] Bytes left in buffer after parsing packet: bytearray(b'<!doctype html>\n<html><head><title>404 - Page not found</title></head><body>\n<h1>Page not found.</h1>\n<p><a href="/">Return to home page</a></p>\n</body>\n</html>\n')
2020-03-19 09:59:35 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
]

2020-03-19 09:59:35 ERROR (MainThread) [aiohomekit.controller.ip.connection] Unexpected error whilst trying to connect to accessory. Will retry.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 443, in _reconnect
    return await self._connect_once()
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 517, in _connect_once
    request, expected = state_machine.send(response)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/protocol/__init__.py", line 380, in get_session_keys
    response_tlv[0][0] == TLV.kTLVType_State and response_tlv[0][1] == TLV.M2
IndexError: list index out of range

[Jc2k]

Eep. First error is weird. It shouldn't return 404's, its not like its a RESTful API and the endpoints vary and we could screw that up. The endpoints are all static. It's like the device isn't ready yet or we somehow ended up talking to the wrong port or even wrong device.

First of all, switch to the second version of the file if you haven't already. Secondly the gist now includes a connection.py. Can you place it at aiohomekit/controller/ip/connection.py and see if that changes things? It will close the connection if the accessory 404's and retry a bit later. (Currently it leaves the HTML from the 404 in the parsing buffer which is obviously problematic).

[geekofweek]

Tested, the device it is attempting to connect is correct. I validated the IP address is correct.

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv req /pair-verify [(6, bytearray(b'\x01')), (3, b'\x88\xffb\xbfM\xd9d[\xe9U\x90P\xa3\x12\xe0\xd5\xd5\xb5S\xfd\xf5k(\x8e:\xcd8\x0fKaR2')]
2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x01
  3: (32 bytes/<class 'bytes'>) b'\x88\xffb\xbfM\xd9d[\xe9U\x90P\xa3\x12\xe0\xd5\xd5\xb5S\xfd\xf5k(\x8e:\xcd8\x0fKaR2'
]

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw req: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.101.78\r\nContent-Type: application/pairing+tlv8\r\nContent-Length: 37\r\n\r\n\x06\x01\x01\x03 \x88\xffb\xbfM\xd9d[\xe9U\x90P\xa3\x12\xe0\xd5\xd5\xb5S\xfd\xf5k(\x8e:\xcd8\x0fKaR2'
2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw resp: bytearray(b"\x06\x01\x02\x03 q\xb0\xbd\xab\'\xadMz\xce\x80\xe3\':\xf5d\x12[S\n$\x10\xf3\xaaX\xf1\xf0p\xda8h\x81=\x05e\x1f\xe35\xfb\xa5\xee~=\xb1A\x1e6\x1e\x8c\xb1\xff\xbc\x10\xfe(\x9a\xf6a\x80i\x16\xa2\xbd\xce\x8e\xba&/\xccIO`\xca\x08\xb3\x07?\x82\x10\xde\xf7\x84\xf0\t\x98\xce\x8d\xee\x19\x17-\x10\x90\xa4_\x1b<\r\xfa\x03\x07^\xac\xb1%\xd0\xc8\x11]\xbb\xc2\xc3#\xa9O\xcet\x91\x8f\xc1\x87\xbf\x8f]\xa4\xf5[C\x8c\\\xbf\x1b\xee\x9e\x91\xde")
2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x02
  3: (32 bytes/<class 'bytearray'>) 0x71b0bdab27ad4d7ace80e3273af564125b530a2410f3aa58f1f070da3868813d
  5: (101 bytes/<class 'bytearray'>) 0x1fe335fba5ee7e3db1411e361e8cb1ffbc10fe289af661806916a2bdce8eba262fcc494f60ca08b3073f8210def784f00998ce8dee19172d1090a45f1b3c0dfa03075eacb125d0c8115dbbc2c323a94fce74918fc187bf8f5da4f55b438c5cbf1bee9e91de
]

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv resp: [[6, bytearray(b'\x02')], [3, bytearray(b"q\xb0\xbd\xab\'\xadMz\xce\x80\xe3\':\xf5d\x12[S\n$\x10\xf3\xaaX\xf1\xf0p\xda8h\x81=")], [5, bytearray(b'\x1f\xe35\xfb\xa5\xee~=\xb1A\x1e6\x1e\x8c\xb1\xff\xbc\x10\xfe(\x9a\xf6a\x80i\x16\xa2\xbd\xce\x8e\xba&/\xccIO`\xca\x08\xb3\x07?\x82\x10\xde\xf7\x84\xf0\t\x98\xce\x8d\xee\x19\x17-\x10\x90\xa4_\x1b<\r\xfa\x03\x07^\xac\xb1%\xd0\xc8\x11]\xbb\xc2\xc3#\xa9O\xcet\x91\x8f\xc1\x87\xbf\x8f]\xa4\xf5[C\x8c\\\xbf\x1b\xee\x9e\x91\xde')]]
2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1: (17 bytes/<class 'bytearray'>) 0x43443a46423a34333a38453a42383a3745
  10: (64 bytes/<class 'bytearray'>) 0x9e7367fb72d8eef90c60ada79b314e369de82a70ae419ba73bcef67c5cbb5b0c6b062f463936d9fb2c2d0d4cc3a5fa2d0cdd04ce2715c2aed55dcc03b8587506
]

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1: (36 bytes/<class 'bytes'>) b'8fb07d3b-0311-45de-b96c-6484e181f3bf'
  10: (64 bytes/<class 'bytes'>) b"\x19\x05\xd0\x8e\xdd\xacTu\xaa\xf2\xead\x1d\xbc@\x94UK\xee\xc4\x080\xad\x11\xafm1\xaeu\xd6\x1f\xca\x17\x0f\xc9>w\xe6i\x9f0wj\x1b\xb8rWlu\x90\xc9\xa2'\xe3\xf8\xa3a=B\xb1\xbdt\x7f\x0e"
]

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv req /pair-verify [(6, bytearray(b'\x03')), (5, b'\x18o\xd1\xb0&\xf5\xc4\x89Q<\xa6+\xfa\xbb\x86\xb6\xa1g\xbe_\x9271\x0e\xf9\t/%\x8e"\xb1: \xfa\xe0\xdb\x80\x0e dy\x90hp\x06\xc6\xc3\xdf\x80\x11\xeb\xe7n\xc3\xba\xd4\x91\x04~\xb1eA\xa7\x89\xe1\xe0\xf8\xfdF+\xfb\x7fb\x14\xef2\x07*\xe6Dn\x94\xf5\xbf\xc3x\x1c2\xfa\x08\xe2\x01\x8dB`/K\xca \x1e\xa4~\x11i\xe4\xa3:\xc4OcfY\xb6\xe0\x07g\xd9\xb3;\xde')]
2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x03
  5: (120 bytes/<class 'bytes'>) b'\x18o\xd1\xb0&\xf5\xc4\x89Q<\xa6+\xfa\xbb\x86\xb6\xa1g\xbe_\x9271\x0e\xf9\t/%\x8e"\xb1: \xfa\xe0\xdb\x80\x0e dy\x90hp\x06\xc6\xc3\xdf\x80\x11\xeb\xe7n\xc3\xba\xd4\x91\x04~\xb1eA\xa7\x89\xe1\xe0\xf8\xfdF+\xfb\x7fb\x14\xef2\x07*\xe6Dn\x94\xf5\xbf\xc3x\x1c2\xfa\x08\xe2\x01\x8dB`/K\xca \x1e\xa4~\x11i\xe4\xa3:\xc4OcfY\xb6\xe0\x07g\xd9\xb3;\xde'
]

2020-03-19 10:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw req: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.101.78\r\nContent-Type: application/pairing+tlv8\r\nContent-Length: 125\r\n\r\n\x06\x01\x03\x05x\x18o\xd1\xb0&\xf5\xc4\x89Q<\xa6+\xfa\xbb\x86\xb6\xa1g\xbe_\x9271\x0e\xf9\t/%\x8e"\xb1: \xfa\xe0\xdb\x80\x0e dy\x90hp\x06\xc6\xc3\xdf\x80\x11\xeb\xe7n\xc3\xba\xd4\x91\x04~\xb1eA\xa7\x89\xe1\xe0\xf8\xfdF+\xfb\x7fb\x14\xef2\x07*\xe6Dn\x94\xf5\xbf\xc3x\x1c2\xfa\x08\xe2\x01\x8dB`/K\xca \x1e\xa4~\x11i\xe4\xa3:\xc4OcfY\xb6\xe0\x07g\xd9\xb3;\xde'

It appears to try again but still fails:

2020-03-19 10:32:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.101.78', port=80) lost.
2020-03-19 10:32:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw resp: bytearray(b'\x06\x01\x04')
2020-03-19 10:32:05 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x04
]

2020-03-19 10:32:05 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv resp: [[6, bytearray(b'\x04')]]
2020-03-19 10:32:05 ERROR (MainThread) [aiohomekit.controller.ip.connection] Unexpected error whilst trying to connect to accessory. Will retry.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 444, in _reconnect
    await self._connect_once()
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 522, in _connect_once
    self.transport.set_protocol(self.protocol)
AttributeError: 'NoneType' object has no attribute 'set_protocol'
2020-03-19 10:32:11 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv req /pair-verify [(6, bytearray(b'\x01')), (3, b'^/It =\x9bFO\xbc\x80\xae\xc66\x9c-\x00\x95r?<\xc4\xe9RV@8\xec\xbb08\t')]
2020-03-19 10:32:11 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x01
  3: (32 bytes/<class 'bytes'>) b'^/It =\x9bFO\xbc\x80\xae\xc66\x9c-\x00\x95r?<\xc4\xe9RV@8\xec\xbb08\t'
]

2020-03-19 10:32:11 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw req: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.101.78\r\nContent-Type: application/pairing+tlv8\r\nContent-Length: 37\r\n\r\n\x06\x01\x01\x03 ^/It =\x9bFO\xbc\x80\xae\xc66\x9c-\x00\x95r?<\xc4\xe9RV@8\xec\xbb08\t'
2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw resp: bytearray(b"\x06\x01\x02\x03 \x9f*\xa3\x83\x1e\xa34\x94\'\n\x04\xe5NaX\x0c|\x9b\x07\x08L&o5\x1d\x1b\xb3@$1\xa9\x1a\x05e\xcf\x1a \xff\x9fc\xc8\x98\x80\xaa\xaf\x81O\x97\xc4US\xfav\xac\x17\xc6\x14Kt\x93\xc2\x95P\x8fX\xb9\xb85\xad-\x81\x8a\x17\x99\x95\xd8\x941\xd1\xf8\xea\xd0\x97\t\xc4\x168\x19\x8c4\x86qv\xbd\r\xcc\x83tS\x12?\xa6%\xbf\x9fBC\x18\xd7M\xcf|\x0e\xcf&\xc4\xa38\xf3\x8f\x05\xe9N\xf0\xfe\xe9\xf8\xd4\xaf\xbc(\xa7\t\x88\xd2")
2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x02
  3: (32 bytes/<class 'bytearray'>) 0x9f2aa3831ea33494270a04e54e61580c7c9b07084c266f351d1bb3402431a91a
  5: (101 bytes/<class 'bytearray'>) 0xcf1a20ff9f63c89880aaaf814f97c45553fa76ac17c6144b7493c295508f58b9b835ad2d818a179995d89431d1f8ead09709c41638198c34867176bd0dcc837453123fa625bf9f424318d74dcf7c0ecf26c4a338f38f05e94ef0fee9f8d4afbc28a70988d2
]

2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv resp: [[6, bytearray(b'\x02')], [3, bytearray(b"\x9f*\xa3\x83\x1e\xa34\x94\'\n\x04\xe5NaX\x0c|\x9b\x07\x08L&o5\x1d\x1b\xb3@$1\xa9\x1a")], [5, bytearray(b'\xcf\x1a \xff\x9fc\xc8\x98\x80\xaa\xaf\x81O\x97\xc4US\xfav\xac\x17\xc6\x14Kt\x93\xc2\x95P\x8fX\xb9\xb85\xad-\x81\x8a\x17\x99\x95\xd8\x941\xd1\xf8\xea\xd0\x97\t\xc4\x168\x19\x8c4\x86qv\xbd\r\xcc\x83tS\x12?\xa6%\xbf\x9fBC\x18\xd7M\xcf|\x0e\xcf&\xc4\xa38\xf3\x8f\x05\xe9N\xf0\xfe\xe9\xf8\xd4\xaf\xbc(\xa7\t\x88\xd2')]]
2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1: (17 bytes/<class 'bytearray'>) 0x43443a46423a34333a38453a42383a3745
  10: (64 bytes/<class 'bytearray'>) 0x49128e28b46690308baf7251bc8ef251dbe4f7ba754367604eca5d12fcccb614982933f1895e0f8aea875df7176cd48179596a9931edc8e741fbaed56c634f00
]

2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1: (36 bytes/<class 'bytes'>) b'8fb07d3b-0311-45de-b96c-6484e181f3bf'
  10: (64 bytes/<class 'bytes'>) b"\xae\x97@\xea\r\xbe'\xdc\x19\x100\xb5\x97G\xd7e\xf4S\xca\xa34\xf1\xeb1\xb7\r\xfcj'K\x12\xea \xafJ\t\x02\x82\xf7a\x17H\x15\xba\xbf\xef\xa6\x8e\x18\x03\xb6I>\x0e\xae\x1f\xc0\xadsh\x91!\x95\x04"
]

2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.controller.ip.connection] post_tlv req /pair-verify [(6, bytearray(b'\x03')), (5, b'x\xb5r\x89\xbc\xaeF\xd6\x11\xf0e\xf6\xb8\xf4\xe2\x8b\xff\xfd\xfe\xd0\xa3\xfb5/\xbd\xbc_\xf4L\xb5\xa0\xf8wm\x0e\x15\xb2p\xae\x96+)\xcd\x8a\x8bX\xd3-\x19\xff\x9b\xfe\x89\x0b\xb9\xfd\xaa\x8c\x02\x94E)e\x9a\xb1g\xe4\x11\xbe\xf8zzt\x01M<\x80Aj+X\x1d\x80\xc0\x94\xff\xaay\x8a"`VU]nW\x8cnx\xbc\xa5.\xf6Q\xdd\x14M\xf1?\xb2\xbe\xf5\xc3d\xc6\x05\x17+c\x1d')]
2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x03
  5: (120 bytes/<class 'bytes'>) b'x\xb5r\x89\xbc\xaeF\xd6\x11\xf0e\xf6\xb8\xf4\xe2\x8b\xff\xfd\xfe\xd0\xa3\xfb5/\xbd\xbc_\xf4L\xb5\xa0\xf8wm\x0e\x15\xb2p\xae\x96+)\xcd\x8a\x8bX\xd3-\x19\xff\x9b\xfe\x89\x0b\xb9\xfd\xaa\x8c\x02\x94E)e\x9a\xb1g\xe4\x11\xbe\xf8zzt\x01M<\x80Aj+X\x1d\x80\xc0\x94\xff\xaay\x8a"`VU]nW\x8cnx\xbc\xa5.\xf6Q\xdd\x14M\xf1?\xb2\xbe\xf5\xc3d\xc6\x05\x17+c\x1d'
]

2020-03-19 10:32:12 DEBUG (MainThread) [aiohomekit.controller.ip.connection] raw req: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.101.78\r\nContent-Type: application/pairing+tlv8\r\nContent-Length: 125\r\n\r\n\x06\x01\x03\x05xx\xb5r\x89\xbc\xaeF\xd6\x11\xf0e\xf6\xb8\xf4\xe2\x8b\xff\xfd\xfe\xd0\xa3\xfb5/\xbd\xbc_\xf4L\xb5\xa0\xf8wm\x0e\x15\xb2p\xae\x96+)\xcd\x8a\x8bX\xd3-\x19\xff\x9b\xfe\x89\x0b\xb9\xfd\xaa\x8c\x02\x94E)e\x9a\xb1g\xe4\x11\xbe\xf8zzt\x01M<\x80Aj+X\x1d\x80\xc0\x94\xff\xaay\x8a"`VU]nW\x8cnx\xbc\xa5.\xf6Q\xdd\x14M\xf1?\xb2\xbe\xf5\xc3d\xc6\x05\x17+c\x1d'
2020-03-19 10:32:13 ERROR (MainThread) [aiohomekit.controller.ip.connection] Unexpected error whilst trying to connect to accessory. Will retry.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 444, in _reconnect
    await self._connect_once()
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 512, in _connect_once
    "/pair-verify", body=request, expected=expected,
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 336, in post_tlv
    target, TLV.encode_list(body), content_type=HttpContentTypes.TLV,
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 300, in post
    body=body,
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 384, in request
    resp = await self.protocol.send_bytes(request_bytes)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 72, in send_bytes
    return await asyncio.wait_for(result, 10)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 435, in wait_for
    await waiter

[Jc2k]

Can you change that line 72 in connection.py and bump it from 10 to 30?

E.g

return await asyncio.wait_for(result, 30)

[Jc2k]

Actually, try with this https://gist.githubusercontent.com/Jc2k/c89e30fdc112b2329b12609bff8a9e07/raw/8c40335b6726d0a66a4e117887bedc272bc353d3/connection.py - realised the previous copy was from an old checkout.

[geekofweek]

Same issue, 404 then timeout while trying to connect:

2020-03-19 12:10:38 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Got HTTP error 404 for POST against /pair-verify
2020-03-19 12:10:38 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connecting to accessory failed. Retrying in 12 seconds

  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/pairing.py", line 90, in _ensure_connected
    await asyncio.wait_for(self.connection.ensure_connection(), 10)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1257, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 198, in handle_service
    self._platforms.values(), func, call, required_features
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 402, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 599, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 433, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/cover.py", line 109, in async_close_cover
    await self.set_door_state(STATE_CLOSED)
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/cover.py", line 114, in set_door_state
    {CharacteristicsTypes.DOOR_STATE_TARGET: TARGET_GARAGE_STATE_MAP[state]}
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/__init__.py", line 98, in async_put_characteristics
    return await self._accessory.put_characteristics(payload)
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 342, in put_characteristics
    results = await self.pairing.put_characteristics(characteristics)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/pairing.py", line 246, in put_characteristics
    await self._ensure_connected()
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/pairing.py", line 93, in _ensure_connected
    "Timeout while waiting for connection to device"
aiohomekit.exceptions.AccessoryDisconnectedError: Timeout while waiting for connection to device

[Jc2k]

Can you try the latest connection.py from here. This fixed it for another garage door user.

[geekofweek]

Different issue, it can't connect or find the device at all:

2020-03-19 12:24:52 WARNING (MainThread) [homeassistant.helpers.service] Unable to find referenced entities cover.garage_door

[Jc2k]

Sorry, fat finger try this.

[eugr]

@geekofweek - I have the same garage door opener (Insignia) and we just found out the reason. Works great now. The latest gist from @Jc2k should solve this for you.

[geekofweek]

@Jc2k that version seems to have done the trick

[geekofweek]

@eugr you ever have issues with yours? Mine works great until the door sensor decides the battery doesn't have enough juice every few months. Friend of mine used an ESPHome setup I'm going to try out. No battery on the door sensor. It gets cold in the midwest and those batteries tend to fail then. I'd say it's 98% reliable, that last 2% I want to close out.

[eugr]

@geekofweek - none so far, but I bought it in late October, so the battery is still going strong. I'm in SoCal though so it doesn't get that cold here :) I also have MyQ as a backup, but I don't like it, it's not as reliable and requires a cloud connection. My only gripe with Insignia when using via HA was the delay in the status updates, but thanks to Jc2k it's a thing of the past now :)

[geekofweek]

@eugr I also came off the MyQ, it was great until it just decided it had enough that day randomly. So this is my second attempt. I've had the Insignia probably about year, only gripe is the door sensor battery which wouldn't be as bad of a problem without the severe cold. Just curious since I haven't talked to anyone else that has the same device.

[eugr]

@geekofweek - it's seriously underrated. I got it on sale for $35 and it's great little device. I also like that it just plugs into the ceiling outlet and stays there, no drilling required. The beeps are also better than MyQ - that one keeps beeping for some time after the door is closed already which also was driving me crazy.

One option to battle the battery issue would be to wire it to external DC power source, but cable management could be a challenge...