HomeKit_Controller not turning switch on

rdariolemes commented 4 years ago

The problem

While using homekit_controller with my Ecobee switch+ i'm unable to turn light on. Turn off function and sensors that come with the switch update accordingly but turn on function is not working. Tested by unpairing from HA and configure on phone as HomeKit accessory and turn on function works as expected

Environment

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

Problem-relevant `configuration.yaml`

Traceback/Error logs

No errors detected

Additional information

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

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

Jc2k commented 4 years ago

@rdariolemes can you try with 0.107.5? There were a couple of fixes for homekit_controller in there that might be applicable.

Can you confirm that turn_on feature worked in 0.105.x?

If 0.107.5 doesn't help can you turn on verbose debug logs and attach one here. In needs to show from when you start HA to when you trigger the problem please.

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

rdariolemes commented 4 years ago

@Jc2k ,

can you try with 0.107.5? There were a couple of fixes for homekit_controller in there that might be applicable.

Already did and still doesn't work.

Can you confirm that turn_on feature worked in 0.105.x?

Yes. Just recently started failing. I didn't report earlier as I thought it was an issue with a code update Ecobee had pushed out but they dismissed this by advising to test with native HomeKit which I did and works as expeted.

If 0.107.5 doesn't help can you turn on verbose debug logs and attach one here. In needs to show from when you start HA to when you trigger the problem please.

I already enabled the logs. Can you advise if there is an easy way of collecting all the logs in a file from boot till I reproduce the issue?

Thanks

Jc2k commented 4 years ago

Sorry how to collect the logs is very environment specific. I don't know Hass.io at all.

Did it work in 0.106.x or did you skip that version?

rdariolemes commented 4 years ago

Did it work in 0.106.x or did you skip that version?

I skipped that version.

See logs here: home-assistant.zip

Jc2k commented 4 years ago

Brilliant. Thanks for your help with this.

So first of all in the logs I can see you toggle a device on an off a bunch of times:

2020-03-23 14:39:17 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 60\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": false}]}'
2020-03-23 14:39:17 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')
2020-03-23 14:39:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'
2020-03-23 14:39:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')
2020-03-23 14:39:22 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 60\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": false}]}'
2020-03-23 14:39:22 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')
2020-03-23 14:39:24 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'
2020-03-23 14:39:24 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')
2020-03-23 14:39:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 60\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": false}]}'
2020-03-23 14:39:26 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')
2020-03-23 14:39:27 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.89.101\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'
2020-03-23 14:39:27 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.89.101: raw response: bytearray(b'')

You turn it off, on, off, on, off, on. The device does not report an error.

Polling happens as normal. One of your accessories (not sure which one) is reporting an error (like a bridge where the accessory is out of range?). I don't think its an Ecobee Switch. I can see 7 devices get polled and the on/off state of them all. All of them were off apart from one.

I'm going to have a think about some extra logging we can add to get a better understanding of what is happening, as these seem to not be reporting any problems at all.

rdariolemes commented 4 years ago

@Jc2k ,

One of your accessories (not sure which one) is reporting an error (like a bridge where the accessory is out of range?)

That's my appleTV which is currently offline.

If i turn on the device manually and then turn it off using HA it works no problem. But if I try to turn it on it does nothing. Not even toggle works.

Let me know what other information you need from my end.

Thanks

Dan320neo commented 4 years ago

Hi

I think i can report a similar issue with two myStrom Energy Control/Switches. They worked perfectly before and stopped working on the update to 0.107.5. (Not sure if i was on a .107 version before) I found that after the update the switches didn't work anymore but the sensors did still report temperature. I thought a factory reset and rediscover may solve the problem, but now i can't add them to HA anymore. HA finds them as new accessories and upon entering the Homekit pairing code it gives me an error saying "An unhandled error occurred while attempting to pair with this device. This may be a temporary failure or your device may not be supported currently." Not sure if it's a related issue or something else.

Thank you for looking into it

Jc2k commented 4 years ago

@rdariolemes im talking about a homekit error not the appletv error. if you can tell me how to pair my apply tv with homekit controller i'd be very interested so i can test upgrades with it.

