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
74.07k stars 31.09k forks source link

Invalid Lennox E30 pairing flow via HomeKit controller #20885

Closed jeromelaban closed 4 years ago

jeromelaban commented 5 years ago

Home Assistant release with the issue:

0.87.0

Last working Home Assistant release (if known): None

Operating environment (Hass.io/Docker/Windows/etc.): Docker

Component/platform:

Homekit controller

Description of problem: Here's the "normal" flow for pairing a Lennox E30 to home kit:

Pairing a Lennox E30 with home-assistant using the HomeKit Controler does not work properly, for two reasons:

Tracking down the issue in homekit_python, I could create a manual pairing by adding:

    pin = input("PIN: ")

at this line: https://github.com/jlusiardi/homekit_python/blob/9604d76131a9955c8b4dbd9f10dc92394cc61ae3/homekit/protocol/__init__.py#L102

and run it as CLI:

python3 pair.py -d XX:XX:XX:XX:XX:XX -f pairing.json -a "LennoxE30" -p 123456

Blocking the pairing procedure to input the pin at the precise moment (after step 3, the verify request) during the negotiation makes the pairing code appear and stay visible long enough on the Lennox E30 screen to be able to input it at the CLI.

I've yet to be able to reuse the pairing file in home-assistant, and I'm not sure either how to create such an asynchronous flow using the HA UI.

Update 2019-02-09: I was able to reuse in HA the pairing I made using my modified CLI of homekit_python. The name of the pairing has to be the device ID XX:XX:XX:XX:XX:XX (AccessoryPairingID value in the pairing file). I'm only able to see the temperature, modes are not available and setting the temperature does not seem to have any actual effect.

Jc2k commented 5 years ago

Hi - thanks for raising this. Good work :-) You'll be pleased to know that I think most of this is known and being worked on but there isn't an ETA yet.

The pairing bug is already tracked here. There is a branch with a very similar hack here and the upstream bug for async pairing is here.

There is already a bug for C# (https://github.com/home-assistant/home-assistant/issues/17853). I haven't commented yet but my local branch should no longer choke on that.

The main work right now is to port homekit_controller from Configurator to ConfigEntries. It's quite a large change so it's probably going to have to be split up and sent through the HA review process in stages.

Are there any errors when setting the temperature etc?

If you can send me the output of:

python3 get_accessories.py -f pairing.json -a "LennoxE30" -o json

That would be super helpful.

jeromelaban commented 5 years ago

My pleasure! Good work on this component!

When setting the temperature from HA, there are no errors in the log, the thermostat value does not change, and the value in HA is reset to the actual thermostat value after a while.

Which logger should I enable to see the errors, if any ?

Here's the accessories result:

[
    {
        "aid": 1,
        "services": [
            {
                "characteristics": [
                    {
                        "format": "bool",
                        "iid": 2,
                        "perms": [
                            "pw"
                        ],
                        "type": "14"
                    },
                    {
                        "format": "string",
                        "iid": 3,
                        "perms": [
                            "pr"
                        ],
                        "type": "20",
                        "value": "Lennox"
                    },
                    {
                        "format": "string",
                        "iid": 4,
                        "perms": [
                            "pr"
                        ],
                        "type": "21",
                        "value": "E30 2B"
                    },
                    {
                        "format": "string",
                        "iid": 5,
                        "perms": [
                            "pr"
                        ],
                        "type": "23",
                        "value": "Lennox"
                    },
                    {
                        "format": "string",
                        "iid": 6,
                        "perms": [
                            "pr"
                        ],
                        "type": "30",
                        "value": "XXXXXXXX"
                    },
                    {
                        "format": "string",
                        "iid": 7,
                        "perms": [
                            "pr"
                        ],
                        "type": "52",
                        "value": "3.40.XX"
                    },
                    {
                        "format": "string",
                        "iid": 8,
                        "perms": [
                            "pr"
                        ],
                        "type": "53",
                        "value": "3.0.XX"
                    }
                ],
                "iid": 1,
                "type": "3E"
            },
            {
                "characteristics": [
                    {
                        "format": "uint8",
                        "iid": 101,
                        "maxValue": 2,
                        "minStep": 1,
                        "minValue": 0,
                        "perms": [
                            "pr",
                            "ev"
                        ],
                        "type": "F",
                        "value": 1
                    },
                    {
                        "format": "uint8",
                        "iid": 102,
                        "maxValue": 3,
                        "minStep": 1,
                        "minValue": 0,
                        "perms": [
                            "pr",
                            "pw",
                            "ev"
                        ],
                        "type": "33",
                        "value": 3
                    },
                    {
                        "format": "float",
                        "iid": 103,
                        "maxValue": 100,
                        "minStep": 0.1,
                        "minValue": 0,
                        "perms": [
                            "pr",
                            "ev"
                        ],
                        "type": "11",
                        "unit": "celsius",
                        "value": 20.5
                    },
                    {
                        "format": "float",
                        "iid": 104,
                        "maxValue": 32,
                        "minStep": 0.5,
                        "minValue": 4.5,
                        "perms": [
                            "pr",
                            "pw",
                            "ev"
                        ],
                        "type": "35",
                        "unit": "celsius",
                        "value": 21
                    },
                    {
                        "format": "uint8",
                        "iid": 105,
                        "maxValue": 1,
                        "minStep": 1,
                        "minValue": 0,
                        "perms": [
                            "pr",
                            "pw",
                            "ev"
                        ],
                        "type": "36",
                        "value": 0
                    },
                    {
                        "format": "float",
                        "iid": 106,
                        "maxValue": 37,
                        "minStep": 0.5,
                        "minValue": 16,
                        "perms": [
                            "pr",
                            "pw",
                            "ev"
                        ],
                        "type": "D",
                        "unit": "celsius",
                        "value": 29.5
                    },
                    {
                        "format": "float",
                        "iid": 107,
                        "maxValue": 100,
                        "minStep": 1,
                        "minValue": 0,
                        "perms": [
                            "pr",
                            "ev"
                        ],
                        "type": "10",
                        "unit": "percentage",
                        "value": 34
                    },
                    {
                        "format": "float",
                        "iid": 108,
                        "maxValue": 32,
                        "minStep": 0.5,
                        "minValue": 4.5,
                        "perms": [
                            "pr",
                            "pw",
                            "ev"
                        ],
                        "type": "12",
                        "unit": "celsius",
                        "value": 21
                    }
                ],
                "iid": 100,
                "primary": true,
                "type": "4A"
            }
        ]
    }
]
Jc2k commented 5 years ago

