core 🚀 - Invalid Lennox E30 pairing flow via HomeKit controller

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.

Jc2k on 11 Feb 2019

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"
            }
        ]
    }
]

jeromelaban on 12 Feb 2019

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

Jc2k on 12 Feb 2019

👍1

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 on 14 Feb 2019

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.

jeromelaban on 14 Feb 2019

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.

Jc2k on 14 Feb 2019

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!

GaryOkie on 1 Apr 2019

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.

garyak on 1 Apr 2019

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

niemyjski on 4 Apr 2019

@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?

Jc2k on 4 Apr 2019

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

>

niemyjski on 4 Apr 2019

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 on 4 Apr 2019

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:

There is a related branch here that adds device registry support. This allows HA to know the relationship between entities and physical devices attached to HomeKit hubs.
Now that config entries is done I've also finished polishing the pairing patch which is really the one most people tracking this ticket are interested in. It's here. With this we should be able to support any HomeKit with a display (i.e. randomised pairing codes) - save for device specific quirks.

Jc2k on 15 May 2019

👍1

@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.

GaryOkie on 15 May 2019

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

The pairing fix for devices with screens and random pairing codes
The new config entry support (so your devices appear under 'Integrations' like Hue etc)
Device info support (groups entities by phsyical device and lets you put them in areas)
Migrates to the new zeroconf module for discovery

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 on 30 May 2019

🎉1

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.

Jc2k on 7 Jun 2019

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.

GaryOkie on 7 Jun 2019

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

garyak on 7 Jun 2019

@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.

Jc2k on 7 Jun 2019

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.

GaryOkie on 7 Jun 2019

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

garyak on 7 Jun 2019

@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!

jeromelaban on 11 Jun 2019

@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.

Jc2k on 11 Jun 2019

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

jeromelaban on 11 Jun 2019

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.

Jc2k on 11 Jun 2019

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.

jeromelaban on 11 Jun 2019

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?

GaryOkie on 12 Jun 2019

@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?

Jc2k on 12 Jun 2019

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.

GaryOkie on 13 Jun 2019

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

Jc2k on 13 Jun 2019

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?

GaryOkie on 13 Jun 2019

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.

mrdehate on 13 Jun 2019

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.

GaryOkie on 13 Jun 2019

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...

Jc2k on 13 Jun 2019

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.

GaryOkie on 16 Jun 2019

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.

garyak on 19 Jun 2019

@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 _ip_implementation.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.

GaryOkie on 19 Jun 2019

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?

mrdehate on 20 Jun 2019

@Jc2k - I'll be back up to the cabin tomorrow and will finally be able to continue testing. I was going to proactively edit _ip_implementation.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 on 26 Jun 2019

@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).

GaryOkie on 27 Jun 2019

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

Jc2k on 27 Jun 2019

👍1

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

GaryOkie on 27 Jun 2019

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

skyway007 on 29 Jun 2019

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.

garyak on 9 Aug 2019

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.

Jc2k on 9 Aug 2019

@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.

GaryOkie on 29 Sep 2019

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.

Jc2k on 29 Sep 2019

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 on 29 Sep 2019

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!

GaryOkie on 29 Sep 2019

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.

Jc2k on 29 Sep 2019

iOS 13.1 on iPhone 8. HA running on a Hass.io install on Intel NUC under Ubuntu 18.04. S30 firmware is version 03.50.0148 updated August 28, 2019. Using the built-in HA Thermostat card. These are the states reported by HA:

climate.icomfort_s30_02f6a2 | off | hvac_modes: off,heat,cool,heat_cool current_temperature: 76 min_temp: 40 max_temp: 90 temperature: 58 current_humidity: 38 hvac_action: off friendly_name: Master Thermostat supported_features: 1
-- | -- | --
climate.icomfort_s30_22eed8 | off | hvac_modes: off,heat,cool,heat_cool current_temperature: 78 min_temp: 40 max_temp: 90 temperature: 65 current_humidity: 27 hvac_action: off friendly_name: Kitchen Thermostat supported_features: 1

I haven't restarted since the S30's paired a couple days ago. I have loging set to "ERROR". No errors are appearing for this integration.

-- | -- | --

garyak on 30 Sep 2019

🚀1

@garyak nice. it sounds like you had the same problem as @GaryOkie originally, which definitely makes me think its a race as nothing in that bit of code has changed in a while.

You updated your firmware on August 28 - that was after you last posted here. Can you confirm you experienced the error again after that update? Specificially the JSONDecodeError? If not then maybe the latest firmware helped.

Where there any other changes - like in your networking etc between the last time you noticed and error and it working?

Did it just work first time with 99.3 or did you try more than once? What version were you on previously?

Jc2k on 30 Sep 2019

Chamberlin pushes updates to the S30. It's likely @GaryOkie is at the same version, but if not, has a means to verify the S30 part. I have not received a JSONDecodeError in the HA logs.

No changes to networking. S30's are on the same VLAN as the HA instance. S30's are WiFi @ 2.4Ghz, HA is hardwired.

Pairing did not work first time. I fumbled the first pairing code by not entering the dashes. The result was HA throwing a Pairing attempt failed with an unhandled exception error. I restarted WAC, without a complete reset, and HA rediscovered the S30. The second S30 integrated first time. I have not exported the S30's from HA to HomeKit.

Previous version was 0.94.xx. I added zeroconf: to the config file and made several attempts at pairing. S30 firmware was updated after those attempts. What prompted the new attempt was that I found both S30 in WAC mode. Believing there had been a firmware update, I retried the pairing procedure. Not sure why the S30's went into WAC mode. No indication of power transient.

garyak on 30 Sep 2019

Wow, nice to see that you got it to work @garyak I'm on the same new version as well and have tried on every new version of HA with the same results. The S30 thinks it paired okay but HA doesn't. I will try adding zeconf and try again tonight. Network is relatively basic and on the same VLAN. Will report back. Thanks for your help @Jc2k. Would it be valuable to go ahead and add the retry to see if that helps us?

skyway007 on 30 Sep 2019

@garyak - According to this site, the latest iComfort S30 software update was v3.5 in May 2019, which is automatically installed. (By Lennox, not Chamberlain - BTW! :)

That interesting that your S30's went into WAC mode on their own, but something surely caused them to reboot. I'm sure you already know there is an option in the S30 Homekit menu of "Auto WAC mode" that is enabled by default. It is triggered if the S30 reboots and WAC was not previously configured.

It's also interesting that the HA zeroconf detection picked up the Homekit broadcast while the S30 was only in the initial WAC "ready for configuration" mode. I didn't think the broadcast occurred until after the WAC wifi connection was completed via iOS (after tapping Next then done in iOS).

@skyway007 - would you be able to work with @jc2k to implement the additional debugging tests he is needing? I won't be able to for another week or two. If you are using HASSIO, I can help you with how to update the python code.

GaryOkie on 30 Sep 2019

+1 - I need to understand what the failure is before I can add appropriate error handling and retrying. The 20s sleep not working is somewhat troubling.

My understanding was that HomeKit devices should always broadcast. At least they need to when paired for networks where IPs are dynamic (most non techie DHCP setups). So the whole WAC thing is confusing. Unless a paired S30 does always broadcast?

Jc2k on 30 Sep 2019

@GaryOkie yes absolutely. I'm definitely willing. Honestly the challenge has been getting to a point where I can access the core files. I use a container within docker so have to setup SSH to it I believe. I will work on it today and then work on making the changes. Any feedback to update the python would be appreciated of course. Will report back tonight.

skyway007 on 30 Sep 2019

Hi @skyway007 - that's great you can pick up with the additional debugging! Happy to help.

I can only speak to a HASSIO configuration, but it sounds like your docker configuration is similar. I use the community SSH & web Terminal add-on, which requires disabling "protection mode" then restarting HA.

Once connected to HASSIO via SSH terminal, I can access the the HA Docker container via this command:
docker exec -it homeassistant /bin/bash

Then you can edit (I use vi) the following python code:
/usr/local/lib/python3.7/site-packages/homekit/controller/ip_implementation.py