@Dan320neo unfortunately factory reset has never been the answer to a homekit_controller problem :-( Pairing is the hardest bit, so most likely to fail. Can you open a seperate ticket for the re-pairing problem, i don't want to confuse things here. When we get you re-paired you can join in here. Hard to juggle 2 seperate issues in the same ticket. Make sure you include all the information in the template and attach your logs. As you will have seen in this ticket, please set your logging config as follows:

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

Jc2k commented 4 years ago

@rdariolemes do you know how to get to the home assistant code on your hass io box and change it?

rdariolemes commented 4 years ago

@Jc2k , can you elaborate? U mean upgrade to newer code?

Jc2k commented 4 years ago

@rdariolemes given the nature of your problem (specific to a subset of devices none of which i own) the only way i can fix this is if someone is able to make line by line changes i request with a text editor. At first this will just be extra logging. I could push some of this in a release but the time it takes to get to you means that it might take multiple releases to get enough information - each weeks apart. When I move on to the fixing it stage it might be that you need to test it actually works. I can't do that through a release because it might break things as it would be untested by nature.

You said you are using HA OS - that complicates things as the code is inside a docker container. And HA OS SSH might not let you access a real shell. So if you aren't used to docker and linux command lines this can be tricky.

Does that make sense? Can you help with this?

CAB426 commented 4 years ago

@Jc2k I am also seeing this exact issue, but also running on docker. I am familiar with docker and linux, however I have not been able to find the code files for HA. I am not sure if they are available in docker. I checked the python site-packages folder, but there is nothing there.

Any chance we could build this as a custom-component to test?

Jc2k commented 4 years ago

@CAB426 can you confirm specifically that turn_off works and turn_on doesnt? Can you also confirm the type of device?

If the code files weren't in the home-assistant container then you wouldn't have a working system!

On a normal debian/ubuntu docker host i do docker ps then docker exec -it <container_id> sh. From there:

ls /usr/src/homeassistant/homeassistant/components/homekit_controller/
__init__.py             alarm_control_panel.py  config_flow.py          cover.py                lock.py                 sensor.py               switch.py
__pycache__             binary_sensor.py        connection.py           fan.py                  manifest.json           storage.py
air_quality.py          climate.py              const.py                light.py                media_player.py         strings.json

and

ls /usr/local/lib/python3.7/site-packages/aiohomekit
__init__.py    __pycache__    controller     exceptions.py  model          testing.py     zeroconf
__main__.py    const.py       crypto         http           protocol       utils.py

Does that help?

At the moment there is nothing to build as a custom component. Reluctant to go down that route as then i have to try and explain how to do something i dont use myself.

CAB426 commented 4 years ago

@Jc2k Confirming that turn_off works correctly, and turn_on does not - turn_on turns OFF the device. I am using an Ecobee Switch+.

Those commands helped greatly. I am in there and see the files in both directories.

Jc2k commented 4 years ago

Okie dokie. First of all make sure you have this logging config

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

Then replace /usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py with https://gist.githubusercontent.com/Jc2k/11c2a53ebb1de1810655bb8758dbb132/raw/b66595ffbdb5a915875d44e22bbe002667e7df4c/connection.py. Restart HA. Turn the switch on and off a few times.

If you can, tail the logs. It would be really interesting if you toggled the switch in HA then watched the log for the next "Finished HomeKit controller update". Then try and toggle it again, then wait for the next "Finished HomeKit controller update". Then send me the logs.

I am on discord as Jc2k#6068 if you'd feel happer PMing me the logs.

In @rdariolemes's case it looked like turn on and turn off commands were being processed and accepted. But i couldn't see the raw response from the device in full, with this connection.py change in place we can see it in full. Additionally i couldn't see what state HK was reporting. By waiting for "Finished HomeKit controller update" after each toggle i can see what state HK reports at each step.

Finally, if possible can you toggle the switch on the device a couple of times? I want to verify that it generates events as well.

rdariolemes commented 4 years ago

@Jc2k , I just PM in Discord. Do u want us to meet so we could have a virtual meeting and troubleshoot this? You could do any live testing and get logs as needed.

Let me know

Jc2k commented 4 years ago

@CAB426 @rdariolemes Anyone had any luck with these steps so far? I should be free in a bit if so.

CAB426 commented 4 years ago

Haven't had a chance to look at it. I am tied up most likely until this evening (Pacific Time). Hoping to be able to get you some logs by the end of the day.

Jc2k commented 4 years ago

Brilliant - GMT here so will be see you on the other side!

rdariolemes commented 4 years ago

@Jc2k , instructions doesn't work in hass.io Anything else I could try?

CAB426 commented 4 years ago

@Jc2k Here are my logs. I couldn't test the physical switch tonight but can do so tomorrow during the day. hk_logs.txt

Jc2k commented 4 years ago

@rdariolemes i don't know enough about that platform to help i'm afraid. pretty sure they would be enough if you could get to the Home Assistant docker container inside HA OS but i'm not familiar with how you do that.

@CAB426 Thank you very much for the logs. So let me talk you through what i see.

The characteristic we are toggling has an iid of 17.
At the start of this run, that characteristic is off.
You toggle it a bunch of times. I see 6 toggles. On, off, on, off, on, off.
It tries to read the state and the connection is dropped without any error from the ecobee side.
There is a timeout while trying to do the next toggle as it hasn't finished reconnecting.
When it reconnects it enables events.
Then i set more writes to 17. On twice.
Then it polls. The device actually tells us that iid 17 is ON (!!)
Then more writes to 17. Off, on.
Then it polls. The device is still on.
Then it polls. The device is still on.
Then you write to 17. Off, on.

The 2 things that are interesting to me from this are:

Every single write apart from the timeout was reported as successful. This appeared to be the case for @rdariolemes too, and here with the more detailed looks its confirmed. All those "204 No Content" messages are succesful writes.
Turning the characteristic on and then reading it back gives us the correct value as well.

Both of these things make me question if there is even a problem! The device is saying, "yep it worked" and when i ask it if its sure its saying "yep look everything worked". But yet I have 2 users with the same device reporting the same weird problem.

Now I would suggest backing up /config/.storage/homekit-controller-entity-map (/config is where your configuration.yml lives) and deleting it (or moving it to homekit-controller-entity-map.bak then restarting HA. It woul refetch the data and it should be identical. This would test if a firmware update had changed the iid we needed to write to. And I think we probably should test that. But @rdariolemes unpaired and repaired which should have the same effect.

The only other thing to try is to send me your /config/.storage/homekit-controller-entity-map and i can check it for any new characteristics HA doesn't know about and iPhone does or something like that.

TL;DR - these logs see to mostly absolve the transport layer (including encryption layer). This bit changed substantially in 0.107.0. But despite this the devices are accepting and confirming our writes have been accepted. So next we need to validate the entity mapping layer (how we identify the iid that belongs to the switch on/off state).

CAB426 commented 4 years ago

@Jc2k Thank you for looking through this. I tried a couple more things just to get a bit more information for you.

I removed the switch from HA and deleted the (empty) homekit-controller-entity-map
I reset the switch and started from scratch.
I added the switch to HomeKit directly, and all functionality and sensors work.
I reset the switch again.
I added back to HA.
Unfortunately, no difference in functionality in HA for the switch. I will say the sensors are reporting correctly though so communication seems to be working.

Here is my homekit_controller-entity-map.txt

Please let me know if there is anything else I can provide. Thanks for your help!

Jc2k commented 4 years ago

Cheers, i'll try and look at this in a bit. Did you happen to notice if it's still sending the writes to iid 17 in your logs? Should look like this:

2020-03-24 20:28:17 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 1.2.3.4: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 1.2.3.4\r\nContent-Type: application/hap+json\r\nContent-Length: 60\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'

rdariolemes commented 4 years ago

@Jc2k , i believe this broke after latest upgrade where sensor update immediately on HA. I didn't see any issues prior to that. Is there any way to rollback to previous version for testing?

Jc2k commented 4 years ago

Technically yes, but I can't support you with rollbacks. It could make it worse (other integrations might not rollback cleanly). And I don't have enough information about your config to help or anything.

You could remove the pairing and pair it with a blank fresh copy HA at an older version. That would be the safest thing. I have a "prod" and "dev" instance of HA running at home.

CAB426 commented 4 years ago

@jc2k Yes, I am still seeing it sending the writes to iid 17, both true and false.

2020-03-25 14:00:31 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 10.0.10.105: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 10.0.10.105\r\nContent-Type: application/hap+json\r\nContent-Length: 60\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": false}]}'
2020-03-25 14:00:27 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 10.0.10.105: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 10.0.10.105\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'

Jc2k commented 4 years ago

@CAB426 And you see a 204 No Content response to go with both of those?

CAB426 commented 4 years ago

@jc2k I see this:

2020-03-25 14:00:27 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 10.0.10.105: raw response: bytearray(b'')

Jc2k commented 4 years ago

Yeah a 204 has no body which is why it prints that. when you sent me logs last time we had blocks like this:

2020-03-24 20:26:00 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b'\x1b\x00D\xaf\xd3\x19\x9bQ\xbc&J{\x86\xca=\xac\x9d\xdc\x05&9\xff\x8e\x1b+x\x16\x83g\x81\xa0\xa0\xe6\x9d\x18\xeb*\xcb\x99\x9c\xbf\xdf\x98\xc0\xff'
2020-03-24 20:26:00 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'HTTP/1.1 204 No Content\r\n\r\n')
2020-03-24 20:26:00 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 1.2.3.4: raw response: bytearray(b'')

Still have those?

CAB426 commented 4 years ago

@jc2k I realized I updated HA in a haze last night when playing around trying to work through this and forgot to replace connection.py with the one you provided. I just did so and rebooted HA. Here is the full log from a turn_on request:


2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 10.0.10.105: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 10.0.10.105\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'
2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE send_bytes b'PUT /characteristics HTTP/1.1\r\nHost: 10.0.10.105\r\nContent-Type: application/hap+json\r\nContent-Length: 59\r\n\r\n{"characteristics": [{"aid": 1, "iid": 17, "value": true}]}'
2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE write: b'\xa7\x00\x17}m\x10\xd5i\xa3?d\x0e"\xe5\xd4\xdbv\xb4B\xe8\x91\xf0*\x86\x80i\x93V\xc8\t\x01E@t\x1f%\xa5\xa3\xf6\xbd\xbcF\xc6\xe7f\xe2\xe9\x84\x1b+c\xb6\x17\x1c\x9c\xd5\xf7n\x06-\xdfa\x7f\xe0\xf5\x00\xdf\x8b\xbe\x1a\x03\xd8)a\x11\xdd\x8fm2\xd1_5\xfb\x83\xe8&\xcb\xb1\xc9\xeb"\x13\xf2<\xbc\xa5\xc3`\xc5xT,RR\xe6\xc9\xac\x04\t\xf3\x1a\x88\xac\xbb\xe9\xb12\xc8\x0f\xfcK\xf2<\x95\xfe\x14\xb1\xf7j\x88\x19\xd8A\x01\x1bM\x83\x94>Pyt\xe9\x16"\x90\xc0F\xd6\x9eK!\xeeq{ur\n\x11,\xa0\xfcq`\x05\xb0y\x0cTLYx\xf0`]\xf8\x8d\xf5v\x9a\x81\x17D\xc13'
2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b"\x1b\x00\xfe\x02.\x99W#'\xd3}\xb8i{m\x9c\xcej\xb2)\x82\xbcK\xc3\x06\x10}\x8a8\x17~\x0c\xd4\xf6\r\xb4\xb618\x8c\xba\xb7\xa5\x08|"
2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'HTTP/1.1 204 No Content\r\n\r\n')
2020-03-25 14:17:25 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 10.0.10.105: raw response: bytearray(b'')

