search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
74.17k stars 31.14k forks source link

Homekit Setup Failed #34130

Closed viptampa closed 4 years ago

viptampa commented 4 years ago

The problem

Attempting to pair Home Assistant with HomeKit. I see the pin, I add it to Apple Home, the pin in home assistant disappears, and Home never pairs with HomeKit. Eventually get a Unable to pair message. Same as issue #31676

Environment

Home Assistant 0.108.3

Problem-relevant configuration.yaml

homekit: port: 51869 filter: include_entities:

Traceback/Error logs

2020-04-13 01:23:39 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Home Assistant Bridge (Home Assistant Bridge - 74:DA:04:FF:C2:E7) 2020-04-13 01:23:39 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] HomeKit device 74:DA:04:FF:C2:E7 ignored as already paired 2020-04-13 01:23:39 INFO (Thread-16) [pyhap.hap_server] 10.69.69.51 - "POST /pair-setup HTTP/1.1" 200 - 2020-04-13 01:23:39 DEBUG (Thread-16) [pyhap.hap_server] Cleaning connection to ('10.69.69.51', 53122)

2020-04-13 01:28:00 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Upstairs (EB-STATE5 - ED:24:F0:95:BF:0C) 2020-04-13 01:28:00 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Homebridge-CAD8 (Homebridge - CC:22:3D:E3:CE:30) 2020-04-13 01:28:00 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] HomeKit device ED:24:F0:95:BF:0C ignored as already paired 2020-04-13 01:28:00 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] HomeKit device CC:22:3D:E3:CE:30 ignored as already paired

Additional information

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

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

bdraco commented 4 years ago

@viptampa Would you please check the docker console log to see if there is an untrapped exception from pyhap

viptampa commented 4 years ago

I can look. I’m unsure what an untrapped exception looks like, but I’ll check tomorrow evening when I get home to try again.

bdraco commented 4 years ago

@viptampa It will look something like this

Exception happened during processing of request from ('192.168.88.196', 50342)
Traceback (most recent call last):
File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socketserver.py", line 650, in process_request_thread
self.finish_request(request, client_address)
File "/usr/local/lib/python3.7/site-packages/pyhap/hap_server.py", line 853, in finish_request
self, self.accessory_handler)
File "/usr/local/lib/python3.7/site-packages/pyhap/hap_server.py", line 143, in init
super(HAPServerHandler, self).init(sock, client_addr, server)
File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socketserver.py", line 720, in init
self.handle()
File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/server.py", line 426, in handle
self.handle_one_request()
File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/server.py", line 414, in handle_one_request
method()
File "/usr/local/lib/python3.7/site-packages/pyhap/hap_server.py", line 204, in dispatch
getattr(self, self.HANDLERS[self.command][path])()
File "/usr/local/lib/python3.7/site-packages/pyhap/hap_server.py", line 389, in handle_pair_verify
self._pair_verify_two(tlv_objects)
File "/usr/local/lib/python3.7/site-packages/pyhap/hap_server.py", line 439, in _pair_verify_two
cipher = CHACHA20_POLY1305(self.enc_context["pre_session_key"], "python")
TypeError: 'NoneType' object is not subscriptable
TerrorSource commented 4 years ago

Got the same issue on a new 0.108.3 installation. Already stopped HA, removed .homekit.state and started HA multiple times without result.

Running HA on a Pi 3b, using HA's own image.

Let me know what i can do to help.

EDIT: Steps i did:

  1. Open Homekit on iPhone
  2. Add accessory
  3. Dont have a code or cant scan
  4. Choose Home Assistant Bridge
  5. Add anyway
  6. Enter code shown in HomeAssistant after HA restart
  7. Errors out : "Invalid code"
bdraco commented 4 years ago

First try adding this to your configuration.yaml and restarting. Look for anything interesting in the log during pairing

logger:
  default: info
  logs:
    homeassistant.components.homekit: debug
    custom_components.homekit: debug
    custom_components.flume: debug
    pyhap: debug

If that doesn't uncover anything, try pairing again in safe mode. Add the following to your existing homekit: config in configuration.yaml and restart

homekit:
  safe_mode: true

Lastly, you can try the 0.109 version with the zeroconf_default_interface option

cd /config
mkdir custom_components
cd custom_components
git clone https://github.com/bdraco/homekit.git

Add the following to your existing homekit: config in configuration.yaml and restart

homekit:
  zeroconf_default_interface: true
TerrorSource commented 4 years ago