Then insert the THREE new "logging.warning" debug statements as per below...

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:
            logging.warning("STARTING NEW 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']

Be sure you have at least WARN level logging enabled in configuration.yaml, then restart HA. Reset the S30 Homekit to factory defaults, which should then automatically enter WAC mode and you then set up the wifi connection with iOS. HA (via zeroconf) should automatically detect the S30 in the notification panel to start the pairing process. Capture the relevant messages from the home-assistant.log for @jc2k .

GaryOkie on 30 Sep 2019

@GaryOkie got MyQ on my mind. I hope my credibility isn't too damaged. I verified both S30's are on 03.50.0148 updated August 28, 2019 according the S30's About screen. As for WAC mode triggering, I sure you're correct. I had reset both S30's after pounding them testing last time. Must have had a minor power drop. I do not have them configured in HomeKit.

Yes, you need to wait for the S30 to configure the SSID and press Done at the Find App screen to receive an HA code prompt. Sorry for the confusion. I'll increase my dose to two cups tomorrow.

garyak on 30 Sep 2019

@Jc2k I have DHCP reservations for both S30's. If it's relevant.

garyak on 30 Sep 2019

@GaryOkie thank you very much for taking the time to spell this out. I believe I was able to make all the right changes and I'm ready to go. Will try it with the S30 tonight when I get home.

skyway007 on 30 Sep 2019

Hi @Jc2k, here's what I got.

I'm using HA with Docker v0.99.2. S30 is on same VLAN as HA.

HA doesn't have any trouble recognizing it as a new Home Kit device ready to connect. When I attempt to configure it, the S30 promptly displays the code and after I enter the code into HA, the S30 successfully confirms that it is paired. HA continues to spin and then ultimately gives me the error. The flow, error and timing has been largely unchanged for me in the last few version of HA.

Please let me know if you need anything else. Thank you!

2019-09-30 19:46:44 WARNING (SyncWorker_15) [root] LIST_accessories_and_characteristics
2019-09-30 19:46:54 WARNING (SyncWorker_15) [root] STARTING NEW SESSION
2019-09-30 19:47:04 WARNING (SyncWorker_15) [root] GOT RESPONSE 
2019-09-30 19:47:04 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 85, 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-30 19:47:04 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 "4A:A4:6E:73:E1:60" is already paired.

skyway007 on 1 Oct 2019

Thanks @skyway007 for implementing this test! It's an identical result to my test, but with confirmation that a NEW SESSION is being started that @jc2k wanted to see.

As you can see, there is no accessory data in the log following GOT RESPONSE (tmp) - just python errors primarily due to tmp being null. Seems reasonable to test for a null tmp and exit with a related message. But of course, getting to the bottom of why nothing is returned and solving it, that data verification shouldn't be needed.

While we are waiting for @jc2k to suggest additional debugging code to try, please change time.sleep(10) to time.sleep(30) to see if that makes any difference.

EDIT: Also, please see if your Lennox S30 is on the latest firmware release that @garyak identified on his units... 03.50.0148 according the S30's About screen.

GaryOkie on 2 Oct 2019

Thanks @GaryOkie - thats exactly right - i want to keep bumping the time.sleep to see if there is a value that works.

I've verified that the existing code closes the TCP stream used for pairing (i had worried that the stream was getting left open and that was to blame, but this is now ruled out).

Another thought was that the listen port was changing and without an updated Bonjour search result this wasn't been detected. But that would manifest as a ConnectionTimeout, not an empty string being returned.

I guess that is one thing to look at actually - although this value is empty, there should have been a full HTTP response with headers. So we can do something like this. Find homekit/http_impl/response.py. It should look like this. Find the parse function and edit as follows:

    def parse(self, part):
        import logging
        logging.warning(part)
        self._raw_response += part
        pos = self._raw_response.find(b'\r\n')
        while pos != -1:

(This module doesn't have logging already hence us adding the import).

This well let us see the full decrypted response from the device which might include a HTTP error code.

So that's 3 more pieces of info:

This new debug logging
Increasing the time.sleep to see if there is a delay before it starts working
Report on device firmware

Jc2k on 2 Oct 2019

Hi @Jc2k so my unit is definitely on 3.5.0.0148 and changing the value to 30 did the trick!!!!

I also added the other logging.

It took a long time. And from the logs it almost looks like it had to do it a couple of times but it finally configured it okay. HA is reporting the state and I'm able to control based on very preliminary testing.

Here's the logs.

2019-10-02 16:58:39 WARNING (SyncWorker_12) [root] LIST_accessories_and_characteristics
2019-10-02 16:59:10 WARNING (SyncWorker_12) [root] STARTING NEW SESSION
2019-10-02 16:59:10 WARNING (SyncWorker_12) [root] bytearray(b'HTTP/1.1 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 1853\r\n\r\n{"accessories":[{"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":"S30 2B"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"iComfort S30 3eaf73"},{"format":"string","iid":6,"perms":["pr"],"type":"30","value":"WL17J00671"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"3.55.626"},{"format":"string","iid":8,"perms":["pr"],"type":"53","value":"3.0.002"}],"iid":1,"type":"3E"},{"characteristics":[{"format":"uint8","iid":101,"maxValue":2,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"F","value":0},{"format":"uint8","iid":102,"maxValue":3,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"33","value":0},{"format":"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":25.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":1},{"format":"float","iid":106,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"D","unit":"celsius","value":23},{"format":"float","iid":107,"maxValue":100,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"10","unit":"percentage","value":56},{"format":"float","iid":108,"maxValue":32,"minStep":0.5,"minValue":4.5,"perms":["pr","pw","ev"],"type":"12","unit":"celsius","value":21},{"format":"string","iid":109,"perms":["pr"],"type":"23","value":"Thermostat"}],"iid":100,"primary":true,"type":"4A"},{"characteristics":[{"format":"string","iid":301,"perms":["pr"],"type":"37","value":"1.1.0"}],"iid":300,"type":"A2"}]}]}')
2019-10-02 16:59:10 WARNING (SyncWorker_12) [root] GOT RESPONSE {"accessories":[{"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":"S30 2B"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"iComfort S30 3eaf73"},{"format":"string","iid":6,"perms":["pr"],"type":"30","value":"WL17J00671"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"3.55.626"},{"format":"string","iid":8,"perms":["pr"],"type":"53","value":"3.0.002"}],"iid":1,"type":"3E"},{"characteristics":[{"format":"uint8","iid":101,"maxValue":2,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"F","value":0},{"format":"uint8","iid":102,"maxValue":3,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"33","value":0},{"format":"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":25.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":1},{"format":"float","iid":106,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"D","unit":"celsius","value":23},{"format":"float","iid":107,"maxValue":100,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"10","unit":"percentage","value":56},{"format":"float","iid":108,"maxValue":32,"minStep":0.5,"minValue":4.5,"perms":["pr","pw","ev"],"type":"12","unit":"celsius","value":21},{"format":"string","iid":109,"perms":["pr"],"type":"23","value":"Thermostat"}],"iid":100,"primary":true,"type":"4A"},{"characteristics":[{"format":"string","iid":301,"perms":["pr"],"type":"37","value":"1.1.0"}],"iid":300,"type":"A2"}]}]}
2019-10-02 16:59:10 INFO (MainThread) [homeassistant.setup] Setting up homekit_controller
2019-10-02 16:59:10 INFO (MainThread) [homeassistant.setup] Setup of domain homekit_controller took 0.0 seconds.
2019-10-02 16:59:10 WARNING (SyncWorker_8) [root] LIST_accessories_and_characteristics
2019-10-02 16:59:40 WARNING (SyncWorker_8) [root] STARTING NEW SESSION
2019-10-02 16:59:40 WARNING (SyncWorker_8) [root] bytearray(b'HTTP/1.1 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 1853\r\n\r\n{"accessories":[{"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":"S30 2B"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"iComfort S30 3eaf73"},{"format":"string","iid":6,"perms":["pr"],"type":"30","value":"WL17J00671"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"3.55.626"},{"format":"string","iid":8,"perms":["pr"],"type":"53","value":"3.0.002"}],"iid":1,"type":"3E"},{"characteristics":[{"format":"uint8","iid":101,"maxValue":2,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"F","value":0},{"format":"uint8","iid":102,"maxValue":3,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"33","value":0},{"format":"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":25.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":1},{"format":"float","iid":106,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"D","unit":"celsius","value":23},{"format":"float","iid":107,"maxValue":100,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"10","unit":"percentage","value":56},{"format":"float","iid":108,"maxValue":32,"minStep":0.5,"minValue":4.5,"perms":["pr","pw","ev"],"type":"12","unit":"celsius","value":21},{"format":"string","iid":109,"perms":["pr"],"type":"23","value":"Thermostat"}],"iid":100,"primary":true,"type":"4A"},{"characteristics":[{"format":"string","iid":301,"perms":["pr"],"type":"37","value":"1.1.0"}],"iid":300,"type":"A2"}]}]}')
2019-10-02 16:59:40 WARNING (SyncWorker_8) [root] GOT RESPONSE {"accessories":[{"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":"S30 2B"},{"format":"string","iid":5,"perms":["pr"],"type":"23","value":"iComfort S30 3eaf73"},{"format":"string","iid":6,"perms":["pr"],"type":"30","value":"WL17J00671"},{"format":"string","iid":7,"perms":["pr"],"type":"52","value":"3.55.626"},{"format":"string","iid":8,"perms":["pr"],"type":"53","value":"3.0.002"}],"iid":1,"type":"3E"},{"characteristics":[{"format":"uint8","iid":101,"maxValue":2,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"F","value":0},{"format":"uint8","iid":102,"maxValue":3,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"33","value":0},{"format":"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":25.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":1},{"format":"float","iid":106,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"D","unit":"celsius","value":23},{"format":"float","iid":107,"maxValue":100,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"10","unit":"percentage","value":56},{"format":"float","iid":108,"maxValue":32,"minStep":0.5,"minValue":4.5,"perms":["pr","pw","ev"],"type":"12","unit":"celsius","value":21},{"format":"string","iid":109,"perms":["pr"],"type":"23","value":"Thermostat"}],"iid":100,"primary":true,"type":"4A"},{"characteristics":[{"format":"string","iid":301,"perms":["pr"],"type":"37","value":"1.1.0"}],"iid":300,"type":"A2"}]}]}
2019-10-02 16:59:40 INFO (MainThread) [homeassistant.components.climate] Setting up climate.homekit_controller
2019-10-02 16:59:40 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new climate.homekit_controller entity: climate.icomfort_s30_3eaf73
2019-10-02 16:59:40 ERROR (MainThread) [homeassistant.components.alexa.capabilities] climate.icomfort_s30_3eaf73 (<class 'homeassistant.core.State'>) has unsupported state value 'unknown'
2019-10-02 16:59:41 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/alexa/state_report.py", line 45, in async_entity_state_listener
    hass, smart_home_config, alexa_changed_entity
  File "/usr/src/homeassistant/homeassistant/components/alexa/state_report.py", line 70, in async_send_changereport_message
    properties = list(alexa_entity.serialize_properties())
  File "/usr/src/homeassistant/homeassistant/components/alexa/entities.py", line 181, in serialize_properties
    for prop in interface.serialize_properties():
  File "/usr/src/homeassistant/homeassistant/components/alexa/capabilities.py", line 106, in serialize_properties
    prop_value = self.get_property(prop_name)
  File "/usr/src/homeassistant/homeassistant/components/alexa/capabilities.py", line 589, in get_property
    raise UnsupportedProperty(name)
homeassistant.components.alexa.errors.UnsupportedProperty: thermostatMode

skyway007 on 3 Oct 2019

That's sure good news @skyway007 - thanks! It looks like after pairing, the component needs to query the accessory detail a second time during a separate "Setting up climate.homekit.controller" process. So there was at least a 30 + 30 second timed.wait to complete the pairing and setup process.

@Jc2k - I hope this provides you with sufficient background to insert a 10-second retry loop. Thanks so much for all your great attention to this code!

GaryOkie on 3 Oct 2019

@skyway007 did you add any other code? I'm not getting the same results as you with a 30s sleep. I've also tried 60 and 90 seconds without success.

My S30 is on version 3.5.0.0148 as well.

2019-10-03 09:56:44 WARNING (SyncWorker_37) [root] list_accessories_and_characteristics
2019-10-03 09:56:44 WARNING (SyncWorker_37) [root] beginsleep
2019-10-03 09:57:14 WARNING (SyncWorker_37) [root] endsleep
2019-10-03 09:57:14 WARNING (SyncWorker_37) [root] STARTING NEW SESSION
2019-10-03 09:57:44 WARNING (SyncWorker_37) [root] got response

ccormier on 3 Oct 2019

@ccormier can you try the other change I posted in https://github.com/home-assistant/home-assistant/issues/20885#issuecomment-537523780? It won’t make it work but might give clues as to the underlying fault.

Jc2k on 3 Oct 2019

@Jc2k I actually do have that code there, but it doesn't look like it's getting triggered, I don't see the associated logline

ccormier on 3 Oct 2019

Interesting. If that code isn’t hit then it shouldn’t get as far as it has. I wonder if there is another copy of the homekit package in your install somehow?

Jc2k on 3 Oct 2019

If I understand the flow correctly (good chance i dont) it looks like the _read_response method in SecureHttp calls the parse function only if there is data . I put some debugging lines in secure_httpy.py -> SecureHttp -> _read_response

def _read_response(self, timeout=10):                                                                               
    # following the information from page 71 about HTTP Message splitting:                                          
    # The blocks start with 2 byte little endian defining the length of the encrypted data (max 1024 bytes)         
    # followed by 16 byte authTag                                                                                   
    tmp = bytearray()                                                                                               
    exp_len = 1024                                                                                                  
    response = HttpResponse()                                                                                       
    while not response.is_read_completely():                                                                        
        logging.warn('_read_response: loop begin')                                                                  
        # make sure we read all blocks but without blocking to long. Was introduced to support chunked transfer mode
        # from https://github.com/maximkulkin/esp-homekit                                                         
        self.sock.setblocking(0)                                                                                  

        no_data_remaining = (len(tmp) == 0)                                                                       

        # if there is no data use the long timeout so we don't miss anything, else since there is still data go on
        # much quicker.                                                                                           
        if no_data_remaining:                                                                                     
            used_timeout = timeout                                                                                
            logging.warn('_read_response: no data remaining')                                                     
        else:                                                                                                     
            used_timeout = 0.01                                                                                   
            logging.warn('_read_response: data remaining')                                                        
        data_ready = select.select([self.sock], [], [], used_timeout)[0]                                          

        # check if there is anything more to do                                                                   
        if not data_ready and no_data_remaining:                                                                  
            logging.warn('_read_response: no data breaking out')                                                  
            break

2019-10-03 10:45:28 WARNING (SyncWorker_1) [root] list_accessories_and_characteristics
2019-10-03 10:45:28 WARNING (SyncWorker_1) [root] beginsleep
2019-10-03 10:46:58 WARNING (SyncWorker_1) [root] endsleep
2019-10-03 10:46:58 WARNING (SyncWorker_1) [root] STARTING NEW SESSION
2019-10-03 10:46:58 DEBUG (SyncWorker_1) [root] init session
removed some debug lines...
2019-10-03 10:46:58 DEBUG (SyncWorker_1) [root] session established
2019-10-03 10:46:58 DEBUG (SyncWorker_1) [root] handle request: b'GET /accessories HTTP/1.1\r\nHost: 10.6.6.229:7373\r\n\r\n'
2019-10-03 10:46:58 WARNING (SyncWorker_1) [root] _read_response: loop begin
2019-10-03 10:46:58 WARNING (SyncWorker_1) [root] _read_response: no data remaining
2019-10-03 10:47:28 WARNING (SyncWorker_1) [root] _read_response: no data breaking out
2019-10-03 10:47:28 WARNING (SyncWorker_1) [root] got response

ccormier on 3 Oct 2019

Yeah it is quite a pain to follow. I think you are right. Looks like _read_response can return an empty HttpResponse in that case. So its weirder than I thought - had assumed the encrypted session was set up and a HTTP service was running but returning an error http status code with no body. Instead the encrypted session is up but its returning a completely empty string.

The retry loop i was going to try based off @ccormier's report was something like this change to _entry_from_accessory in homeassistant/components/homekit_controller/config_flow.py:

    async def _entry_from_accessory(self, pairing):
        """Return a config entry from an initialized bridge."""
        # The bulk of the pairing record is stored on the config entry.
        # A specific exception is the 'accessories' key. This is more
        # volatile. We do cache it, but not against the config entry.
        # So copy the pairing data and mutate the copy.
        pairing_data = pairing.pairing_data.copy()

        # Use the accessories data from the pairing operation if it is
        # available. Otherwise request a fresh copy from the API.
        # This removes the 'accessories' key from pairing_data at
        # the same time.
        accessories = pairing_data.pop("accessories", None)
        if not accessories:
            while not accessories:
                try:
                    accessories = await self.hass.async_add_executor_job(
                        pairing.list_accessories_and_characteristics
                    )
                except Exception:
                    _LOGGER.exception("Error whilst retrieving pairing metadata")
                    # Clean up the session that just failed
                    pairing.session.close()
                    pairing.session = None
                    # Retry in 5s
                    import asyncio
                    await asyncio.sleep(5)
... snip....

Would be interested if that helped anyone.

Jc2k on 3 Oct 2019

I've removed the sleep and added the retry code. It loops indefinitely for me.

2019-10-03 14:03:07 WARNING (SyncWorker_2) [root] list_accessories_and_characteristics
2019-10-03 14:03:07 WARNING (SyncWorker_2) [root] STARTING NEW SESSION
2019-10-03 14:03:08 WARNING (SyncWorker_2) [root] _read_response: loop begin
2019-10-03 14:03:08 WARNING (SyncWorker_2) [root] _read_response: no data remaining
2019-10-03 14:03:38 WARNING (SyncWorker_2) [root] _read_response: no data breaking out
2019-10-03 14:03:38 WARNING (SyncWorker_2) [root] got response 
2019-10-03 14:03:38 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Error whilst retrieving pairing metadata
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 326, 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 86, 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-10-03 14:03:43 WARNING (SyncWorker_31) [root] list_accessories_and_characteristics
2019-10-03 14:03:43 WARNING (SyncWorker_31) [root] STARTING NEW SESSION
2019-10-03 14:03:43 WARNING (SyncWorker_31) [root] _read_response: loop begin
2019-10-03 14:03:43 WARNING (SyncWorker_31) [root] _read_response: no data remaining
2019-10-03 14:04:13 WARNING (SyncWorker_31) [root] _read_response: no data breaking out
2019-10-03 14:04:13 WARNING (SyncWorker_31) [root] got response 
2019-10-03 14:04:13 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Error whilst retrieving pairing metadata
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 326, 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 86, 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)

...snip...

2019-10-03 14:09:34 WARNING (SyncWorker_18) [root] list_accessories_and_characteristics
2019-10-03 14:09:34 WARNING (SyncWorker_18) [root] STARTING NEW SESSION
2019-10-03 14:09:34 WARNING (SyncWorker_18) [root] _read_response: loop begin
2019-10-03 14:09:34 WARNING (SyncWorker_18) [root] _read_response: no data remaining
2019-10-03 14:10:04 WARNING (SyncWorker_18) [root] _read_response: no data breaking out
2019-10-03 14:10:04 WARNING (SyncWorker_18) [root] got response 
2019-10-03 14:10:04 ERROR (MainThread) [homeassistant.components.homekit_controller.config_flow] Error whilst retrieving pairing metadata
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/config_flow.py", line 326, 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 86, 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-10-03 14:10:09 WARNING (SyncWorker_16) [root] list_accessories_and_characteristics
2019-10-03 14:10:09 WARNING (SyncWorker_16) [root] STARTING NEW SESSION
2019-10-03 14:10:09 WARNING (SyncWorker_16) [root] _read_response: loop begin
2019-10-03 14:10:09 WARNING (SyncWorker_16) [root] _read_response: no data remaining

ccormier on 3 Oct 2019

OK change of plan. Let's revert that and not fail hard at this stage of pairing. Make _entry_from_accessory like this:

    async def _entry_from_accessory(self, pairing):
        """Return a config entry from an initialized bridge."""
        # The bulk of the pairing record is stored on the config entry.
        # A specific exception is the 'accessories' key. This is more
        # volatile. We do cache it, but not against the config entry.
        # So copy the pairing data and mutate the copy.
        pairing_data = pairing.pairing_data.copy()

        name = f"{self.model} ({self.hkid})"

        # Use the accessories data from the pairing operation if it is
        # available. Otherwise request a fresh copy from the API.
        # This removes the 'accessories' key from pairing_data at
        # the same time.
        accessories = pairing_data.pop("accessories", None)
        if not accessories:
            try:
                accessories = await self.hass.async_add_executor_job(
                    pairing.list_accessories_and_characteristics
                )
            except Exception:
                 _LOGGER.exception("Failure whilst retrieving config entry metadata")

        if accessories:
            bridge_info = get_bridge_information(accessories)
            name = get_accessory_name(bridge_info)

        return self.async_create_entry(title=name, data=pairing_data)

The name of the config entry will now be less pretty, but the pairing should actually be saved. It likely still won't work but now we can try things like power cycling HomeAssistant and the thermostat. And we can inspect the config entry, too.

EDIT: Forgot a try/except in my haste

Jc2k on 3 Oct 2019

Gave it a shot. It shows up as a "configured" integration now, but with no devices. When restarting HA i get the following in the logs.

2019-10-03 15:32:36 WARNING (SyncWorker_31) [root] list_accessories_and_characteristics
2019-10-03 15:32:36 WARNING (SyncWorker_31) [root] STARTING NEW SESSION
2019-10-03 15:32:36 WARNING (SyncWorker_31) [root] _read_response: loop begin
2019-10-03 15:32:36 WARNING (SyncWorker_31) [root] _read_response: no data remaining
2019-10-03 15:33:06 WARNING (SyncWorker_31) [root] _read_response: no data breaking out
2019-10-03 15:33:06 WARNING (SyncWorker_31) [root] got response 
2019-10-03 15:33:06 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry S30 1B (A9:40:C7:55:C8:F8) for homekit_controller
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 190, in async_setup
    hass, self
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/__init__.py", line 187, in async_setup_entry
    if not await conn.async_setup():
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 129, in async_setup
    if await self.async_refresh_entity_map(self.config_num):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 177, in async_refresh_entity_map
    self.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 86, 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-10-03 15:33:06 WARNING (SyncWorker_30) [root] list_accessories_and_characteristics
2019-10-03 15:33:06 WARNING (SyncWorker_30) [root] _read_response: loop begin
2019-10-03 15:33:06 WARNING (SyncWorker_30) [root] _read_response: no data remaining
2019-10-03 15:33:36 WARNING (SyncWorker_30) [root] _read_response: no data breaking out
2019-10-03 15:33:36 WARNING (SyncWorker_30) [root] got response 
2019-10-03 15:33:36 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 177, in async_refresh_entity_map
    self.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 86, 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)

ccormier on 3 Oct 2019

Are you able to restart the thermostat?

Jc2k on 3 Oct 2019

I restarted, thermostat and thermostat hub, then HA. Same results in logs

ccormier on 3 Oct 2019

So the initial time.sleep before starting a new session is creating an exact delay as intended, but it obviously can't be counted on to ensure a reliable http response from an S30.

What about the separate timeout in SecureHttp ?
def __init__(self, session, timeout=10)

This is used in the select.select module where timeout is a _floating point_ value in seconds.

What's odd is that the logs show just a half-second differential between the session start/no data remaining, and when the loop breaks out. Clearly not 10.0 seconds. I'm not a Python programmer, but could there be a type/conversion issue here?

2019-10-03 15:33:06 WARNING (SyncWorker_30) [root] list_accessories_and_characteristics
2019-10-03 15:33:06 WARNING (SyncWorker_30) [root] _read_response: loop begin
2019-10-03 15:33:06 WARNING (SyncWorker_30) [root] _read_response: no data remaining
2019-10-03 15:33:36 WARNING (SyncWorker_30) [root] _read_response: no data breaking out
2019-10-03 15:33:36 WARNING (SyncWorker_30) [root] got response

GaryOkie on 4 Oct 2019

Found the source of the issue. It turns out the pairing was fine, the problem is when attempting to retrieve the accessories list. There is a bug related to size of the request, I don't know if this is on the sending or receiving side.

By padding the session.get /accessories request in the homekit library I can successfully list accessories.

Here is the workaround, minimum pad was 6 characters (padding the user-agent because it seemed clean, but padding can be elsewhere):
homekit/http_imp/secure_http.py

    def get(self, target):
        data = 'GET {tgt} HTTP/1.1\nUser-Agent: homekit-python/0.15.0\nHost: {host}:{port}\n\n'.format(tgt=target, host=self.host, port=self.port)

ccormier on 5 Oct 2019

Yes, it did seem like the pair-setup had worked, a new TCP stream had been created and that pair-verify had set up a secure session. It seemed unlikely pair-verify would pass if pair-setup had generated duff crypto keys. It's great that you have been able to verify this.

In summary:

By retrying and probably with luck @garyak got it working
By adding a massive sleep @skyway007 got it working
By padding the request size @ccormier was able to get things working

I'm at a loss as to how @ccormier case relates to @skyway007 and @garyak despite the obviously identical tracebacks so i feel like thats not the quite full story yet. Are their external factors at play? Magic external factors which might explain why what we think is happening isn't really?

Request size could change because DHCP has allocated the device a different IP
If thermostat incluces its clock in a custom characteristic response size could change because it is the start of the month. "5" is smaller than "25" and "October" is shorter than "September". Combined with the time, which is a smaller string in the AM.
The response could be smaller if the thermostat is reporting outdoor temperatures. (It's starting to get chilly where I am).

These tiny changes in size could bit us if our multi-block crypto is broken. But (1) isn't enough to account for 6 bytes of padding that @ccormier needs, and (2) and (3) don't change the size of the request. Are there any others?

A problem we have with padding is that adding new headers is "off spec". The tado thermostat chokes on fairly normal (but not HAP) HTTP headers. So we only use headers we've seen the real iOS client use. So we need to see why a actual iOS client works here and we don't. I'm pretty sure the headers we send are the same as an actual iOS client (though it has been a while since i checked).

The big difference i know about is the Host header. The spec is vague about what Host /should/ contain but in practice where an actual iOS client sends Host: devicename._hap._tcp.local:1234 we send Host: 123.123.123.123:1234. If we were accurate here this would obviously get us an extra few bytes.

The real question is, is this papering over a real bug in the encryption code on our side? Or is this a bug on their side? It feels like if we couldn't successfully encrypt small requests we would have hit this problem with other devices?

Jc2k on 5 Oct 2019

Good summary, I also believe that the different cases can be explained by environmental factors. Likely the IP addresses as you pointed out already. For example, the address of my "Host: " header is fairy short 10.6.6.229, whereas someone else is likely be using something like 192.168.100.200. Thats a different of 5 extra characters already, one short of my 6 required. That said it looks like most people would be right on the border of hitting that minimum magic size.

Re @skyway007 case: he did mention that he added some extra debugging lines, I'm curious if he also changed something in his headers or something to effect the size of the request. In my testing playing with timeouts alone wouldn't help.

My report of "6 characters" more is ambiguous, so here is some more data around it. The "extra" characters that I'm adding are the "123456" and "12345" in the "Host" header in the examples below.

Successful testcase:

python3 -m homekit.get_accessories -f ~/homekit -a s30
handle request: b'GET /accessories HTTP/1.1\r\nHost: 12345610.6.6.229:7373\r\n\r\n'
_handle_request len loop begin
unencrypted request data len: 58
encrypted request len: 76
encrypted request: b':\x00\x08\xf9v\xadmj1\xc9\xf6ZV/\x0c\x08\xa6\x1f\xb4\xea\xe96\xbf\t\xc4\xc2\x8a\x00\xcf\xa1\xc6|1\x0bF\x9c\x0f\x92d\x07\xfb\xb1\xc5\x81\xa9f\xa6Z$\t\x0b\xa5\xb9\x82\xa0j9\xd7su\x01\x0b\xe6\xab\x8c3l\xea\x0c\xf7Zln{av'
1.1: >accessory-information<
...snip...

Failed testcase

python3 -m homekit.get_accessories -f ~/homekit -a s30
handle request: b'GET /accessories HTTP/1.1\r\nHost: 1234510.6.6.229:7373\r\n\r\n'
_handle_request len loop begin
unencrypted request data len: 57
encrypted request len: 75
encrypted request: b'9\x00|\x8e\x8d\x88(\xa7\xcf\x86>\xa1\x1aa\x03(\x81\xcc\xb9T\xa2\x10Q\xd1\x81.\x06\xdd\x85 \xccE\xe7\xd4\xe4\x86\xaaDi\xe5\xcb\x07w\x11\xaf\xca\rU\x92\xdd\xeb\x14QBF\xc4\x98\x13\xe6\xd5\x01\xe6[\xe2\xf3\xa7j\x8c\x07]\xf1\x8d\xd9\xc5\xf1'
Expecting value: line 1 column 1 (char 0)

Re: multi crypto block
I believe this is working. Normally it's only creating a single block. I've also tried creating multiple blocks by reducing the len_data = min(len(data), 32). This forces the code to split my data up into 2 blocks and it is successful without the padded request. Summing up the 2 blocks resulted in a total request of size 88.

python3 -m homekit.get_accessories -f ~/homekit -a s30
handle request: b'GET /accessories HTTP/1.1\r\nHost: 10.6.6.229:7373\r\n\r\n'
_handle_request len loop begin
unencrypted request data len: 52
encrypted request len: 50
encrypted request: b" \x002J\x88\xe6.\xb4z\x9b\xfc\xf7\xbb\xd3\x96\x14\xd2\x9b\xf1n\xafqX\x8d1){\x85\xa2B']aV\x9c\xd6\x9f\x8e\xb4\\\x07\xfc\xcd\xdd\x9fb\n\x97\xf2*"
_handle_request len loop begin
unencrypted request data len: 20
encrypted request len: 38
encrypted request: b'\x14\x00\x1eq\xb0O{\xd2\x17\x95\xcd\x9f\x00\xba\xe6\t!gD\x9e\xaeIC\xf4\xff=B\x7f.\x15\xb6`@\x19\x93\xd0Er'
1.1: >accessory-information<
...snip...

In summary, based on my testing I believe that the thermostat is waiting for a minimum amount of data to be received before processing the request. maybe it's waiting for a buffer or a highwater mark to get hit before processing the request (ie. minimum 76 bytes received). I think a valid workaround could be to make the Host header be more iOS like as you described. That should stay within the spec, be more iOS like and work around an issue such as this. As coincidence would have it, setting my hostname to "._hap._tcp.local:7373" results in a 76 byte request after encryption :)

ccormier on 5 Oct 2019

If someone else would like to verify the request size theory you can use the following code.
homekit/http_impl/secure_http.py

    def _handle_request(self, data):
        logging.warn('handle request: %s', data)
        with self.lock:
            while len(data) > 0:
                logging.warn("_handle_request len loop begin")
                logging.warn("unencrypted request data len: %s", len(data))
                # split the data to max 1024 bytes (see page 71)
                len_data = min(len(data), 1024)
                tmp_data = data[:len_data]
                data = data[len_data:]
                len_bytes = len_data.to_bytes(2, byteorder='little')
                cnt_bytes = self.c2a_counter.to_bytes(8, byteorder='little')
                self.c2a_counter += 1
                ciper_and_mac = chacha20_aead_encrypt(len_bytes, self.c2a_key, cnt_bytes, bytes([0, 0, 0, 0]),
                                                      tmp_data)

                try:
                    request = len_bytes + ciper_and_mac[0] + ciper_and_mac[1]
                    logging.warn("encrypted request len: %s", len(request))
                    logging.warn("encrypted request: %s", request)
                    self.sock.send(request)
                except OSError as e:
                    raise exceptions.AccessoryDisconnectedError(str(e))

            return self._read_response(self.timeout)

ccormier on 5 Oct 2019

Count me in for testing this - but it will be at least another week before I can get onsite with the S30 to pair it. However, I can VPN to my remote site and run python test code, but I'm not sure how you set this get_accessories test case up.

I also can't tell what you changed (other than debug statements) in secure_http.py without dif'ing the original. I thought the most logical approach was to change the hostname to "._hap._tcp.local" to match the iOS client and also be a consistent 76 byte request?

Did you leave the original time.sleep(10) as-is, or do you recommend increasing it too?

FWIW, my S30 IP is 192.168.2.xxx (13 chars).

GaryOkie on 5 Oct 2019

The proper fix is to set the host header the same way as an iOS client (based on the bonjour data). But the bonjour discovery data isn’t available from this part of the code and we don’t save it in the pairing data yet. So we need to save it in the pairing data and fall back to the current mechanism for existing pairings.

Jc2k on 6 Oct 2019

@GaryOkie The code in https://github.com/home-assistant/home-assistant/issues/20885#issuecomment-538683053 will log some details around the request size. The work around would be to increase the size of your "request" by increasing the size the headers.
The following is where you would manipulate the headers(junk prefixing the {host} worked in my case). No timeouts or debugging code is required.
homekit/http_imp/secure_http.py

    def get(self, target):
        data = 'GET {tgt} HTTP/1.1\nHost: Xtrapadding123456X{host}:{port}\n\n'.format(tgt=target, host=self.host, port=self.port)

ccormier on 6 Oct 2019

Thanks @ccormier for the added context. The problem I face now is that I don't have a pairing file which is an essential component for running the get_accessories test. I understand that once HA successfully configures the Homekit accessory (which is not the case for me yet), the integration details are saved in the HA configuration.

Is it possible to manually create a pairing.json file from the following homekit.discover information (for testing purposes only)?

Name: iComfort S30 5185f0._hap._tcp.local.
Url: http_impl://192.168.1.23:7373
Configuration number (c#): 1
Feature Flags (ff): Supports HAP Pairing (Flag: 1)
Device ID (id): 4A:D4:7A:95:0A:42
Model Name (md): S30 2B
Protocol Version (pv): 1.0
State Number (s#): 1
Status Flags (sf): Accessory has been paired. (Flag: 0)
Category Identifier (ci): Thermostat (Id: 9)

EDIT:
I did try:
_python3 -m homekit.init_controller_storage -f /config/pairing.json_
which only created an empty pairing.json file, the best I could tell. Then I guessed at what might be a pairing file from the "demoserver.json" example in the documentation and created this:

{
  "name": " iComfort S30 5185f0._hap._tcp.local.",
  "host_ip": 192.168.1.23,
  "host_port": 7373,
  "accessory_pairing_id": "12:00:00:00:00:00",
  "accessory_pin": "123-45-678",
  "peers": {},
  "unsuccessful_tries": 0,
  "c#": 0,
  "category": "Thermostat"

}

Turns out this was not a good guess as the tests fail with "_homekit.exceptions.ConfigLoadingError: Cannot parse "/config/pairing.json" as JSON file"_

GaryOkie on 7 Oct 2019

That’s the pairing file for an accessory not a controller.

You can’t create a pairing file manually - it’s generated as part of doing the pairing crypto dance. Even if the syntax was valid your device is unpaired and would not trust your fake crypto keys.

Jc2k on 7 Oct 2019

ok, thanks @jc2k for clearing that up. So that counts me out as being able to run any further tests that require the pairing file.

Do you plan on providing an update that saves the iOS host header in the pairing data for examination? That's a test I can run when I get back to the remote site unless someone else is able to sooner.

GaryOkie on 7 Oct 2019

I’m going to try but it might be hard to retrofit into the existing API, so might just fix it in the new async/push event client PR I’m working on instead.

Jc2k on 7 Oct 2019

Hi @jc2k - I'm heading back to the S30 remote location now and will be able to try again later today with the HA pairing and any additional debugging or beta code you may want me to try. I've just now updated Hassio to .100.2 so I will be starting with the current production code unless I add back any logging (such as iOS host header capture).

I should have some time tomorrow for testing as well. Thanks!

GaryOkie on 14 Oct 2019

I went ahead and added the new logging @ccormier suggested to validate his request size theory, but there is a new and very significant variable that was just introduced by Lennox.

The S30 thermostat alerted me to a pending firmware update for Homekit (version 3.55.626). It was not automatically installed like other firmware updates have been. I have not found what this update involves, but I did notice that the S30 was now Bonjour broadcasting. Before the update, I had to initiate a Homekit factory reset and use an iOS device for WAC/wifi inclusion before it would broadcast and allow pairing.

Now, HA zeroconf immediately detects the S30 but since it was previously paired (unsuccessfully) to HA, it was ignored. I chose the S30 option to clear previous Homekit pairings instead of the full Homekit factory reset, so there was no need to enter WAC mode and use an iOS device in order to trigger pairing.

Once this incomplete pairing was cleared, the HA/zeroconf notification to configure the S30 appeared. Pairing was successful! Other than the logging statements, the only code change was the original timeout(10) @jc2k suggested. I did NOT add any padding to the header.

2019-10-15 10:41:27 WARNING (SyncWorker_4) [root] LIST_accessories_and_characteristics:  None                                                                                                                                            
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] STARTING NEW SESSION                                                                                                                                                                                                                                                                                                     
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] handle request: b'GET /accessories HTTP/1.1\r\nHost: 192.168.0.53:7373\r\n\r\n'                                                                                                        
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] _handle_request len loop begin                                                                                                                                                         
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] unencrypted request data len: 54                                                                                                                                                       
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] encrypted request len: 72                                                                                                                                                              
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] encrypted request: b'6\x00\x11\xed\<snip>'                                                                                                                                                                                                                                                                         
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] _read_response: loop begin...                                                                                                                                                          
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] _read_response: no data remaining, used_timeout=  10.0                                                                                                                                 
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] _read_response: loop begin...                                                                                                                                                          
2019-10-15 10:41:37 WARNING (SyncWorker_4) [root] _read_response: data remaining, used_timeout=   0.0                                                                                                                                    
2019-10-15 10:41:38 WARNING (SyncWorker_4) [root] GOT Response: {"accessories":[{"aid":1,"services":[{"characteristics":[{"format":"bool","iid":2,"perms":["pw"],"type":"14"},{"format":"string","iid":3,<snip>"}]}]}                                                                                                                                                                             
2019-10-15 10:41:38 WARNING (SyncWorker_2) [root] LIST_accessories_and_characteristics:  None                                                                                                                                            
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] STARTING NEW SESSION                                                                                                                                                                                                                                                                                      
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] handle request: b'GET /accessories HTTP/1.1\r\nHost: 192.168.0.53:7373\r\n\r\n'                                                                                                        
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] _handle_request len loop begin                                                                                                                                                         
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] unencrypted request data len: 54                                                                                                                                                       
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] encrypted request len: 72                                                                                                                                                              
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] encrypted request: b"6\x00\xd9\xf2\..."                                                                                                                                                                                                                                                                             
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] _read_response: loop begin...                                                                                                                                                          
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] _read_response: no data remaining, used_timeout=  10.0                                                                                                                                 
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] _read_response: loop begin...                                                                                                                                                          
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] _read_response: data remaining, used_timeout=   0.0                                                                                                                                    
2019-10-15 10:41:48 WARNING (SyncWorker_2) [root] GOT Response: {"accessories":[{"aid":1,"services":[{"characteristics":[{"format":"bool","iid":2,"perms":["pw"],"type":"14"},{"format":"string","iid": <snip> ,"type":"A2"}]}]}

Then once a minute, the following logging statements repeat (with different encrypted request data). The request lengths are all the same (91/109).

2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] handle request: b'GET /characteristics?id=1.101,1.102,1.103,1.104,1.107 HTTP/1.1\r\nHost: 192.168.0.53:7373\r\n\r\n'                                                                  
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] _handle_request len loop begin                                                                                                                                                        
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] unencrypted request data len: 91                                                                                                                                                      
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] encrypted request len: 109                                                                                                                                                            
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] encrypted request: b'[\x00"\x9b\xe8\x92\<snip>'                                                                                                                                                                                     
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] _read_response: loop begin...                                                                                                                                                         
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] _read_response: no data remaining, used_timeout=  10.0
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] _read_response: loop begin...
2019-10-15 10:42:49 WARNING (SyncWorker_16) [root] _read_response: data remaining, used_timeout=   0.0