Jc2k commented 4 years ago

Sweet. So currently:

Using the official HomeKit Accessory Simulator from Apple to make a virtual switch works. Can turn it on and off as quick as i can click my mouse.
Another switch device ony my end (cobbled together with HAP-NodeJS) works, so not a problem with the higher level switch logic
The entity map you shared is so incredibly normal and boring. There are no weird custom characteristics. The switch service only has the on characteristic and a name. It has an iid of 17 like the code is choosing. This is all fine.
The encryption and pairing is all working as sensor values are retrieved. Indeed the current switch stat is also retrieved.
Turning the switch off works
Both turning on and off yield valid looking HTTP requests which the device accepts. The only difference between those requests is whether to turn the device on or off.
Even more that that, the device reports that it is indeed switched on when queried.
But it is not switched on as far as you can tell (lights dont come on?)

There is something i'm clearly missing. Probably something incredibly stupid!

Is success the lights turning on? How long does that normally take? How long do you wait since this problem started? Could it be that i'm seeing success in the logs but actually there is a delay so you never see the light come on?

We could try pairing manually on the command line if you have a linux or mac with python 3.6 or later using the library ha 106 and earlier was using. Is that something you can do?

CAB426 commented 4 years ago

@Jc2k I never supplied the manual toggling of the switch logs. HA recognizes instantly that the switch was pressed manually. Here are those logs:


2020-03-25 15:09:14 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b"\xac\x00{\x8f\x93\xdc)\xf2\\b\x0cN\xb3\x88\xb1Z\xa5\xd0\xad\xc0X\xf1\xc0\xe2\xa5\xaf\x8e9~bK\x96\xdb\xf80\xa10)\x91m.\x18\x849V(\x98\xd3\xfa/\xe2\xc9\xb0\xbe-\xdetYg\xcbh\xbb\xff\xaeVs$\x02\xb5\xc4\xde\x838\x8a\xa4\xb0\x19\xcc\xdf\xc1\xbe\\\x15H]gY\xd5\x80>\xcd\x84\xa5\x18*pIL\xb1\x05V\x80\xbb'\xb8_\xfc\xc0\xe6\xd6\xac\x82\xf3\x85$\xeeY+\xa7\xbb+\x01\xdac\xdbK\x81\x07\xf19\x11\xbcsf\x8b\x1b|\x9f\x15&\xb6\x1b\x88E\xc3\xe7lS\x13\x9d\xb0II\xce\x82\xb2\xae\xce\xe1\xae\xb7jY\x11\xc83\xab\xa5\xear\xb0\xcdN\xee\xd1\x17J\x7fd{K_\xca\x02r&\xe8G=K"
2020-03-25 15:09:14 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'EVENT/1.0 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 96\r\n\r\n{\n  "characteristics": [\n    {\n      "aid": 1,\n      "iid": 17,\n      "value": true\n    }\n  ]\n}\n')
2020-03-25 15:09:15 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b"\xae\x00c\xeaI\t\xf5\xd2I\xa8\x00\xfa\xac\xe9gAB\xe7\x8at\xb2z\xf2\xe0\x97\\\x06\xc5h\xda}\xe5i\x90\x93\x85X\xa8\xbb x\xdb\xac\xb8\x04\x10\xae\x18\x07\xf4\xc2\xd9\x0f\xd3Y*\n\r%<\xb2\x11r\xb5\x90\xb4\xb8\x14\xb8\xf1\xc5\xac\xd9F\xadI\xa4\x18'\xb0F\x96\xc6\xb2\xc6\xd8r\xb5\xb1\x8fnz\x83\xbc\x9c\xce\x13\xcbC/\x1bv~\xcf\xf8\x1d\x06\xfb;z\xbb\x93\x04\x96\x0f\x8d\x0f\r\x9b+V\xcd?+2c\xd5\t\xfcp\xe8\xa0\xc7r\x8b\xc5\xdce\xdf\xe0\x82\xc3kvHD\xd1\xa0\xf0i\x02\xc2/x\xcel\xef\xb9T\xed6\xae\xb0\x1dYo!\x18\x14+B.\xf1y]7\x8d]\xfbC\x9a\x99'\xd6f\x99\x1a\xaaQ\xb3\xe1\xc2"
2020-03-25 15:09:15 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'EVENT/1.0 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 98\r\n\r\n{\n  "characteristics": [\n    {\n      "aid": 1,\n      "iid": 20,\n      "value": 134.58\n    }\n  ]\n}\n')
2020-03-25 15:09:18 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b'\xad\x00\xd6{\\8k\x89\x1a\xc6\x88b\xe9Dh\x1c\xf2#\x08M{ \xaa\x14H\xcb\r\x88\xdf\x89\x9e\xac\xccC\xd1q\xe7\xb8\xea9\xacr\xecS\x02M\x8bE\xa1\\*\xb6?m"\xdb\xb6\\\r\xf7\x8as"D\x035\x1d\xdc\xa7YU#\x1cf!=\x17\xb6\xdbr\xaf\x87\xd7\xf7\x02}}\x05\xa2\xee\xbehZ\x9a\xd7@fb&\x9925?\x83\x0bM\xc0H2\xfe\xbem2\xab\x7f\x87\x13V\xb2]~\x15\xab\xf5\x82m\x05I&\xd5\x8d?a\xb6D\xa2\xdeZ\xd3z\xb0\xd3\xa2\xc0\x1bi*\xbe\xb56\xe3\xaa\xea\xf8,\x8a\xd3\xa0\x10v\x99\xedav*i\xab\xf1\xae\xecH\xce\x00\xa9\xdc\x9ci\xa0\xf4\xa1\xa2\x80\x97\x153\xa2\xdaD\x86v\xba'
2020-03-25 15:09:18 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'EVENT/1.0 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 97\r\n\r\n{\n  "characteristics": [\n    {\n      "aid": 1,\n      "iid": 17,\n      "value": false\n    }\n  ]\n}\n')
2020-03-25 15:09:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] SECURE receive: b"\xad\x00\x1f{+\xb1\xd4\xd6\x9cAh{r\xcf\x0b\x96,\xaa\xc5\x94&\x06j\x97\xeb^\xb1\xeb\x07\xa0bW5j\x07'\xb6\xa7\xa4B\x92\xd4\xa1\xba?u\x9f\xdf\xc3\xd7/ l\x92Ym9\xb8b\x84\x9b(\x12\xbe\xdc\x82\x9e\x02\xd8a\x1fB\xce\xdfq\x7f\x87\x14\xe9\xb0\xdfI\xdb\\weV\xac\x82\xc5\x88t\x93\x8e\xecp^\xa5\xfb}\xdb \xaf\xf9\x89\x7f\x13f0T\x07\xc4\x8de?\xfeU\xd6\xba\x946\xf0\x89+eW\xc7\x867 \xcd\xfcI\xc6\x97\xcbz\xaa,\xa5\xb1\xe4\x11\xe3\xe8.\x9f}\x92\x06\x92?\x84\r\xff\x82\xc2\x10\xc7R\xa6\xcdN\xc8\xf0\xa8~\xa1+;\xa9cDw\x9a-D_\xaeTJ\xc1\xb2\xd1kWk:\x9a\xf8f"
2020-03-25 15:09:19 DEBUG (MainThread) [aiohomekit.controller.ip.connection] INSECURE receive: bytearray(b'EVENT/1.0 200 OK\r\nContent-Type: application/hap+json\r\nContent-Length: 97\r\n\r\n{\n  "characteristics": [\n    {\n      "aid": 1,\n      "iid": 20,\n      "value": 65.41\n    }\n  ]\n}\n')