My gut feeling is that if you don't see any tracebacks in the logs with the default config then its probably the accessory rejecting the change, and we aren't logging it. If you are comfortable editing the code then track down this line of code in your environment and print the output:

https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/components/homekit_controller/__init__.py#L315

jeromelaban commented 5 years ago

I added this:

        res = self._accessory.pairing.put_characteristics(chars)
        _LOGGER.info("put_characteristics  %s", res)

which said this:

2019-02-14 01:30:30 INFO (SyncWorker_19) [homeassistant.components.homekit_controller] put_characteristics  {}

Which could mean this, if I'm not mistaken: https://github.com/jlusiardi/homekit_python/blob/88b40a9a64a1a897f3751c07c48e117472b92d3a/homekit/controller.py#L458

I'll put some logs deeper to see what happens.

jeromelaban commented 5 years ago

Also interesting, if I do this: 

python3 homekit/put_characteristic.py -f pairing.json -a "XX:XX:XX:XX:XX:X" -c 1.108 22

the temperature changes properly on the thermostat.

Jc2k commented 5 years ago

Ok, gut feeling one disproved. Dang. You are correct, it looks like there are no errors. I guess we should also log the value of chars right before we call put_characteristics too and make sure its trying to write to the correct characteristic.

GaryOkie commented 5 years ago

Have an Lennox iComfort S30 which currently lacks any HA integration, and am just commenting here to track progress with Homekit integration. Thanks very much for all the work done on this so far!

garyak commented 5 years ago

I have two S30s, one controls four zones, the other just one. Wanted interested parties to know I'd be happy to test any Home Assistant / Homekit integration work involving these thermostats.

niemyjski commented 5 years ago

I'm getting a similar error when I try to pair my Hunter Douglas PowerView Hub via HomeKit controller in 0.91.

Thu Apr 04 2019 09:34:01 GMT-0500 (CDT)

step 3
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 122, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1138, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1160, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/configurator/__init__.py", line 221, in async_handle_service_call
    call.data.get(ATTR_FIELDS, {}))
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/homekit_controller/connection.py", line 127, in device_config_callback
    self.controller.perform_pairing(self.hkid, self.hkid, code)
  File "/usr/local/lib/python3.7/site-packages/homekit/controller/controller.py", line 337, in perform_pairing
    pairing = perform_pair_setup(pin, str(uuid.uuid4()), write_fun)
  File "/usr/local/lib/python3.7/site-packages/homekit/protocol/__init__.py", line 132, in perform_pair_setup
    error_handler(response_tlv[1][1], 'step 3')
  File "/usr/local/lib/python3.7/site-packages/homekit/protocol/__init__.py", line 53, in error_handler
    raise BusyError(stage)
homekit.exceptions.BusyError: step 3
Jc2k commented 5 years ago

@niemyjski - a BusyError means an "existing pairing is ongoing" and is on its own unrelated to the issues in this ticket. Is the PowerView Hub a device with a screen and a pin code that changes like the Lennox E30?

niemyjski commented 5 years ago

I did not have an existing pairing but I'm going to go and reboot the hub and try again.

Jc2k commented 5 years ago

I meant the device thinks you were already trying to pair it, then started to pair it a second time. Which is subtly different to it already being paired.

Jc2k commented 5 years ago

For those of you who have paired manually (like @jeromelaban), 0.93 should fix a bunch more issues that were mentioned on this ticket. This includes correctly populating operation_list, support for thermostats that have humidity and target humidity features, support for auto and more.

(@jeromelaban i would appreciate an update on how this looks on your end).

The main config flow work is now on dev so should be in 0.94. If you have paired manually the pairing will be migrated over to a config entry and your device will start showing up on the Integrations screen. This doesn't fix the underlying pairing issue but was the big change blocking me from working on pairing.

There are some other changes pending:

GaryOkie commented 5 years ago

@jc2k,

I really appreciate you updating us on the progress! I've been following the PR, but have held off attempting a manual sync. Sure hope the Lennox S30 isn't one to have "device specific quirks" and will pair successfully with the .94 update.

Jc2k commented 5 years ago

The first 0.94 beta has just been tagged while i was asleep (about 8 hours ago). This includes:

This is still beta so there is still time to fix any surprise gotchas. This is obviously quite a big set of changes so if anyone can run the beta and let me know how they get on please do.