I think there is a good chance that this Lennox Homekit firmware update may have also fixed the handshaking issues and that my successful pairing wasn't a random good luck thing. It sure seems to have fixed the bonjour broadcast/WAC/iOS requirement pairing issues.

GaryOkie on 15 Oct 2019

Both my Smart Hubs were updated on 9/27 with 3.55.0219. No indications of pending firmware updates.

garyak on 15 Oct 2019

double-checked... My Lennox SmartHub (model 105081-03) firmware is 3.55.0626, which matches the Homekit version reported via zeroconf to HA.

It shouldn't matter, but for reference, my S30 Thermostat (model 104553-01) firmware is 3.50.0148.

In the general/about menu, you can select automatic updates and check for software updates. My Tstat and Hub are both set for automatic updates, but this morning I saw a little red message notification icon on the main screen, which said a Homekit firmware update was available to install.

GaryOkie on 15 Oct 2019

@GaryOkie i am reluctant to suggest it now that you have it working, but are you able to revert all changes and then try pairing again with a vanilla install?. If it works are you able to try again a couple of times? (You'll need to remove in from integrations menu in home assistant, restart HA and then use the S30 option to clear previous Homekit pairings.

Jc2k on 15 Oct 2019

Just for full disclosure, we have the same thermostats (104553-01), but different Smart Hubs. Mine are listed as 104329-01.

garyak on 15 Oct 2019

Ok @jc2k - will do. As I had mentioned, the only code changes other than the logging was I kept the _import time; time.sleep(10)_ delay in ip_implementation. I had already removed all the logging but I will remove the sleep as well and reset/repeat the pairing.

back soon with an update...

GaryOkie on 15 Oct 2019

Good news @jc2k - using production code, I was able to repeat the pairing process 3 times with no problems at all!

GaryOkie on 15 Oct 2019

That is wonderful news indeed :-)

