HomeKit not pulling over any devices

asmugala · May 31, 2018, 4:27pm

To preface, I have Home Assistant running in Docker on a Synology. I updated to version 0.70 and added the homekit line to my config file. When I boot up HA, I get the HomeKit code, which I add to my phone. The problem is none of my devices pull over. All I see in HomeKit is my Home Assistant bridge, which is grey. I’m at a bit of a loss. Any help would be greatly appreciated.

cdce8p · May 31, 2018, 8:37pm

Try restarting Home Assistant. That helps sometimes. Alternatively you can enable debug logging: https://www.home-assistant.io/components/homekit/#error-reporting

asmugala · June 2, 2018, 7:42pm

Restarting HA and logs give no indication of any problems. Attached is what I see in HomeKit

cdce8p · June 3, 2018, 8:49pm

Please add this to your config:

logger:
  default: warning
  logs:
    homeassistant.components.homekit: debug
    pyhap: debug

Restart and if possible post the log output.

asmugala · June 4, 2018, 1:29am

2018-06-04 01:26:20 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: Name to Home Assistant Bridge
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: SerialNumber to default
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: FirmwareRevision to 0.69.0
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: Manufacturer to Home Assistant
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: Model to Bridge
2018-06-04 01:26:22 DEBUG (SyncWorker_1) [pyhap.characteristic] set_value: SerialNumber to homekit.bridge
2018-06-04 01:26:27 INFO (SyncWorker_1) [pyhap.accessory_driver] Loading Accessory state from /config/.homekit.state
2018-06-04 01:26:28 DEBUG (SyncWorker_0) [homeassistant.components.homekit] Driver start
2018-06-04 01:26:28 INFO (SyncWorker_3) [pyhap.accessory_driver] Starting accessory Home Assistant Bridge on address 192.168.1.150, port 51827.
2018-06-04 01:26:29 INFO (SyncWorker_3) [pyhap.accessory_driver] Starting event loop
2018-06-04 01:26:37 WARNING (SyncWorker_9) [netdisco.ssdp] Found malformed XML at http://192.168.1.192:9080: status=ok
2018-06-04 01:26:43 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-06-04 01:26:44 ERROR (Thread-5) [pychromecast.socket_client] Exception caught while sending message to controller ReceiverController: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {‘requestId’: 1, ‘status’: {‘applications’: [], ‘isActiveInput’: True, ‘volume’: {‘controlType’: ‘attenuation’, ‘level’: 1, ‘muted’: False, ‘stepInterval’: 0.05}}, ‘type’: ‘RECEIVER_STATUS’}
Traceback (most recent call last):
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 460, in _route_message
message, data)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 775, in receive_message
self._process_get_status(data)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 905, in _process_get_status
status = self._parse_status(data, self.cast_type)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 883, in _parse_status
app_data = data[‘applications’][0]
IndexError: list index out of range
2018-06-04 01:26:49 ERROR (SyncWorker_8) [pywemo.ssdp] Found malformed XML at http://192.168.1.192:9080: status=ok
2018-06-04 01:26:51 WARNING (MainThread) [homeassistant.setup] Setup of wemo is taking over 10 seconds.
2018-06-04 01:26:53 WARNING (SyncWorker_8) [homeassistant.components.wemo] Unable to probe wemo at 192.168.1.213
2018-06-04 01:26:53 WARNING (SyncWorker_8) [homeassistant.components.wemo] Unable to probe wemo at 192.168.1.212

asmugala · June 4, 2018, 1:48am

This is what the log looked like after upgrading to 0.70.0:

2018-06-04 01:45:00 DEBUG (MainThread) [homeassistant.components.homekit] Begin setup HomeKit
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: Name to Home Assistant Bridge
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: SerialNumber to default
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: FirmwareRevision to 0.70.0
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: Manufacturer to Home Assistant
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: Model to Bridge
2018-06-04 01:45:00 DEBUG (SyncWorker_2) [pyhap.characteristic] set_value: SerialNumber to homekit.bridge
2018-06-04 01:45:05 INFO (SyncWorker_2) [pyhap.accessory_driver] Storing Accessory state in /config/.homekit.state
2018-06-04 01:45:07 INFO (SyncWorker_7) [homeassistant.components.homekit.util] Pincode: 667-14-301
2018-06-04 01:45:07 DEBUG (SyncWorker_7) [homeassistant.components.homekit] Driver start
2018-06-04 01:45:07 INFO (SyncWorker_4) [pyhap.accessory_driver] Starting accessory Home Assistant Bridge on address 192.168.1.150, port 51827.
2018-06-04 01:45:08 INFO (SyncWorker_4) [pyhap.accessory_driver] Starting event loop
2018-06-04 01:45:16 WARNING (SyncWorker_9) [netdisco.ssdp] Found malformed XML at http://192.168.1.192:9080: status=ok
2018-06-04 01:45:23 ERROR (Thread-5) [pychromecast.socket_client] Exception caught while sending message to controller ReceiverController: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {‘requestId’: 1, ‘status’: {‘applications’: [], ‘isActiveInput’: True, ‘volume’: {‘controlType’: ‘attenuation’, ‘level’: 1, ‘muted’: False, ‘stepInterval’: 0.05}}, ‘type’: ‘RECEIVER_STATUS’}
Traceback (most recent call last):
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 460, in _route_message
message, data)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 775, in receive_message
self._process_get_status(data)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 905, in _process_get_status
status = self._parse_status(data, self.cast_type)
File “/usr/local/lib/python3.6/site-packages/pychromecast/socket_client.py”, line 883, in _parse_status
app_data = data[‘applications’][0]
IndexError: list index out of range
2018-06-04 01:45:28 ERROR (SyncWorker_0) [pywemo.ssdp] Found malformed XML at http://192.168.1.192:9080: status=ok
2018-06-04 01:45:32 WARNING (MainThread) [homeassistant.setup] Setup of wemo is taking over 10 seconds.
2018-06-04 01:45:34 WARNING (SyncWorker_0) [homeassistant.components.wemo] Unable to probe wemo at 192.168.1.213
2018-06-04 01:45:34 WARNING (SyncWorker_0) [homeassistant.components.wemo] Unable to probe wemo at 192.168.1.207
2018-06-04 01:45:34 WARNING (SyncWorker_0) [homeassistant.components.wemo] Unable to probe wemo at 192.168.1.212
2018-06-04 01:46:02 INFO (Thread-4) [pyhap.hap_server] Got connection with (‘192.168.1.183’, 53937).
2018-06-04 01:46:02 DEBUG (Thread-6) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.183’, 53937)’ for path ‘/pair-setup’.
2018-06-04 01:46:02 DEBUG (Thread-6) [pyhap.hap_server] Pairing [1/5]
2018-06-04 01:46:02 INFO (Thread-6) [pyhap.hap_server] 192.168.1.183 - “POST /pair-setup HTTP/1.1” 200 -
2018-06-04 01:46:09 DEBUG (Thread-6) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.183’, 53937)’ for path ‘/pair-setup’.
2018-06-04 01:46:09 DEBUG (Thread-6) [pyhap.hap_server] Pairing [2/5]
2018-06-04 01:46:09 INFO (Thread-6) [pyhap.hap_server] 192.168.1.183 - “POST /pair-setup HTTP/1.1” 200 -
2018-06-04 01:46:10 DEBUG (Thread-6) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.183’, 53937)’ for path ‘/pair-setup’.
2018-06-04 01:46:10 DEBUG (Thread-6) [pyhap.hap_server] Pairing [3/5]
2018-06-04 01:46:10 DEBUG (Thread-6) [pyhap.hap_server] Pairing [4/5]
2018-06-04 01:46:10 DEBUG (Thread-6) [pyhap.hap_server] Pairing [5/5]
2018-06-04 01:46:10 INFO (Thread-6) [pyhap.accessory_driver] Paired with e14dd8c1-f268-40c2-954e-7a5c9dba97b0.
2018-06-04 01:46:11 INFO (Thread-6) [pyhap.hap_server] 192.168.1.183 - “POST /pair-setup HTTP/1.1” 200 -
2018-06-04 01:46:11 INFO (Thread-4) [pyhap.hap_server] Got connection with (‘192.168.1.183’, 53938).
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.183’, 53938)’ for path ‘/pair-verify’.
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Pair verify [1/2].
2018-06-04 01:46:11 INFO (Thread-7) [pyhap.hap_server] 192.168.1.183 - “POST /pair-verify HTTP/1.1” 200 -
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.183’, 53938)’ for path ‘/pair-verify’.
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Pair verify [2/2]
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Pair verify with client ‘(‘192.168.1.183’, 53938)’ completed. Switching to encrypted transport.
2018-06-04 01:46:11 INFO (Thread-7) [pyhap.hap_server] 192.168.1.183 - “POST /pair-verify HTTP/1.1” 200 -
2018-06-04 01:46:11 DEBUG (Thread-7) [pyhap.hap_server] Request GET from address ‘(‘192.168.1.183’, 53938)’ for path ‘/accessories’.
2018-06-04 01:46:11 INFO (Thread-7) [pyhap.hap_server] 192.168.1.183 - “GET /accessories HTTP/1.1” 200 -
2018-06-04 01:46:14 INFO (Thread-4) [pyhap.hap_server] Got connection with (‘192.168.1.148’, 57623).
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.148’, 57623)’ for path ‘/pair-verify’.
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Pair verify [1/2].
2018-06-04 01:46:14 INFO (Thread-8) [pyhap.hap_server] 192.168.1.148 - “POST /pair-verify HTTP/1.1” 200 -
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Request POST from address ‘(‘192.168.1.148’, 57623)’ for path ‘/pair-verify’.
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Pair verify [2/2]
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Pair verify with client ‘(‘192.168.1.148’, 57623)’ completed. Switching to encrypted transport.
2018-06-04 01:46:14 INFO (Thread-8) [pyhap.hap_server] 192.168.1.148 - “POST /pair-verify HTTP/1.1” 200 -
2018-06-04 01:46:14 DEBUG (Thread-8) [pyhap.hap_server] Request GET from address ‘(‘192.168.1.148’, 57623)’ for path ‘/accessories’.
2018-06-04 01:46:14 INFO (Thread-8) [pyhap.hap_server] 192.168.1.148 - “GET /accessories HTTP/1.1” 200 -
2018-06-04 01:46:17 DEBUG (Thread-7) [pyhap.hap_server] Request PUT from address ‘(‘192.168.1.183’, 53938)’ for path ‘/characteristics’.
2018-06-04 01:46:17 DEBUG (Thread-7) [pyhap.characteristic] client_update_value: Identify to True
2018-06-04 01:46:17 INFO (Thread-7) [pyhap.hap_server] 192.168.1.183 - “PUT /characteristics HTTP/1.1” 207 -
2018-06-04 01:46:22 DEBUG (Thread-7) [pyhap.hap_server] Request PUT from address ‘(‘192.168.1.183’, 53938)’ for path ‘/characteristics’.
2018-06-04 01:46:22 DEBUG (Thread-7) [pyhap.characteristic] client_update_value: Identify to True
2018-06-04 01:46:22 INFO (Thread-7) [pyhap.hap_server] 192.168.1.183 - “PUT /characteristics HTTP/1.1” 207 -

cdce8p · June 4, 2018, 9:51am

Please try using the delayed auto start feature. That might solve it.

asmugala · June 4, 2018, 1:58pm

So I had to add the delayed auto-start function to get things to work, but I also had to go to services and manually start the homekit.start service. The delay didn’t seem to work for me. I’ll play with it. Thanks for your help guys.