Jc2k commented 5 years ago

0.94 is out now - so would be great if you guys could let me know if you could now pair your Lennox E30's.

GaryOkie commented 5 years ago

I certainly plan to! My E-30 is installed at my lake house, so I hope to get up there soon. Area flooding/road access is a bit of mess right now.

EDIT: I meant my S30. Same thing really from the interface perspective.

garyak commented 5 years ago

Are S30's included? If so, I can test when I return home.

Jc2k commented 5 years ago

@garyak It depends! I don't have a ticket about S30 in particular, so I don't know why its not already working. If its just that the S30 has random pairing codes which it shows on a display, then you should test it with 0.94 as the issues around that should be fixed now.

GaryOkie commented 5 years ago

Yep - the Lennox iComfort S30/E30/M30 all have displays that upon pairing, display a random code.

There is another separate iComfort Wifi model with a different API that has its own component and doesn't require Homekit.

garyak commented 5 years ago

OK. I'll test the S30's and report the results.

jeromelaban commented 5 years ago

@Jc2k thanks for the update!

I tried the pairing (reset the E30 completely). it fails and this is what I'm getting:

,2019-06-10 20:35:33 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Pairing attempt failed with an unhandled exception
,Traceback (most recent call last):
,  File "/usr/src/app/homeassistant/components/homekit_controller/config_flow.py", line 259, in async_step_pair
,    pairing)
,  File "/usr/src/app/homeassistant/components/homekit_controller/config_flow.py", line 336, in _entry_from_accessory
,    pairing.list_accessories_and_characteristics
,  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
,    result = self.fn(*self.args, **self.kwargs)
,  File "/usr/local/lib/python3.7/site-packages/homekit/controller/ip_implementation.py", line 81, in list_accessories_and_characteristics
,    accessories = json.loads(tmp)['accessories']
,  File "/usr/local/lib/python3.7/json/__init__.py", line 348, in loads
,    return _default_decoder.decode(s)
,  File "/usr/local/lib/python3.7/json/decoder.py", line 337, in decode
,    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
,  File "/usr/local/lib/python3.7/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 1 (char 0)
,2019-06-10 20:35:33 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Pairing attempt failed with an unhandled exception
,Traceback (most recent call last):
,  File "/usr/src/app/homeassistant/components/homekit_controller/config_flow.py", line 288, in async_step_pair
,    start_pairing, self.hkid, self.hkid
,  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
,    result = self.fn(*self.args, **self.kwargs)
,  File "/usr/local/lib/python3.7/site-packages/homekit/controller/controller.py", line 370, in start_pairing
,    raise AlreadyPairedError('Alias "{a}" is already paired.'.format(a=alias))
,homekit.exceptions.AlreadyPairedError: Alias "XX:XX:XX:XX:XX:XX" is already paired.

Each new pairing attempt shows the homekit.exceptions.AlreadyPairedError with a new alias.

The E30 itself thinks it's paired, though, so the flow works properly from the devices standpoint.

Keep up the good work!

Jc2k commented 5 years ago

@jeromelaban can you take a copy of your .homekit directory, then delete it (or just move it to the side? Then reset the E30 and restart HA. What happens now? I suspect the old pairing.json is involved somehow.

jeromelaban commented 5 years ago

@Jc2k that's the first thing I tried, but it did not help, .homekit folder is not re-created either, which is also curious.

Jc2k commented 5 years ago

Yeah with config entries that folder is no more, woo.

So I’m guessing you attempted to pair twice (or at least submitted twice) and that’s where the AlreadyPairedError comes from. But why the first call to /accessories is failing is a bit of a mystery right now.

jeromelaban commented 5 years ago

Excellent news, I'll poke somewhere else then. The error message happened on the first try, and the ID changed every time. Where can I find those new entries ?

Also, I'll try to find out about that invalid document, will let you know.

GaryOkie commented 5 years ago

I finally made it up the the lakehouse and am now trying to pair the Lennox S30. I must be missing something since I never get a pairing code prompt in HA.

All I've added to the configuration is zeroconf: (I had discovery/enable/homekit initially per the docs, but the log said it wasn't needed). I enter WAC mode on the S30 and then at some point I should expect to see a prompt for code in the HA notifications?

I did try to manually add the Homekit Accessory Integration via the UI, but it said "aborted, no unpaired devices found" - and this was while the S30 was in WAC mode.

The HASSIO/Raspi is Ethernet connected, and on the same subnet as the S30, not on wifi, but there shouldn't be any network isolation between the two. Does this WAC mode pairing require Hassio be on wifi too?

Jc2k commented 5 years ago

@GaryOkie I can’t give specific instructions because every device is different - here I’m struggling a bit because I’ve never even heard of WAC mode before.

Home Assistant is looking for an mdns record of type _hap._tcp.local. If it can’t see that it won’t work. My HA is a VM with the host connected by Ethernet, and it can see WiFi homekit devices just fine. The only gotcha is if you have seperate subnets then mdns records are not visible across subnets without a reflector. But as you say this shouldn’t be a problem for you.

Can you run python3 -m homekit.discover on the machine or container where hass is?

Do you have a iPhone and can that see your device?

Is it definitely pingable from the hass machine?

GaryOkie commented 5 years ago

Thanks @jc2k for the assist! Wifi Accessory Configuration (WAC) creates an open wifi connection that you connect to temporarily to set up the connection. In the Lennox WAC mode, it is expecting an iOS device to connect. @jeromelaban decribes the normal pairing process perfectly in his OP. So the Ecobee does things differently for Homekit pairing?