@bdraco Part 1: Removed a lot of lines where the switch where added result: same, code is incorrect

2020-04-14 16:16:11 INFO (MainThread) [homeassistant.setup] Setting up homekit 2020-04-14 16:16:11 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit 2020-04-14 16:16:11 DEBUG (SyncWorker_9) [pyhap.characteristic] set_value: SerialNumber to homekit.bridge 2020-04-14 16:16:14 INFO (MainThread) [homeassistant.setup] Setup of domain homekit took 2.9 seconds. 2020-04-14 16:16:18 INFO (SyncWorker_2) [homeassistant.loader] Loaded homekit_controller from homeassistant.components.homekit_controller 2020-04-14 16:16:22 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Home Assistant Bridge (Home Assistant Bridge - C0:0B:85:58:FE:41) 2020-04-14 16:16:32 DEBUG (SyncWorker_6) [homeassistant.components.homekit] Add "switch.homekit_vacuum_flip" as "Switch" 2020-04-14 16:16:32 DEBUG (SyncWorker_6) [pyhap.characteristic] set_value: SerialNumber to switch.homekit_vacuum_flip 2020-04-14 16:16:32 DEBUG (SyncWorker_6) [homeassistant.components.homekit] Add "switch.fwp_printer_switch" as "Switch" 2020-04-14 16:16:36 INFO (SyncWorker_6) [pyhap.accessory_driver] Loading Accessory state from /config/.homekit.state 2020-04-14 16:16:36 INFO (SyncWorker_6) [homeassistant.components.homekit.util] Pincode: 577-91-104 2020-04-14 16:16:37 DEBUG (SyncWorker_6) [homeassistant.components.homekit] Driver start

bdraco commented 4 years ago

Nothing odd there. Try safe_mode next

TerrorSource commented 4 years ago

@bdraco Part 2 - with safe mode ON, same as part 1, removed lines of added devices:

2020-04-14 16:30:03 INFO (MainThread) [homeassistant.setup] Setting up homekit
2020-04-14 16:30:03 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit
2020-04-14 16:30:04 DEBUG (SyncWorker_9) [pyhap.characteristic] set_value: SerialNumber to homekit.bridge
2020-04-14 16:30:04 DEBUG (SyncWorker_9) [homeassistant.components.homekit] Safe_mode selected
2020-04-14 16:30:04 INFO (MainThread) [homeassistant.setup] Setup of domain homekit took 0.7 seconds.
2020-04-14 16:30:08 INFO (SyncWorker_19) [homeassistant.loader] Loaded homekit_controller from homeassistant.components.homekit_controller
2020-04-14 16:30:12 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Home Assistant Bridge (Home Assistant Bridge - C0:0B:85:58:FE:41)
2020-04-14 16:30:23 DEBUG (SyncWorker_18) [homeassistant.components.homekit] Add "switch.homekit_vacuum_flip" as "Switch"
2020-04-14 16:30:23 DEBUG (SyncWorker_18) [pyhap.characteristic] set_value: SerialNumber to switch.homekit_vacuum_flip
2020-04-14 16:30:23 DEBUG (SyncWorker_18) [homeassistant.components.homekit] Add "switch.fwp_printer_switch" as "Switch"
2020-04-14 16:30:24 INFO (SyncWorker_18) [pyhap.accessory_driver] Loading Accessory state from `/config/.homekit.state`
2020-04-14 16:30:25 INFO (SyncWorker_18) [homeassistant.components.homekit.util] Pincode: 744-52-043
2020-04-14 16:30:25 DEBUG (SyncWorker_18) [homeassistant.components.homekit] Driver start

Btw, only filtered lines with "homekit" in it.

TerrorSource commented 4 years ago

Part 3, with custom_component:

2020-04-14 16:38:21 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for homekit which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-04-14 16:38:30 INFO (MainThread) [homeassistant.setup] Setting up homekit
2020-04-14 16:38:30 DEBUG (MainThread) [custom_components.homekit] Begin setup HomeKit
2020-04-14 16:38:31 DEBUG (SyncWorker_15) [pyhap.characteristic] set_value: SerialNumber to homekit.bridge
2020-04-14 16:38:31 DEBUG (SyncWorker_15) [custom_components.homekit] Safe_mode selected
2020-04-14 16:38:34 INFO (MainThread) [homeassistant.setup] Setup of domain homekit took 3.2 seconds.
2020-04-14 16:38:38 INFO (SyncWorker_4) [homeassistant.loader] Loaded homekit_controller from homeassistant.components.homekit_controller
2020-04-14 16:38:41 DEBUG (MainThread) [homeassistant.components.homekit_controller.config_flow] Discovered device Home Assistant Bridge (Home Assistant Bridge - C0:0B:85:58:FE:41)
2020-04-14 16:38:52 DEBUG (SyncWorker_12) [custom_components.homekit] Add "switch.homekit_vacuum_flip" as "Switch"
2020-04-14 16:38:52 DEBUG (SyncWorker_12) [pyhap.characteristic] set_value: SerialNumber to switch.homekit_vacuum_flip
2020-04-14 16:38:52 DEBUG (SyncWorker_12) [custom_components.homekit] Add "switch.fwp_printer_switch" as "Switch"
2020-04-14 16:38:54 INFO (SyncWorker_12) [pyhap.accessory_driver] Loading Accessory state from `/config/.homekit.state`
2020-04-14 16:38:54 INFO (SyncWorker_12) [custom_components.homekit.util] Pincode: 983-39-892
2020-04-14 16:38:54 DEBUG (SyncWorker_12) [custom_components.homekit] Driver start
bdraco commented 4 years ago

Going to need the pyhap lines as well

TerrorSource commented 4 years ago

[part_3_full_logs.txt]

See attachment, complete log of Part 3, no lines removed.

bdraco commented 4 years ago

Here is the issue

2020-04-14 16:38:54 DEBUG (SyncWorker_0) [pyhap.accessory_driver] Starting mDNS.
2020-04-14 16:38:54 ERROR (SyncWorker_12) [asyncio] Future exception was never retrieved
future: <Future finished exception=NonUniqueNameException()>
Traceback (most recent call last):
  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/pyhap/accessory_driver.py", line 287, in _do_start
    self.advertiser.register_service(self.mdns_service_info)
  File "/usr/local/lib/python3.7/site-packages/zeroconf/__init__.py", line 2219, in register_service
    self.check_service(info, allow_name_change, cooperating_responders)
  File "/usr/local/lib/python3.7/site-packages/zeroconf/__init__.py", line 2383, in check_service
    raise NonUniqueNameException
zeroconf.NonUniqueNameException
bdraco commented 4 years ago

Did you try with zeroconf_default_interface: true?

TerrorSource commented 4 years ago

Did a new test with the following config:

homekit: zeroconf_default_interface: true port: 51869 filter: include_entities:

  • demo.demo

[part_4_full_logs.txt]

bdraco commented 4 years ago

Try adding

name: MyHomeAssistant

To the homekit: entry and restarting

TerrorSource commented 4 years ago

Following config:

homekit: name: MyHomeAssistant zeroconf_default_interface: true port: 51869 filter: include_entities:

  • demo.demo

Works, i can add the Home Assistant Bridge on iPhone. no items show up, guess that is because the demo.demo device specified.

Any other things i need to test for you before i put my own config back in?

bdraco commented 4 years ago

Nope. Its likely the combination of these two that fix it:

name: MyHomeAssistant
zeroconf_default_interface: true
bdraco commented 4 years ago

@TerrorSource The the zeroconf_default_interface setting will be available in 0.109. You should be able to delete the custom version once it lands.

I've added a note to the docs about this as well https://github.com/home-assistant/home-assistant.io/pull/12969

TerrorSource commented 4 years ago

Nope. Its likely the combination of these two that fix it:

name: MyHomeAssistant
zeroconf_default_interface: true

I've put my homekit config back in, with the name and zeroconf_default_interface added and it works. devices show up on Homekit on iPhone right after HA restarts.

stigganOne commented 4 years ago

@bdraco im trying to use the custom component. Ive downloaded the git and put it inside custom_folders as a folder "homekit" containing all files. also added name: MyHomeAssistant zeroconf_default_interface: true

Restarded home assistant from ssh. Not getting past " Unable to pair message " something i do wrong?

bdraco commented 4 years ago

@stigganOne Would you please adjust the logging and post the log

logger:
  default: info
  logs:
    homeassistant.components.homekit: debug
    custom_components.homekit: debug
    custom_components.flume: debug
    pyhap: debug
stigganOne commented 4 years ago

@bdraco https://pastebin.com/rX7eM0ux

bdraco commented 4 years ago

Did you try pairing again while while watching the log? I don't see any pair attempts in the log

TerrorSource commented 4 years ago

@stigganOne Did you check out .homekit.state before pairing? Needs to be resetted at least once. If paired correctly, .homekit.state has "paired_clients" filled in.