Jc2k on 15 Oct 2019

It is working for me as well, paired on the first try! Thank you very much :)

jeromelaban on 16 Oct 2019

Would someone with an iComfort S30/M30/E30 please temporarily enable the "wider temperature setpoints" (under settings/heat&cool)? This will change the allowed range from 60-90 to 40-99 (F).

What is being reported to HA via the Homekit integration is an incorrect min_temp=60, instead of 40. The max_temp is correct at 99. I'm unable to set the temp lower than 60 via HA, but it works fine via the thermostat touchpad or iComfort app.

Can this min_temp reporting problem be duplicated by anyone?

Thanks!

GaryOkie on 16 Oct 2019

With wider set points set on the S30, HA reports min 40, max 90. Unfortunately these settings, when made from HA, don't reflect back to the S30.

The lovelace card returns to 60 degrees, or 40 depending on your setting at the S30.

garyak on 16 Oct 2019

Thanks @garyak for testing. Your reported wide min/max setpoint range is different I am seeing and I think that may be because my Tstat was in cool mode and yours was in Heat mode. The default range is 60-90 and the optional wider range is 40-99. I don't think it is correct to have either a 40-90 or 60-99 range reported, regardless of which mode the Tstat is in.

@jc2k - I have the original debug GET_Accessories output from when the S30 first paired and have compared it to the _homekit_controller-entity-map_ pairing file, and both agree.