Yes, I can ping the S30 from hassio. I can see the S30 DNS/IP record on my router, connected to wifi, but I don't how to look for an "mdns record of type_hap._tcp.local".

On my hassio system it does not find homekit.discover.

I don't have an iOS device, but in an exchange for a beer, I can ask my neighbor to come by with his iPad.

Jc2k commented 5 years ago

The Ecobee 3 doesn’t have WAC mode, or if it does it’s not part of the homekit flow. If it’s on your WiFi it is discoverable, and then Home Assistant can put the Ecobee into pairing mode which makes it display a pairing code.

On Linux you can use the avahi-browse command to see mdns records being published on your network. https://linux.die.net/man/1/avahi-browse

GaryOkie commented 5 years ago

I have no idea why this WAC process is initiated first before homekit pairing. The T-stat was already connected to wifi but all I could tell that this WAC did was to reconnect it to my home wifi instead of doing it manually through the touchpad. But anyway, after it connected to wifi it then eventually displayed the pairing code on the screen and the iPad home app was connected to it.

I've now done a homekit reset on the T-stat and back to square 1 - only having proven that iOS Home pairing works.

@Garyak - did you ever get a chance to test this on your S30's?

mrdehate commented 5 years ago

If it helps at all, I have an S30 and have been trying to pair with 0.94.0, and I get the same behavior as @jeromelaban above. The S30 says that it paired successfully, but I get an error message in the Home Assistant UI and the following in the log:

Wed Jun 12 2019 23:05:17 GMT-0400 (Eastern Daylight Time)
Pairing attempt failed with an unhandled exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 261, in async_step_pair
    pairing)
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 338, in _entry_from_accessory
    pairing.list_accessories_and_characteristics
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homekit/controller/ip_implementation.py", line 81, in list_accessories_and_characteristics
    accessories = json.loads(tmp)['accessories']
  File "/usr/local/lib/python3.7/json/__init__.py", line 348, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.7/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.7/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 1 (char 0)

Wed Jun 12 2019 23:05:17 GMT-0400 (Eastern Daylight Time)
Pairing attempt failed with an unhandled exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 290, in async_step_pair
    start_pairing, self.hkid, self.hkid
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homekit/controller/controller.py", line 370, in start_pairing
    raise AlreadyPairedError('Alias "{a}" is already paired.'.format(a=alias))
homekit.exceptions.AlreadyPairedError: Alias "6D:B1:87:10:43:6D" is already paired.
GaryOkie commented 5 years ago

Thanks @mrdehate - your post does help to show that this isn't a unique issue.