There is some sensor data in here, but I wasn't sure which log entries aligned so I left them in there.

I haven't seen the lights turn on since this issue came about. I can't remember exactly when it started, but it was in 0.106. I could try to pair manually and test that way, I have a linux instance I can use.

Could this be a bug in the switch firmware? I'm just wondering if we are chasing shadows on the HA side.

Jc2k commented 4 years ago

I'm super stoked about the events working! And they provide another useful data point - the event is for aid 1, iid 17 as we think and the value is "true" then "false".

It could be a firmware issue, but it works with iOS right? So even if its a bug, if it works with iOS it should work for us too. If we've not seen it work with iOS thats another matter.

I have found a difference with 0.106 style command line that I want to rule out.

Edit /usr/src/homeassistant/homeassistant/components/homekit_controller/switch.py and find this bit:

    async def async_turn_on(self, **kwargs):
        """Turn the specified switch on."""
        await self.async_put_characteristics({CharacteristicsTypes.ON: True})

    async def async_turn_off(self, **kwargs):
        """Turn the specified switch off."""
        await self.async_put_characteristics({CharacteristicsTypes.ON: False})

See the 2 CharacteristicsTypes.ON with True and False? According to the HAP spec these are bools but i just noticed 0.106 was sending numbers. Change the True to 1 and the False to 0 and see if that works.