There appear to be two relevant Homekit IID's pertaining to temperature range...
IID: 106 (COOL Mode?) shows a range of 15.5-37 C, which is 60-99F, the exact values I'm seeing.
IID: 108 (HEAT Mode?) shows a range of 4.5-32 C which is 40-90F, the exact values @garyak gets.

I have since switched from Cool to Heat mode since the pairing was done, but the range has not changed for me - it is still 60-99. Problem is, I need to remotely lower the temp below 60 for an empty vacation cabin that is winterized and can't do it via HA/Homekit, only via the iComfort app which properly honors the wider setpoint range of 40-99.

Formatted debug output follows:

accessories:[ |  
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":"S30   2B",
format:"string","iid":5,"perms":["pr"],"type":"23","value":"iComfort   S30 xxxxx",
format:"string","iid":6,"perms":["pr"],"type":"30","value":"WL18Exxxxx",
format:"string","iid":7,"perms":["pr"],"type":"52","value":"3.55.626",
format:"string","iid":8,"perms":["pr"],"type":"53","value":"3.0.002"],"iid":1,"type":"3E",

characteristics:[ |  
format:"uint8","iid":101,"maxValue":2,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"F","value":0,
format:"uint8","iid":102,"maxValue":3,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"33","value":2,
format:"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":21.5,
format:"float","iid":104,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"35","unit":"celsius","value":26.5,
format:"uint8","iid":105,"maxValue":1,"minStep":1,"minValue":0,"perms":["pr","pw","ev"],"type":"36","value":1,
format:"float","iid":106,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"D","unit":"celsius","value":26.5,
format:"float","iid":107,"maxValue":100,"minStep":1,"minValue":0,"perms":["pr","ev"],"type":"10","unit":"percentage","value":60,
format:"float","iid":108,"maxValue":32,"minStep":0.5,"minValue":4.5,"perms":["pr","pw","ev"],"type":"12","unit":"celsius","value":19.5,
format:"string","iid":109,"perms":["pr"],"type":"23","value":"Thermostat"],"iid":100,"primary":true,"type":"4A",