I did install an mdns survey app on an Android tablet connected to the same wifi as the S30 and saw _hap._tcp.local listed. Now I need to make sure that an ethernet-connected hassio on a tomato router is also seeing it. (There was a reported issue in 2013 with tomato routers and Bonjour wifi packets not being seen by ethernet devices, but I've not found confirmation it was fixed).

I won't be able to do any more pairing diagnostics for the next few days until I get back up here.

Jc2k commented 5 years ago

So what is throwing me is that there are 2 seperate exceptions. I thought the second could only be triggered if you pressed submit twice, but actually I think just showing the pairing form after the failure is causing that error.

The real issue is the first one. It's trying to hit the /accessories url on the device to fetch the entities available on your thermostat.

Now we now this does work for @jeromelaban because he paired manually before. So i'm wondering if there is a timing issue or something. It would be helpful if someone could edit /usr/local/lib/python3.7/site-packages/homekit/controller/ip_implementation.py on their environment and stick a sleep in their list_accessories_and_characteristics. I'm also interested in whether this is a new session or an existing session. So something like this would be helpful:

    def list_accessories_and_characteristics(self):
        """
        This retrieves a current set of accessories and characteristics behind this pairing.

        :return: the accessory data as described in the spec on page 73 and following
        :raises AccessoryNotFoundError: if the device can not be found via zeroconf
        """
        print("LIST_ACC_AND_CHAR", self.session)
        if not self.session:
            self.session = IpSession(self.pairing_data)
        import time
        time.sleep(10)
        try:
            response = self.session.get('/accessories')
        except (AccessoryDisconnectedError, EncryptionError):
            self.session.close()
            self.session = None
            raise
        tmp = response.read().decode()
        accessories = json.loads(tmp)['accessories']

This is different to the issue that @GaryOkie is having can only get to these fun errors after successful mdns discovery. Sorry @GaryOkie i'm not sure ho to proceed with that one of yours yet. Will have to see how you get on with mdns surveys...

GaryOkie commented 5 years ago

LOL - after leaving the lake cabin where the iComfort S30 is installed and coming home I connect to Hass and see that Hass zeroconf detected "HomeKit Accessory: iComfort S30 xxxx" and is now asking for the pairing code! I don't understand why it wasn't detected previously, but at least now it's clear there is no network issue with bonjour/mdns.

Apparently it wasn't necessary to put the iComfort into "Homekit/WAC mode" via the Homekit integration option on the S30 menu. WAC mode is an alternate way the S30 provides to simplify connecting the the wifi network, but it sure is weird this option is a required step in the Homekit pairing menu.

What will be interesting is to see when I get back to the cabin is if the S30 will actually display a pairing code when Hass asks for it - all without going through that WAC mode that requires an iOS device.

If you're curious about how the S30 Homekit process works, here's the Homekit pairing instructions.

I hope someone gets a chance to try out your suspected timing issue tweak soon. I will certainly try it if I can get a successful pair, but unfortunately, it will not be soon.

garyak commented 5 years ago

I've updated to HA 94.3, iOS 2.0 build 61 and am getting the "No unpaired devices could be found" error when attempting to add in the integrations page now. Did not put the ss30 into WAC mode.

GaryOkie commented 5 years ago

@garyak - have you added zeroconf: to your config? If so, Hass should automatically detect homekit appliances and display a notification of those it found and then let you pair them. I don't know if this is suppose to be immediate after restarting Hass or not. For me, the notification was significantly delayed for some reason.

Still hoping @mrdehate or @jeromelaban will have time to implement the _ipimplementation.py update to see if that fixes the timing issue reported after pairing.

I'm remotely logged in to Hass and it is still detecting the S30, so when I get back there I'm anxious to try to pair it for the first time.

mrdehate commented 5 years ago

I did paste in the changes to ip_implementation.py as @Jc2k listed above, and I got the same result in the log file. Well, other than the stacktrace mentioning line 84 rather than line 81. I tried both before and after restarting Home Assistant, and both failed in the same way.

However, I'm not sure where that print() line ends up? It isn't in home-assistant.log, there must be a system log somewhere that it gets output to? Or is this where debug mode comes in?

GaryOkie commented 5 years ago

@Jc2k - I'll be back up to the cabin tomorrow and will finally be able to continue testing. I was going to proactively edit _ipimplementation.py before attempting to pair per your suggestions but this does not exist yet on my Hassio 94.4 build. At what point does the homekit/controller directory get created under python3.7/site-packages? The zeroconf detection is working fine though.

Also, did you have any advice for me and @mrdehate to ensure the debug output is viewable? Thanks!

GaryOkie commented 5 years ago

@jc2k - I've just now tried to pair for the first time, and as expected, am getting the same "'Alias "{a}" is already paired.'" errors that @mrdehate and @jeromelaban reported.

On Hassio, I don't seem to have access to the /usr/local/lib/python3.7/site-packages directory in order to make any debugging tweaks to homekit_controller code. I will most likely need to create a custom_components folder in order to do that.

I'm happy to continue to work with you on figuring out this issue, but I will need some guidance in setting it up as a custom component along with its dependencies (homekit_python).

Jc2k commented 5 years ago

Cheers @GaryOkie, I’m away from civilisation right now (barely have 3G) - will check in when I’m back but will be at least 8 more days I would say

GaryOkie commented 5 years ago

Thanks for the heads-up and enjoy the time off!

skyway007 commented 5 years ago

Thanks for all your work @Jc2k. Enjoy your time off. I just had the same issue as everyone else on .95.4. Just an FYI

garyak commented 5 years ago

I've come close several times, but I receive either "already paired" or "no longer found". I once had the s30 id on the Integrations pairing device list, but the operation failed. I have noticed I need to begin the WAC process to allow the s30 to rediscover and connect to wireless. Just after the s30 reconnects to the network, and before adding to the accessory to HomeKit that I receive the HA notification. However, by the time the notification is acknowledged and HA rescans, the s30 has moved on. If I factory reset s30 HomeKit settings, the s30 no longer triggers HA notifications.

Jc2k commented 5 years ago

So i think there is a race condition after pairing that is causing the already paired errors. This is because one user reported success but after the code moved to config flow it stopped working for them. The code that is failing is here:

https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/components/homekit_controller/config_flow.py#L326

This is the most releveant error:

    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

It's weird because it fails after a message is retrieved from the connection and apparently the message was decrypted successfully.

What happens is HomeKit python completes pairing - successfully from what i can tell - and then HomeAssistant tries to access the API to retrieve the name of the bridge or accessory that it is paired with. This fails before the pairing keys are saved to disk and before HomeAssistant tries to load the entity. This leaves things in an inconsistent state - you need to restart HA and reset HomeKIt settings on the S30 to try again otherwise you get the already paired error.

I need someone to try the changes in https://github.com/home-assistant/home-assistant/issues/20885#issuecomment-501893283. The problem is some of you can't see the output of the print() statement (for me it appears on the command line if i run hass on the command line, or in 'docker logs' if i run it in a container). You could try 'logging.error' instead of print.

So to recap, somewhere in your installs will be a file called ip_implementation.py. Can someone located it (find / -name ip_implementation.py), open it in an editor and find def list_accessories_and_characteristics and add the logging bits as folows:


    def list_accessories_and_characteristics(self):
        """
        This retrieves a current set of accessories and characteristics behind this pairing.
        :return: the accessory data as described in the spec on page 73 and following
        :raises AccessoryNotFoundError: if the device can not be found via zeroconf
        """
        logging.warning("list_accessories_and_characteristics")
        import time; time.sleep(10)
        if not self.session:
            self.session = IpSession(self.pairing_data)
        try:
            response = self.session.get('/accessories')
        except (AccessoryDisconnectedError, EncryptionError):
            self.session.close()
            self.session = None
            raise
        tmp = response.read().decode()
        logging.warning("got response %s", tmp)
        accessories = json.loads(tmp)['accessories']

Thats 3 lines added - the 2 logging.warning lines and the time.sleep(10) bit. You'll need to restart HA after changing those lines and you'll need to reset HomeKit settings after each attempt.

I'd also like you to change the size of the time.sleep(10) to see if there is a minimum wait after pairing is finished.

The end goal here is to prove that the E30 will return duff answers for the /accessories after pairing for a few seconds - and if thats the case I can add a retry loop to handle this.

GaryOkie commented 5 years ago

@jc2k - I'll have to try to figure out to make this update on HASSIO. As reported on issue 15336, this "already paired" issue persists even though @garyak reported pairing success somehow with the latest HA version.

I hope I will be able to provide you with this additional logging info.

Jc2k commented 5 years ago

Thanks @GaryOkie - certainly looks like there is a race where we think the device is paired, but the device hasn't realised its paired yet. If we can confirm this I should be able to add some retrying to the pairing process.

Note that i'd expect to see other exceptions other than AlreadyPairedError - those are the more releveant ones in debugging this.

GaryOkie commented 5 years ago

Hi @jc2k - thanks very much for the quick response! I figured out out to gain access to the python code for components on HASSIO. It requires entering the HA docker via docker exec -it homeassistant /bin/bash The files were located in /usr/local/lib/python3.7/site-packages/homekit/controller/

Here's the debug output which includes the new warning messages (using time.sleep(10)). I'll reset everything and try again, doubling the sleep to 20.

019-09-29 15:35:15 DEBUG (zeroconf-ServiceBrowser__hap._tcp.local.) [homeassistant.components.zeroconf] Discovered new device iComfort S30 5185f0._hap._tcp.local. {'host': '192.168.0.53', 'port': 7373, 'hostname': 'lcc-WL18E03691.local.', 'type': '_hap._tcp.local.', 'name': 'iComfort S30 5185f0._hap._tcp.local.', 'properties': {'C#': '1', 'ff': '1', 'id': '0F:FD:6D:A2:CA:DA', 'md': 'S30 2B', 'pv': '1.0', 's#': '1', 'sf': '1', 'ci': '9'}}
2019-09-29 15:35:16 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device iComfort S30 5185f0 (S30 2B - 0F:FD:6D:A2:CA:DA)
2019-09-29 15:35:39 DEBUG (SyncWorker_17) [homekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x01
  0: (1 bytes/<class 'bytearray'>) 0x01
]

2019-09-29 15:35:39 DEBUG (SyncWorker_17) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x01
  0: (1 bytes/<class 'bytearray'>) 0x01
]

