Issue with pairing with Heatmiser Neohub about aiohomekit HOT 17 CLOSED

If you can confirm that iOS sends them in a different order then I would take a pull request for the first 2 diffs without a 2nd thought. I've recently updated the README to confirm as much. Our goal is to slowly get as close to accurate with what iOS sends as possible, and to be as tolerant of what we receive as possible. I'll need to think about the 3rd diff though. While I'm fine in principle as with the other 2 diffs, it feels band-aidy. I want to see if there is a better way to structure that bit of code in general. It's a bit hard to look at the diff on my phone without it being a PR - can't easily look at more of the function - so it might be a few days before I get to this.

from aiohomekit.

I landed your first 2 diffs as is in cec6b65.

In cc2534a i revamped quite a bit of the pairing and re-authenticating code. I made the current state completely optional everywhere, and removed any dependence on the order of the TLV structure.

I need to convince myself the header order does indeed match iOS, but otherwise i'm think we should be there with supporting your device at the aiohomekit level.

I need to throw some tests at it as well...

from aiohomekit.

Thanks John, I finally got around to test your patches. I cherry picked them on top of 0.2.51 locally and checked that with the patches I could successfully run a 'pair_ip' command. I also checked that it did not work without the patches.

I did also update my home assistant to 0.114.4 from 0.109.3 this week, and now it seems that even with the patches the pairing from homeassistant has stopped working - so I assume the homekit component of homeassistant must be using aiohomekit in a different way than before as well now?

I get this when I press configure for the device in the integration meny:

  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/components/homekit_controller/config_flow.py", line 277, in async_step_pair
    self.finish_pairing = await discovery.start_pairing(self.hkid)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/discovery.py", line 74, in start_pairing
    "/pair-setup", body=request, expected=expected,
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 345, in post_tlv
    target, TLV.encode_list(body), content_type=HttpContentTypes.TLV,
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 314, in post
    body=body,
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 401, in request
    resp = await self.protocol.send_bytes(request_bytes)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 87, in send_bytes
    return await asyncio.wait_for(result, 30)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 442, in wait_for
    return fut.result()

I haven't debugged it any further though. Do you have any idea on what change from homeassistant 0.109.3 could be triggering this?

from aiohomekit.

No I can't imagine anything has changed that much at all. It's not like i'm particularly active at all right now changing things willy nilly. I barely have time to reply to tickets like this in fact. Any patches I do make tend to be small and to fix something specific, not grand re-architecting. And there aren't many other contributors.

0.109.3 is from May. Looking through this:

https://github.com/home-assistant/core/commits/dev/homeassistant/components/homekit_controller

You have gone from aiohomekit 0.2.37 to 0.2.49 or something like that. The changes i made in HA were just to bump the version number or to precreate some device registry entries (that happens after where you are getting stuck). Some of the other changes were translations. The remaining work was on the pairing flow by a different dev, but I tested it against devices here so i know its not fundamentally broken. In fact in my testing it made things considerably less broken. It didn't used to handle errors from the device particularly well, and now its pretty good at it. I made some deliberately broken accessories to check out the edge cases. So if it is that its a device specific bug. And it wasn't a fundamental change to how aiohomekit is invoked either, it was really restructuring the HA code a bit to make sure the right UI is shown at the right time. It still invokes aiohomekit in exactly the same way.

The final change is related to discovery. If it is related to a change in HA then it's something to do with discovery. We now use a shared zeroconf instance as before HA was creating a lot of them and it was wasting CPU. But I can see from the traceback that you have got past the discovery part and it seems to instead be a timeout whilst trying to open the initial connection to the device. (start_pairing is where we open the first TCP connection and send the TLV packet to get the devices public key and put it into pairing mode). The most likely reason for that to fail with a timeout is if discovery was returning a wrong IP. This has happened before, when we looked at the discovery data we could see multiple IP addresses and 169.254 addresses were present in the discovery data.

You said pairing worked outside of HA, and indeed when you use the aiohomekit CLI directly you arent using the HA zeroconf shared instance.