characteristics:[ |  
format:"string","iid":301,"perms":["pr"],"type":"37","value":"1.1.0"],"iid":300,"type":"A2"]]

And a snip from the pairing file...

"iid":   106,
--
"maxValue": 37,
"minStep": 0.5,
"minValue": 15.5,
"type":   "0000000D-0000-1000-8000-0026BB765291",
"unit": "celsius",
"value": 25
  |  
"iid": 108,
"maxValue": 32,
"minStep": 0.5,
"minValue": 4.5,
"type":   "00000012-0000-1000-8000-0026BB765291",
"unit": "celsius",
"value": 19.5

And finally, HA climate.icomfort_s30 entity state:

State: HEAT
Attributes:
hvac_modes: off,heat,cool,heat_cool
current_temperature: 65
min_temp: 60
max_temp: 99
temperature: 60
current_humidity: 55
hvac_action: on
friendly_name: Downstairs iComfort S30
supported_features: 1

GaryOkie on 17 Oct 2019

After restarting HA while the S30 is in Heat mode, I am now getting a min/max range of 40-90, the same as @garyak. I'll just have to remember to restart HA any time the mode is changed to get the new range. Not sure why, but I can live with that.

Evidently Lennox hardcoded their Homekit interface to use the 40-90F min/max range for Heat, and 60-99F for Cool. The option to enable a wider setpoint range regardless of mode is not honored by the Homekit interface and seems to be only relevant for the Tstat and iComfort app the best I can tell.