2019-09-29 15:35:40 DEBUG (SyncWorker_17) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x02
  3: (384 bytes/<class 'bytearray'>) 0xa0c618b90d6442356ae2db19028ff818000025b9de762d881cf23711eab0d47b5cdff6f5fd43ee232e9c470d18cd319d441a91d105d9965ea5e9623436ece06740f198bf71f72353fef07c08698b438d353c43d1db1859ee17cafd9e3ed012b30d0641386f7af1cd74dff308344acfbc00e92c02d22184d3761c086a0425bd2434ac7a78eb2186b8eed4a6886a09eac2966da4846572f05676274ad39fb561ad14f646e056ee5875c0b20ee06315bbc286f88aab96b1777a14f5817242c9b0de9e59f0f43d0b39f63c845569c445cef56bbf0523801ae72e7c07c3b55cf67815e7ed7d1aecda2d03cda96f4abb1b4ab9abad7f55ba6c2b9ea588ea270e3bae4b8360590364715e77772edaf684360118bd0f2ca3f80b1c08f25cf8e03b9073ac03eec8b8b865281b50dcdcdafdbfce6c2b9c6837b747abf79ff671a2383cb6ef87f6ec30ba7c0b11b753052bfdf7fef23ae1ac4dd6d4f79223ea3580deecc5b9e6b93f4041ec60f3b80811129a0e246a1a826254aa1d558f0ab183c9e685a0df
  2: (16 bytes/<class 'bytearray'>) 0x071d7104a0777390219239d0df8c6027
]

2019-09-29 15:36:02 DEBUG (SyncWorker_5) [homekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x03
  3: (384 bytes/<class 'bytearray'>) 0x22685170b8d75791872959b8f9e5a933714d7115aa9b8b0c658ce02b11b03a35fb423357b8ce8d5c31d82f8d31bb9faa58e859f53e382f01a319463c1ea7d99a686dbfecb16aca6a6be179c79370763e94ca69e6342fe4bda3231d7ab83433cf348167abb4a47c5cfc2bc4fc3da6e2f6d88593c00b95522927d683383db3209be8b097998bc6256ecf41c0bdb5f854df5b4f4a0756aed52f686cad51a25681cb7d035d7dd50fbb0e3c64f3fd561b1b5d21998bf7a22ea31d78aa7121c1fc034f88ff013784232c2d46340b31b6f4d752e49d24f8a5169d2bdf1b73362ba20185ac97eb446364a7a21f79196f4391930f08e5853d83c17d7d5778fc15f46fad57f569900f6b120bd215a4212daa8a01bfadc23a0e719f197e9d00fbbd436a3e726dd489fd5a327f107f5bd7f25fdcc7df9abe641dc3b61742d33ebd0d0670f627a928463535212a81112551385e46c3749227f0235b690d0b75e1c8b0cfa4b8a71d9157770aba93f16b4d45c203dec691155378b90a2b06baf14060beb7250c9e
  4: (64 bytes/<class 'bytearray'>) 0x47e912cfc7200c49fbec22f5fce7af11b9e4882b02827b5b9b67e7d5869ffc17d3234eaa72ef5fdf01e728d4423c387b415276b7374675c30c4b9795835ff220
]