To test this theory you could print the host and port it is connecting to. In fact, there is already a logger for that. Just make sure your HA has the aiohomekit logger set to debug.

As for changes in aiohomekit itself, we are looking at this set of commits:

0.2.37...0.2.49

There's nothing in there that jumps out in particular. We know your device already... stretches... the spec a bit. But the changes like 7d37d17 or 58c138b make it more like what iOS does and also more tolerant when a device returns something a bit different to the devices that do work. I would say trying to revert 01069fc first, and if that doesnt work try and revert 6a5eeb3.

Either way we should have a better idea if you can post home assistant debug logs with the aiohomekit logger turned on.

from aiohomekit.

I think I know what the issue is. I had a modified version (added your patches) of aiohomekit==0.2.51 installed, but now I can see that I have 0.2.46 - so it must be homeassistant that updates to this version automatically? I guess that explains why it didn't work since I haven't patched that install.

from aiohomekit.

I patched my installed aiohomekit==0.2.46 and I am able to pair through home assistant now.

After a while it does end up with this sort of error though - where I am not able to control sensors through home assistant:

  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/pairing.py", line 90, in _ensure_connected
    await asyncio.wait_for(self.connection.ensure_connection(), _timeout)
  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 "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/core.py", line 1324, in catch_exceptions
    await coro_or_task
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/core.py", line 1343, in _execute_service
    await handler.func(service_call)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity_component.py", line 209, in handle_service
    self._platforms.values(), func, call, required_features
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 454, in entity_service_call
    future.result()  # pop exception if have
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 583, in async_request_call
    await coro
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 485, in _handle_entity_call
    await result
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/components/climate/__init__.py", line 544, in async_service_temperature_set
    await entity.async_set_temperature(**kwargs)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/components/homekit_controller/climate.py", line 87, in async_set_temperature
    {CharacteristicsTypes.TEMPERATURE_TARGET: temp}
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/components/homekit_controller/__init__.py", line 98, in async_put_characteristics
    return await self._accessory.put_characteristics(payload)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/homeassistant/components/homekit_controller/connection.py", line 336, in put_characteristics
    results = await self.pairing.put_characteristics(characteristics)
  File "/home/ubuntu/homeassistant/lib/python3.7/site-packages/aiohomekit/controller/ip/pairing.py", line 253, in put_characteristics
    await self._ensure_connected()
  File "/home/ubuntu/homeassistant/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

When I restart home assistant it is able to connect again - but after a while this happens.

from aiohomekit.

Did it work before with your patched version on the older HA version, or is this the furthest you've got?

I'd be interested to know if reverting 01069fc helped.

from aiohomekit.

I did not have this problem with my patched version on homeassistant==0.114.4. I could try reverting that commit and check if it gets more stable.

from aiohomekit.

Please if you could. My hunch is that your device is timing out the TCP connection (which is fairly normal, some devices seem to have a maximum of about 3 days before they reset any open connection) and that commit might not quite handle your device.

from aiohomekit.

I did the revert yesterday and it has been running fine overnight. I'll continue monitoring it over the weekend.

from aiohomekit.

Still running without any problems encountered - so I would say there is a high probability that the commit 01069fc was the culprit to the problems I saw with the Neohub and HA.

from aiohomekit.

I have reverted it on main. I'll have a quick think this AM if there is another way to avoid the originally reported problem, otherwise i'll post a release as it stands.

I'll try to figure out whats safe to tush into 0.115.0 - will see if i can get a version bump backported so this regression doesn't get released in 0.115.0. Thanks so much for your help tracing this!

from aiohomekit.

Tag released with it reverted, and PR submitted to HA.

from aiohomekit.

@ronped PR was backported into release branch so should be in 0.115.0. Would be good if you could try with dev or beta 10 or later.

from aiohomekit.

Haven't heard anything on this for a while so going to close it and assume all is well.

from aiohomekit.

Sorry, haven't gotten around to updating my HA version yet (if it ain't broke don't fix it). But things have been running stable here since I reverted 01069fc in my local checkout.

from aiohomekit.

No worries, just realised I had some tickets lying around and thought it was time to clean house 🤪.

from aiohomekit.