stigganOne commented 4 years ago

@bdraco Here's a new log when pairing https://pastebin.com/2afHmnKL @TerrorSource Ive deleted .homekit.state before trying to pair

bdraco commented 4 years ago

@stigganOne Looks like there was an exception that was untrapped in 2020-04-14 20:31:43 DEBUG (Thread-9) [pyhap.hap_server] Pairing [3/5]

Can you check the console log for it?

stigganOne commented 4 years ago

@bdraco Thanks for helping out. Not sure what to look for https://pastebin.com/RXLzhkb9

bdraco commented 4 years ago

@stigganOne Replace <container> with the name of your container docker container logs <container> -f

stigganOne commented 4 years ago

@bdraco im lost now. not sure where to find it. I'm running home assistant as a plugin on freenas server

stigganOne commented 4 years ago

@bdraco found something called homeassistant-console.log https://pastebin.com/W57hdACB

bdraco commented 4 years ago

@stigganOne It seems like STDERR is missing from that log. You'll need to figure out where standard error is being logged to find the error. I'm sorry I can't help with that as I don't have a freenas box.

stigganOne commented 4 years ago

@bdraco been looking and the only logs I can find is the two I've linked. thanks for trying to help me tho

stigganOne commented 4 years ago

@bdraco Think ive found it. Exceptions: https://pastebin.com/TbgF7CnA Errors: https://pastebin.com/esuu8kvg

bdraco commented 4 years ago

@stigganOne The openssl that comes with your OS is too old cryptography.exceptions.UnsupportedAlgorithm: ChaCha20Poly1305 is not supported by this version of OpenSSL What are you running Home Assistant on?

stigganOne commented 4 years ago

@bdraco Freenas 11.3 as a core plugin. Everything worked fine before upgrading home assistant from 0.107.7 to 0.108.

bdraco commented 4 years ago

@stigganOne You'll need openssl 1.1.0 or later (released after 25 Aug 2016) as the crypto was upgraded in the underlying homekit libraries. It looks like freenas has an openssl111 package but I don't know enough about freenas to advise on how to get home assistant to use it.

stigganOne commented 4 years ago

@bdraco managed to update openssl111 inside jail. Still says haCha20Poly1305 is not supported by this version of OpenSSL

bdraco commented 4 years ago

@stigganOne There is a thread on the forums where others have hit this issue. https://community.home-assistant.io/t/my-outdated-quick-start-for-home-assistant-core-on-freenas-11-2/71882/151. Its possible someone may have figured out how to do it.

bdraco commented 4 years ago

You probably need to rebuild python linked to openssl111 similar to this: https://www.ixsystems.com/community/threads/openssl-update-to-1-1-1.76814/

stigganOne commented 4 years ago

@bdraco Thanks will check it out. Also 2020-04-15 08:22:25 INFO (Thread-7) [pyhap.hap_server] Got connection with ('10.0.1.9', 56822). is that right adress? shouldnt it be something like this? 2020-04-15 08:22:12 INFO (SyncWorker_0) [pyhap.accessory_driver] Starting accessory MyHomeAssistant on address 10.0.1.14, port 51827.

stigganOne commented 4 years ago

@bdraco Rolled back to 0.107.7 for now and working again without zeroconf. Will stay here for now while trying to figure out openssl for 0.108.

bdraco commented 4 years ago

@stigganOne You should be able to change HAP-python==2.8.2 to HAP-python==2.7.0 in homekit/manifest.json and use 0.108.x

Of course you won't get all the bug fixes from 2.7.0->2.8.2 and its much slower but it works without a modern version of openssl.

stigganOne commented 4 years ago

@bdraco thanks will give it a try :)

stigganOne commented 4 years ago

@bdraco worked like a charm. You're my hero. Thanks<3

tprelog commented 4 years ago

Sorry to comment on this closed issue @bdraco @stigganOne

We might have have figured out the openssl issue for HomeKit in the Home Assistant Core FreeNAS plugin. I don't have any physical HomeKit devices to test with -- but I was successfully able to pair the HomeKit Bridge integration with the HomeKit Controller integration in Home Assistant 0.110.1

The steps are written for the FN plugin but should also apply to anyone using a FreeBSD/FreeNAS jail 11.3-RELEASE. I'm looking for a few people to confirm this works before I add it to the FN plugin

https://github.com/tprelog/iocage-homeassistant/issues/14#issuecomment-633141287