2019-09-29 15:36:02 DEBUG (SyncWorker_5) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x03
  3: (384 bytes/<class 'bytearray'>) 0x22685170b8d75791872959b8f9e5a933714d7115aa9b8b0c658ce02b11b03a35fb423357b8ce8d5c31d82f8d31bb9faa58e859f53e382f01a319463c1ea7d99a686dbfecb16aca6a6be179c79370763e94ca69e6342fe4bda3231d7ab83433cf348167abb4a47c5cfc2bc4fc3da6e2f6d88593c00b95522927d683383db3209be8b097998bc6256ecf41c0bdb5f854df5b4f4a0756aed52f686cad51a25681cb7d035d7dd50fbb0e3c64f3fd561b1b5d21998bf7a22ea31d78aa7121c1fc034f88ff013784232c2d46340b31b6f4d752e49d24f8a5169d2bdf1b73362ba20185ac97eb446364a7a21f79196f4391930f08e5853d83c17d7d5778fc15f46fad57f569900f6b120bd215a4212daa8a01bfadc23a0e719f197e9d00fbbd436a3e726dd489fd5a327f107f5bd7f25fdcc7df9abe641dc3b61742d33ebd0d0670f627a928463535212a81112551385e46c3749227f0235b690d0b75e1c8b0cfa4b8a71d9157770aba93f16b4d45c203dec691155378b90a2b06baf14060beb7250c9e
  4: (64 bytes/<class 'bytearray'>) 0x47e912cfc7200c49fbec22f5fce7af11b9e4882b02827b5b9b67e7d5869ffc17d3234eaa72ef5fdf01e728d4423c387b415276b7374675c30c4b9795835ff220
]

2019-09-29 15:36:04 DEBUG (SyncWorker_5) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x04
  4: (64 bytes/<class 'bytearray'>) 0xbff09b452a9f6aedd494920b7430d6654255f6ff32b9a8c31a9847ab4cb103d1945c872b0a55a656c9adc6437795922e273a3aef48bc27b8659fa642272d94e7
]

2019-09-29 15:36:07 DEBUG (SyncWorker_5) [homekit.protocol.tlv] sending [
  1: (36 bytes/<class 'bytes'>) b'07f89275-1659-4657-9d12-dfe7d3fb69b7'
  3: (32 bytes/<class 'bytes'>) b'\xd5\xea\xc6\xe4\xb4\xb6\x138Q\xcf[\x03w\x1f\xa3p\xa0xg\x0f\x8b\xcc!X\ni>\xf6\x13\x80\xf1\xdd'
  10: (64 bytes/<class 'bytes'>) b'\x0f1-\xe4\xee5\xc3T\t\xac\x98\xbd\x8fh\x8dZ\xfd\xf3\xf4\xd7\xa0\xfc\\_\xd1e\xb0\x13\xe2eO{\x0c\x91"@\x17\xa6\xf8g\xc2\x84\xa0\x1fj:\x80\xedWfm\xa1\xee\xe2\xb69~]\x8d\xc7\xc0k\x9e\x01'
]

2019-09-29 15:36:07 DEBUG (SyncWorker_5) [homekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x05
  5: (154 bytes/<class 'bytearray'>) 0x6ffd31319a47136541455cfacfec577987728c095c425d777d90ce7b86f286875aececf3fd628eeb6e4815cc78cc3c812dd0e248b045eb9f53397bb6a879ac53b2cc9e3ec2040a227a7be6e405ee1f375090b49a0abd3611508fc5b850f830e924ab8491977eea9ba0b19c55b3a968bb3fb324e375cd866a763cdfa0b9924a12bf418f2eb36d4e64be9c2b38049066abd1319f5c0972468e5f43
]

2019-09-29 15:36:07 DEBUG (SyncWorker_5) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x05
  5: (154 bytes/<class 'bytearray'>) 0x6ffd31319a47136541455cfacfec577987728c095c425d777d90ce7b86f286875aececf3fd628eeb6e4815cc78cc3c812dd0e248b045eb9f53397bb6a879ac53b2cc9e3ec2040a227a7be6e405ee1f375090b49a0abd3611508fc5b850f830e924ab8491977eea9ba0b19c55b3a968bb3fb324e375cd866a763cdfa0b9924a12bf418f2eb36d4e64be9c2b38049066abd1319f5c0972468e5f43
]

2019-09-29 15:36:10 DEBUG (SyncWorker_5) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x06
  5: (135 bytes/<class 'bytearray'>) 0xc13b30f09a037dffca6e16a02f665bbc9486f7117d67329acd852ee149ce20fcff8f73c357f97825fead6d386eb0f0b147221e354c3c53a31d415c6703f7a7b8e3e51ee0a41fbb7cf48f86b27af7b5269776924115b23f30fcf7dfa252dd2f68e11bb7c910107d10271bc57a22cd11bfa04400523bd889df340426cc132c3adf8c3bdf9a10cba3
]

2019-09-29 15:36:10 DEBUG (SyncWorker_5) [homekit.protocol.tlv] receiving [
  1: (17 bytes/<class 'bytearray'>) 0x30463a46443a36443a41323a43413a4441
  3: (32 bytes/<class 'bytearray'>) 0x7401099212bc8748a164c888ecc6f26041cf078bf9a3e95ce74238f923882beb
  10: (64 bytes/<class 'bytearray'>) 0x09383cedc5184fb23c4f252942872f447f15686f24b9db820bc95c8f63057c38477f25165c12bf6b60436fa0bc4398596a20f02fea42c91dcedd69cb58c54502
]