LOL - I switched back to Cool mode, restarted, and the range is still 40-90. Oh well, that range is fine, even though it beats me how/when this Homekit component refreshes attributes.

GaryOkie on 17 Oct 2019

So what is supposed to happen is the thermostat bumps the c# attribute whenever the attribute database changes. This is broadcast by bonjour and HA should see it and pull the latest "entity map". Could be the comfort is always updating the attributes but not always updating c# in a timely fashion or we aren't noticing. You could use the CLI to see if c# is changing. If it's not, theres not much i can do their implementation is buggy. If it is, its my problem to sort out (:sob:).

RE: The 2 UUID's you posted - they are the cooling and heating thresholds and are apparently only applicable to Auto mode. We don't support them yet, mostly because i don't have a way to test what happens.

Jc2k on 17 Oct 2019

Thanks for the info! I have checked the timestamp of _.storage/homekit_controller-entity-map_ and noticed that it doesn't change when I change heat/cool modes or temp values from either the HA UI or the iComfort app. It also doesn't change after an HA restart.

So what is this CLI you mention and how do I use it to see if c# is changing? I know of C#, the programming language, but not the "c#" you are referring to.

Do you have a documentation link that describes the UUID's? I've tried, but not found one yet. Still don't understand where HA is getting the temperature ranges from if 106/108 only apply to Auto mode that isn't supported by the component. And since it's not supported, why is "Heat_Cool" being reported as an available mode and show up as a button on the climate card? Isn't that Auto mode?

EDIT: On second thought, by "CLI", you mean the SSH/Bash terminal into HA?

GaryOkie on 17 Oct 2019

The cli ships with the library we use to make the HA integration:

https://github.com/jlusiardi/homekit_python/

It should be already installed in your HA install so it should be enough to do something like:

python3 -m homekit.discover

And after about 30s you should see output like this:

Name: smarthomebridge3._hap._tcp.local.
Url: http://192.168.178.21:51827
Configuration number (c#): 2
Feature Flags (ff): Paired (Flag: 0)
Device ID (id): 12:34:56:78:90:05
Model Name (md): Bridge
Protocol Version (pv): 1.0
State Number (s#): 1
Status Flags (sf): 0
Category Identifier (ci): Other (Id: 1)

(This is the data that we use to detect the devices available to pair)

Jc2k on 17 Oct 2019

bash-5.0# python3 -m homekit.discover

Name: iComfort S30 5185f0._hap._tcp.local.
Url: http_impl://192.168.0.53:7373
Configuration number (c#): 2
Feature Flags (ff): Supports HAP Pairing (Flag: 1)
Device ID (id): 4A:D4:7A:95:0A:42
Model Name (md): S30 2B
Protocol Version (pv): 1.1
State Number (s#): 1
Status Flags (sf): Accessory has been paired. (Flag: 0)
Category Identifier (ci): Thermostat (Id: 9)

EDIT: Ah, just now see the c# number!

GaryOkie on 17 Oct 2019

:-) As it is currently 2 it seems it does not change when you change between heat and cool. But you should be able to change settings on the thermostat and verify.

As for the UUID documentation, you can download the official spec here:

https://developer.apple.com/homekit/specification/

You'll need an Apple ID but i don't think you need to be in the paid for developer program or anything like that.

For the 2 you called out it says:

This characteristic describes the cooling threshold in Celsius for devices that support simultaneous heating and cooling. The value of this characteristic represents the 'maximum temperature' that must be reached before cooling is turned on.

For example, if the Target Heating Cooling State (page 161) is set to "Auto" and the current temperature goes above the 'maximum temperature', then the cooling mechanism should turn on to decrease the current temperature until the 'minimum temperature' is reached.

and

This characteristic describes the heating threshold in Celsius for devices that support simultaneous heating and cooling. The value of this characteristic represents the 'minimum temperature' that must be reached before heating is turned on.

For example, if the Target Heating Cooling State (page 161) is set to "Auto" and the current temperature goes below the 'minimum temperature', then the heating mechanism should turn on to increase the current temperature until the 'minimum temperature' is reached.

There are 2 key things in these that have made me reluctant to press ahead with making arbritary changes:

"This characteristic describes the X threshold in celsius for devices that support simultaneous heating and cooling"
"For example, if the target heating cooling state is set to "auto" and..."

Clearly in some cases we need to respect these characteristics and in others we need to respect the target temperature characteristic (like we do now). But IMO it is vague and it doesn't say it is OK to refer to these threshold characteristics when not using the "auto" ("heat_cool") mode. I would say it implied that you shouldn't But it doesn't explicitly ban that either. My hope is that if the characteristic is present we should just use it for all relevant modes over the "target temperature" one.

Ultimately i'm going to have to build a mock thermostat accessory and verify which characteristics are surfaced in the iPhone UI in which circumstances - but thats a lot more work than i have time to do right now.

Jc2k on 17 Oct 2019

@GaryOkie are you able to modify temperature settings from HA? All I can do is On/Off and change modes. HA Current temp and Humidity values accurately reflect thermostat readings.

garyak on 17 Oct 2019

Hi @Garyak - Yes, I'm able to modify temps from HA - at least according to the iComfort app which updates within several seconds of any HA change. I'm not at the remote S30 site to see it first hand, but the iComfort app must be showing the actual status.

GaryOkie on 18 Oct 2019

@jc2k - thanks for providing the link to the Apple Homekit docs.

I see in the official doc, that Current Temperature (IID 103) has an Apple-defined min/max range of 0-100 C, and this is exactly the characteristic that is being reported by the S30 and recorded in the pairing file.

format:"float","iid":103,"maxValue":100,"minStep":0.1,"minValue":0,"perms":["pr","ev"],"type":"11","unit":"celsius","value":21.5

Clearly Lennox hardcoded their min/max temp range to match the spec rather than pass the normal min/max ranges set on the thermostat. But why is the Homekit controller component ignoring the current temp range 0-100C and picking up the hardcoded trigger point ranges for the Auto Heat or sometimes Auto Cool instead?

This wouldn't be an issue for me except when the component sometimes decides to set the minimum heat to 60F.

EDIT - my apologies... I should have looked at TARGET Temperature (IID 104), not current temp. I see now the Apple-defined min/max range is 10-38C. The S30 originally passed a range of 15.5-37C (60-99F). However, I see that the S30 Heat state remains at min_temp: 40F and max_temp: 90F. (But that may be because I have changed from cool to heat mode).

format:"float","iid":104,"maxValue":37,"minStep":0.5,"minValue":15.5,"perms":["pr","pw","ev"],"type":"35","unit":"celsius","value":26.5,

GaryOkie on 18 Oct 2019

Your edit is correct, we are currently using the target temperature min and max values.

My next step is to make a mock thermostat with homekit_python which has the target temperature, heating threshold and cooling threshold characteristics. I will give each of the 3 different min and max values. Will then pair with an iOS device and see which of the 3 min/max ranges it uses in each of the 3 operating modes. Hopefully this will show that iOS prefers the heating and cooling thresholds if they are present, regardless of operating mode. This will mean that we have a way forward.

If it shows my narrow interpration of the spec holds, and that the heating and cooling thresholds are only for heat_cool mode (i.e. auto mode) then we are somewhat stuck. I could potentially add a "force reload" service for the characteristics database. But I don't want to dwell on this until we have been able to verify the "nice fix" is a no go.

In the mean time if you delete your homekit_controller-entity-map and restart HA it should fetch the latest one. You could verify this does cause the target temperature to update (without a change to c#). Worth taking a copy just in case it doesn't, i guess.

Jc2k on 18 Oct 2019

OK @GaryOkie . For Heat and Cool modes I can adjust temperature set points. For Heat/Cool, I cannot. I believe I understand now what you and @Jc2k are discussing.

garyak on 18 Oct 2019

That sounds great @jc2k as a potential way forward! I am quite happy with the functionality I now have and greatly appreciate all the attention you have been giving to improve this component.

@garyak - I don't use the Auto (Heat/Cool) mode, but I'll do some testing with it.

EDIT: I see what you mean now - there isn't any way I've found to set the separate heat setpoint and the cool setpoint for heat/cool mode. I currently use the simple-thermostat lovelace card, but it has the same limitation as the official thermostat card. Even though both provide a heat/cool button, there is only a single setpoint.

Now, there is a dual-thermostat card that has a nice dual setpoint capability, and it works just like the iComfort app round slider. I tried using it, but it seems to require two separate entities for heat and cool. Giving it the same S30 entity for both heat/cool didn't work. This has to be a common issue, but I haven't found a solution yet.

GaryOkie on 18 Oct 2019

I can also confirm successful pairings and retrieval of the accessory list after updating the homekit firmware on the S30 on HA release code.

ccormier on 19 Oct 2019

Shouldn't it be possible to set the hvac_action attribute as IDLE, instead of OFF, when the HVAC unit is not actually turned off?

GaryOkie on 7 Nov 2019

Another question. Are the Fan settings exposed by the API?

garyak on 7 Nov 2019

Nope, looking through the Apple Homekit HAP R2 non-commercial spec, there are no references to Fan settings or status for the Thermostat accessory.

GaryOkie on 7 Nov 2019

Do without I guess. Thanks for checking.

garyak on 7 Nov 2019

@Jc2k -
The Homekit "Current Heating/Cooling State" shows possible values of _0=Off; 1=Heat is on; 2=Cooling is on_. I think that in this context, "Off" really means the hvac_action should be "Idle".

The "Target Heating/Cooling State" of 0=OFF is what is used to turn off the unit (hvac_mode). I don't see any other setting that can indicate if the unit is actually off, but it would probably be best to set hvac_action to off based on this target 0 value.

GaryOkie on 7 Nov 2019

We should probably take any new issues to new tickets from now on guys, the pairing issue is resolved by the firmware (no one has said otherwise yet) and i'm going to lose track of what else is and isn't resolved. (Feel free to @ me directly for homekit stuff).

I think you are probably right about this @GaryOkie. I don't have any spare cycles right now but if you were to submit a PR to update the mapping here i would be able to review it.

I'm fine with simply replacing CURRENT_HVAC_OFF with CURRENT_HVAC_IDLE, i'm less certain about inferring the hvac_action is CURRENT_HVAC_OFF when the hvac_mode is HVAC_MODE_OFF. I think i'd prefer to not do that now, unless it is causing a reduction in functionality in the Home Assistant UI or someone demonstrates that's what the official HomeKit app is doing for its UI.

Jc2k on 7 Nov 2019

Thanks - I've only done a PR on documentation before, not yet for code, but will give it a shot if it's just a simple matter of remapping.

The most important thing is to define hvac_action as idle (or heating, or cooling) when the unit is on, and off otherwise. The thermostat operation state is working properly and shows off, when the unit is off, and heat/cool/heat_cool when on.

EDIT: Another thermostat component I tried returned Hvac_action to Idle (not off) when the system was turned off. So yeah, this simple remapping of 0=CURRENT_HVAC_IDLE should suffice.

And I agree - this original E30 pairing issue should be closed, with the advice that the latest firmware needs to be installed.

GaryOkie on 7 Nov 2019

I'm going to close this because pairing now seems to be working.

If you are waiting for support the temperature ranges in heat/cool mode, you can track this ticket.

Cheers

Jc2k on 2 Jan 2020

Core: Invalid Lennox E30 pairing flow via HomeKit controller

All 123 comments

Successful testcase:

Failed testcase

Related issues