I kind of hope it doesn't as we've seen events and polls return data as bools. So writing a true failed it would be super odd. But lets try it anyway.

Jc2k commented 4 years ago

HA always sent a value of true even on 0.106.x:

PUT /characteristics HTTP/1.1\r\n
Host: 192.168.1.225:8080\r\n
Content-Type: application/hap+json\r\n
Content-Length: 59\r\n
\r\n
{"characteristics": [{"aid": 1, "iid": 10, "value": true}]}

But in comparison an iPhone sends:

PUT /characteristics HTTP/1.1\r\n
Host: DemoAccessory\\0321234._hap._tcp.local\r\n
Content-Length: 50\r\n
Content-Type: application/hap+json\r\n
\r\n
{"characteristics":[{"aid":1,"iid":10,"value":1}]}

The HAP spec itself says:

Note that all the characteristics with the format bool must expose/accept a Boolean value expressed as one of the following: true, false, 0 (false), or 1 (true).

CAB426 commented 4 years ago

@Jc2k I'm stoked on the events too! It's an amazing addition!

Well, that was it. I changed the CharacteristicsTypes.ON values to 1 and 0, and the switch works correctly again. Really appreciate the help with this.

Any ideas for a fix for this? Assuming this means ecobee is out of spec on this device?

Jc2k commented 4 years ago