2019-09-29 15:36:11 WARNING (SyncWorker_6) [root] list_accessories_and_characteristics
2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x01
  3: (32 bytes/<class 'bytes'>) b'F\xa2\xb5c\x0c\xe0=\xeed\xd4>\x18/\x1b\x1c\xf7/;\xebs\xbbR&\x07Q\x0fP\xa3\x9e3\rd'
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x01
  3: (32 bytes/<class 'bytearray'>) 0x46a2b5630ce03dee64d43e182f1b1cf72f3beb73bb522607510f50a39e330d64
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x02
  3: (32 bytes/<class 'bytearray'>) 0xa404dc933feb847a09f6d5a339d3fedeb698895de098206651a716f7a3a2c41f
  5: (101 bytes/<class 'bytearray'>) 0xa810af2d48d435169c0f5b47dacd15f395c9274cbd6c3d4f841294d34c0963954dfd24ecad6ef12a03193a999ca7a9c02150413dc0ca81c34b68be8a28230616ed67d81d080133561afca9e54f3d8dc83a34f7c072b96cfad5eac78e1024f21bb2feb6bd24
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] receiving [
  1: (17 bytes/<class 'bytearray'>) 0x30463a46443a36443a41323a43413a4441
  10: (64 bytes/<class 'bytearray'>) 0x06fd5de9e4a84c46e35e12b674c77eb24d63d89b958714bdb21679bf562359fc8f7d21055afd95796d3d2cd1833995061fea1c30f47dc5f7c084639c67b79005
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] sending [
  1: (36 bytes/<class 'bytes'>) b'07f89275-1659-4657-9d12-dfe7d3fb69b7'
  10: (64 bytes/<class 'bytes'>) b'\xca\x83\x82^7\xe0"\x1e\x03\xe7K\x14w\xd5\x8c\xea\xa7\x13+|\xa8\x94\x04X\xa6\x9f\xf3\xd2\x87\xd0\x08\xc9=\xfc6\xa4P\xd9\xd4c\x19\xd1\xbb\x8b\x0coQWw\x871f\x1e\xc8\xf9\xe2\x06\x9b\x84U\x8c\x88\x8e\x06'
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] sending [
  6: (1 bytes/<class 'bytearray'>) 0x03
  5: (120 bytes/<class 'bytearray'>) 0xd3b90d83ca61aae1e6902b83292d044975b74802e83d9eb0741469f2db6472a9241afb4d51c835f4dba813cda1724f835ccb5c987cb133e65eaa7c82fc37a9fe952e6e22aaa987faf88cf17f02f65a2a44cc86f515730d4e87b21accc73e3847bf837b974cfe0e0f5378bc94041c86a0ca08095b460eeeaa
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x03
  5: (120 bytes/<class 'bytearray'>) 0xd3b90d83ca61aae1e6902b83292d044975b74802e83d9eb0741469f2db6472a9241afb4d51c835f4dba813cda1724f835ccb5c987cb133e65eaa7c82fc37a9fe952e6e22aaa987faf88cf17f02f65a2a44cc86f515730d4e87b21accc73e3847bf837b974cfe0e0f5378bc94041c86a0ca08095b460eeeaa
]

2019-09-29 15:36:21 DEBUG (SyncWorker_6) [homekit.protocol.tlv] receiving [
  6: (1 bytes/<class 'bytearray'>) 0x04
]

2019-09-29 15:36:31 WARNING (SyncWorker_6) [root] got response 
2019-09-29 15:36:31 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Pairing attempt failed with an unhandled exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 251, in async_step_pair
    return await self._entry_from_accessory(pairing)
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 324, in _entry_from_accessory
    pairing.list_accessories_and_characteristics
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homekit/controller/ip_implementation.py", line 84, in list_accessories_and_characteristics
    accessories = json.loads(tmp)['accessories']
  File "/usr/local/lib/python3.7/json/__init__.py", line 348, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.7/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.7/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 1 (char 0)
2019-09-29 15:36:31 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Pairing attempt failed with an unhandled exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 278, in async_step_pair
    start_pairing, self.hkid, self.hkid
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homekit/controller/controller.py", line 374, in start_pairing
    raise AlreadyPairedError('Alias "{a}" is already paired.'.format(a=alias))
homekit.exceptions.AlreadyPairedError: Alias "0F:FD:6D:A2:CA:DA" is already paired.
GaryOkie commented 5 years ago

No joy after changing time sleep to 20. Debug log the same as above. Did you see confirmation in the log that adding a retry loop will help?

Unfortunately I will not be able to run any more tests for at least a week or two. This S30 is at my lake house and we're heading back home now. Thanks again for your time looking into this - I greatly appreciate it!

Jc2k commented 5 years ago

Sadly not enough no. One positive is this:

2019-09-29 15:36:31 WARNING (SyncWorker_6) [root] got response

Means the problem is after a successful pairing has happened but before the pairing is saved to disk. We need to get some metadata from the device before we save it to a config entry, and thats what fails. The device doesn't return an error, it returns an empty string.

I guess next time i'd like to try this:

        logging.warning("list_accessories_and_characteristics")
        import time; time.sleep(10)
        if not self.session:
            logging.warning("STARTING NEW SESSION")
            self.session = IpSession(self.pairing_data)

To make sure an old session from during the pairing isn't being used somehow.