@CAB426 wow! thanks for testing.

So yeah, technically the spec says a bool characteristic must accept true, false, 0 or 1. With your help we've shown that it does accept 3 of these (as false was working to turn it off. We've also seen the behaviour for true is bugged (the homekit protocol accpts true with a success result code and reports the true value back to us when polling but doesnt switch the device on).

It looks like ha 0.106.x also used to send the same true/false values as 0.107.x, so i don't think that upgrade is the root cause any more. I think a firmware update was mentioned earlier in this ticket, so I wonder if thats the root cause.

We have a precident for this sort of bug. Whilst the spec is good for understanding what is supposed to happen we have already seen with other devices that following the spec is not enough. Some thermostat's are really picky about the value of the Host header. Some other devices are picky if the HTTP request is split into multiple TCP packets. Ultimately all these pieces of hardware are only tested against iOS, so all we can do is reverse enginner what iOS does and follow it more closely.

The "fix" is probably the change you made manually. If iOS sends 1 and 0 then we should too. The risk to other switches is low because we will be more compliant with the iOS implementation. But I will probably finesse it a bit so that the HA side continues to follow the spec and pass bools for bool fields, and the API serializes them down to 0 and 1.

rdariolemes commented 4 years ago

@Jc2k , since I'm using Hass.io, is there any way for me to change that and test or do I need to wait until you add it in a future code release?

Thanks

CAB426 commented 4 years ago

@rdariolemes You should be able to make the changes above in Hass.io. That is what I am using as well.

Basic steps: Terminal into host and run: docker ps (find the ID of the HA container) docker exec -it <container_id> sh

Once in the docker session, I copied the file from /usr/src/homeassistant/homeassistant/components/homekit_controller/switch.py to /config/debugging/ (created this folder):

cp /usr/src/homeassistant/homeassistant/components/homekit_controller/switch.py /confg/debugging/switch.py

I then edited the file in the /config folder using WinSCP to connect to the host (I am not very strong in vi or nano, so I went this route). Once the file matched the above changes, I copied it back to /usr/src/homeassistant/homeassistant/components/homekit_controller/switch.py:

cp /confg/debugging/switch.py /usr/src/homeassistant/homeassistant/components/homekit_controller/switch.py

and finally reboot HA.

If you have any plans to upgrade to 0.107.+ do so before you make this change is the upgrade will overwrite your changes.

rdariolemes commented 4 years ago

@CAB426 , sorry but docker ps is not a valid command on my hass.io instance (see below)

CAB426 commented 4 years ago

@rdariolemes Don't SSH into Hass.io, you need to get into the host.

rdariolemes commented 4 years ago

@CAB426 , apologies for my ignorance, how can i do that?

CAB426 commented 4 years ago

@rdariolemes What OS are you running Hass.io (Docker) on?

I have it running in Ubuntu, but you can also run it on many flavors of Linux (including on a Raspberry Pi) or Windows. The commands I am sending are Linux using SSH to connect into the host, but you my have a screen, keyboard and mouse plugged in, or you may have it running on your Windows box.

rdariolemes commented 4 years ago

@rdariolemes What OS are you running Hass.io (Docker) on?

I have it running in Ubuntu, but you can also run it on many flavors of Linux (including on a Raspberry Pi) or Windows. The commands I am sending are Linux using SSH to connect into the host, but you my have a screen, keyboard and mouse plugged in, or you may have it running on your Windows box.

@CAB426 , I'm running on NUC so whatever that comes with. I was able to access the host and get it working as you mentioned previously. Thanks for your instructions and @Jc2k ones.

@Jc2k , do u have any idea when would this fix be added through core update on HA?

Thank you both

CAB426 commented 4 years ago

@rdariolemes Glad to help and glad you got it working!

Jc2k commented 4 years ago

@rdariolemes hoping to put together a PR this weekend. I might be able to get it into 0.108.0 but can't make any promises.

rdariolemes commented 4 years ago

@Jc2k , Thanks man no problem. Really appreciated all work you do. Can u update on this email thread once fixed? I will hold my upgrades till then since this is a critical component of all my environment (Most of my switches on the house are ecobees).

Thanks

Jc2k commented 4 years ago

Have opened a PR with this fix. @rdariolemes I'll let you know what tag to expect it in when it gets through code review.

home-assistant / core